Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

colfetcher,row: decode only needed columns when tracing is enabled #74236

Merged
merged 5 commits into from
Jan 7, 2022

Conversation

yuzefovich
Copy link
Member

@yuzefovich yuzefovich commented Dec 23, 2021

colfetcher: minor optimization when decoding the value part

Release note: None

colfetcher: fix recent bug of using wrong column with tracing in some cases

A couple of months ago when we taught the cFetcher to operate only on
needed columns, we refactored the meaning of ColIdxMap - now it
returns for the given ColumnID the ordinal of the column among all
needed columns whereas previously it would return the ordinal among all
columns in the table. In tracing we were relying on the old behavior to
append the column name to the key part, and we mistakenly used the
"needed" ordinal when accesing the "whole table" columns. This is now
fixed. I noticed it while working on the next commit.

Release note: None

colfetcher,row: decode only needed columns when tracing is enabled

In a recent change we made it so that the cFetcher would treat all
columns present in the index as "needed" when the KV tracing is enabled.
This led to some bugs (like reading of a virtual column that doesn't
exist in the index) but is also not very meaningful since the goal of
the tracing is to show what the cFetcher is doing without tracing. This
commit starts treating the KV tracing as the request to log all needed
operations without doing anything extra (like decoding unnecessary
columns).

A similar change is applied to the row.Fetcher as well.

Fixes: #73745.

Release note (sql change): The KV tracing of SQL queries (that could be
obtained with \set auto_trace=on,kv) has been adjusted slightly.
Previously, we would fully decode the key part of each key-value pair
even if some part of the key would not be decoded when tracing is
enabled. Now, we won't perform any extra decoding, and parts of the key
that aren't decoded are replaced with ?.

colfetcher: find needed columns upfront

Previously, the two users of the cFetcher (ColBatchScan and
ColIndexJoin) had different ways of figuring out which columns are
actually needed to be fetched (that information is needed to not decode
parts of the KV pairs unnecessarily). In one case we explicitly
propagated the information through the spec, and in another we did some
pre-processing to find the information.

This overall was more complicated than necessary (because we had complex
code path for pruning "unaccessible" columns from the secondary index
while keeping track of the ordinal mapping) as well as suboptimal (in
some cases TableReaderSpec.NeededColumns contained ordinals of the
columns that weren't actually needed by the post-processing stage), so
this commit unifies both ways into one addressing both of these
shortcomings.

Now, in order to find the set of needed columns, we examine the
post-processing spec all the time, but we do it in an efficient manner:

  • we make sure to deserialize render expressions early
  • we use a tree.Visitor rather than a heavy-weight ExprHelper.

As a result, we can remove TableReaderSpec.NeededColumns field as well
as not decode some columns in a handful of cases.

Release note: None

sql: log undecoded values as in tracing

Previously, if the value part of a key-value pair wasn't needed, we
would log it as NULL. However, that can be confusing whether an actual
NULL value was decoded or not. This commit replaces the undecoded
values with <undecoded> reducing the confusion (given that the
likelihood of the value actually being equal to <undecoded> is
negligible).

Release note: None

@cockroach-teamcity
Copy link
Member

This change is Reviewable

@yuzefovich yuzefovich force-pushed the fix-cfetcher-tracing branch 2 times, most recently from e55bf7b to 387d847 Compare December 23, 2021 07:19
Copy link
Collaborator

@mgartner mgartner left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

:lgtm:

Reviewed 10 of 10 files at r1, all commit messages.
Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (waiting on @yuzefovich)


-- commits, line 8 at r1:
nit: "doing in without" => "doing without"


-- commits, line 15 at r1:
I'm not sure if any users rely on tracing details like this, but it might be worth mentioning in a release note for our internal team members incase they notice the change in behavior while debugging and are confused by it.


pkg/sql/colfetcher/cfetcher_setup.go, line 183 at r1 (raw file):

// post is updated accordingly to refer to new ordinals of columns. The method
// also populates tableArgs.ColIdxMap.
func keepOnlyNeededColumns(

It seems like now were doing a lot of unnecessary work in populateTableArgs to first populate a bunch of columns regardless of whether or not they are needed and pruning them in the case of a secondary index fetch, and then further pruning them here in keepOnlyNeededColumns.

Could we not remove keepOnlyNeededColumns entirely and do something like the psuedo-code below in populateTableArgs, getting rid of the special code for secondary indexes and system columns:

for _, col := range table.AllColumns() {
  if neededColumns.Contains(col) {
    cols = append(cols, col)
  }
}

Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think I addressed all test failures, but there are a couple of questions that I want to answer first before merging this:

  1. there is a regression in usability of tracing in some cases, in particular in regional_by_row_query_behavior file where we no longer show the region in the key part of the fetched KV. The query uses SELECT *, so I'm guessing that the optimizer is smart to know that the region column is not needed to be decoded because it was encoded in a span constraint, or something like that? Is this an acceptable regression? I can't immediately think of a simple workaround here.
  2. there is a confusion between actual NULL value and a value that didn't have to be decoded (which we show as NULL). I think this problem existed before, so it might be not a big deal. Some improvements I have in mind is showing the value part that didn't have to be decoded as ? as well as not showing the value part at all when reading of a secondary index with no stored columns. Thoughts?

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @mgartner)


pkg/sql/colfetcher/cfetcher_setup.go, line 183 at r1 (raw file):

Previously, mgartner (Marcus Gartner) wrote…

It seems like now were doing a lot of unnecessary work in populateTableArgs to first populate a bunch of columns regardless of whether or not they are needed and pruning them in the case of a secondary index fetch, and then further pruning them here in keepOnlyNeededColumns.

Could we not remove keepOnlyNeededColumns entirely and do something like the psuedo-code below in populateTableArgs, getting rid of the special code for secondary indexes and system columns:

for _, col := range table.AllColumns() {
  if neededColumns.Contains(col) {
    cols = append(cols, col)
  }
}

You're right that in the case when cFetcher is used by the ColBatchScan (i.e. simple table reader) we could simplify this logic. This is easy to do because we know the set of needed columns since it's included in TableReaderSpec. However, for the index join (which also uses cFetcher) we don't know the needed columns up front, and in some cases we have to know the types.T schema of available columns in order to calculate that needed columns set:

if err = proc.Init(post, tableArgs.typs, helper.SemaCtx, flowCtx.EvalCtx); err != nil {

That was the reason for why I broke this process down into two steps.

If the optimizer can propagate the set of needed columns for the index joins, then we could simplify things, but that would be a separate change.

@yuzefovich yuzefovich marked this pull request as ready for review December 24, 2021 04:22
@yuzefovich yuzefovich requested a review from a team as a code owner December 24, 2021 04:22
@yuzefovich yuzefovich requested a review from a team December 24, 2021 04:23
@RaduBerinde
Copy link
Member

Does the row fetcher also decode unnecessary columns when tracing? If so we should fix that too for consistency

Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does the row fetcher also decode unnecessary columns when tracing? If so we should fix that too for consistency

Thanks for the nudge here. In the row fetcher with tracing we now decode exactly the same things as without tracing (after some minor changes in the third commit).

There are some differences between the vectorized and row-by-row fetchers where in the former only the necessary parts of the key are decoded whereas in the latter the whole key is decoded if at least one part of the key is needed.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @mgartner)


pkg/sql/colfetcher/cfetcher_setup.go, line 183 at r1 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

You're right that in the case when cFetcher is used by the ColBatchScan (i.e. simple table reader) we could simplify this logic. This is easy to do because we know the set of needed columns since it's included in TableReaderSpec. However, for the index join (which also uses cFetcher) we don't know the needed columns up front, and in some cases we have to know the types.T schema of available columns in order to calculate that needed columns set:

if err = proc.Init(post, tableArgs.typs, helper.SemaCtx, flowCtx.EvalCtx); err != nil {

That was the reason for why I broke this process down into two steps.

If the optimizer can propagate the set of needed columns for the index joins, then we could simplify things, but that would be a separate change.

Radu's nudge to look closer in the row-by-row fetcher made me realize that the cFetcher might be decoding more things than necessary in some cases, so I ended up refactoring the way we figure out the set of needed columns, and eventually the code looks similar to what you were suggesting. PTAL.

@yuzefovich yuzefovich force-pushed the fix-cfetcher-tracing branch 2 times, most recently from 4a998b3 to 12d3377 Compare December 28, 2021 01:04
Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Fixed a silly mistake, RFAL.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @mgartner and @rharding6373)

Copy link
Member

@RaduBerinde RaduBerinde left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @mgartner, @rharding6373, and @yuzefovich)


pkg/sql/execinfrapb/processors_sql.proto, line 149 at r5 (raw file):

  optional bool has_system_columns = 14 [(gogoproto.nullable) = false];

  reserved 15;

This requires a DistSQL version bump, no? (alternatively, we could still populate it until the cluster has the right version)

@yuzefovich yuzefovich force-pushed the fix-cfetcher-tracing branch 2 times, most recently from 34958c9 to 579c510 Compare January 4, 2022 00:30
Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 1 stale) (waiting on @mgartner, @RaduBerinde, and @rharding6373)


pkg/sql/execinfrapb/processors_sql.proto, line 149 at r5 (raw file):

Previously, RaduBerinde wrote…

This requires a DistSQL version bump, no? (alternatively, we could still populate it until the cluster has the right version)

Yes, that's a good catch, fixed. Note that this wasn't strictly necessary because we've already had some bumps of the distsql version in 22.1 cycle and haven't released any binaries yet, still it's better to be explicit.

Copy link
Collaborator

@rharding6373 rharding6373 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

:lgtm: Had a minor nit and a clarification question. Probably best to wait for another lgtm from someone who's been following along.

Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (and 1 stale) (waiting on @mgartner, @RaduBerinde, @rharding6373, and @yuzefovich)


pkg/sql/opt/exec/execbuilder/testdata/virtual_columns, line 1570 at r4 (raw file):

          spans: [/'foo' COLLATE en_US - /'foo' COLLATE en_US]

# Regression test for the cFetcher trying to fetch virtual computed columns from

nit: Include what the expectation for the test is, e.g. Regression test for #73745. The cFetcher should not fetch virtual computed columns from a primary index.


pkg/sql/opt/exec/execbuilder/testdata/window, line 34 at r4 (raw file):

 ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /kv/kv_pkey/1/v -> /2

Could you explain how the tracing changes affected the results to this test? Why are some of the keys shorter (e.g., /v/w/f/b to /v)? Are the NULLs due to the confusion between actual NULLs and non-decoded values? I don't understand why some keys in the trace had values before but now have NULL...

@yuzefovich yuzefovich force-pushed the fix-cfetcher-tracing branch from 579c510 to 5f55231 Compare January 4, 2022 19:09
Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (and 1 stale) (waiting on @mgartner, @RaduBerinde, and @rharding6373)


pkg/sql/opt/exec/execbuilder/testdata/window, line 34 at r4 (raw file):
Some keys have gotten shorter because we no longer decode the full key but only the needed part from it. Note that decoding the whole key was introduced recently in 8e40f1c.

Are the NULLs due to the confusion between actual NULLs and non-decoded values? I don't understand why some keys in the trace had values before but now have NULL...

Yes, this is the case. This is one of the questions that I want to get answered before merging this (#74236 (review)).

For example,

fetched: /kv/kv_pkey/1/s -> 'a'

is transformed into

fetched: /kv/kv_pkey/1 -> NULL

because s column is not needed, so we don't write the name of the column into the key part and keep the value part undecoded, so we log it as NULL.

Copy link
Collaborator

@mgartner mgartner left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice! :lgtm:

Reviewed 10 of 10 files at r2, 1 of 1 files at r3, 9 of 13 files at r4, 19 of 19 files at r7, 18 of 18 files at r8, all commit messages.
Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (and 1 stale) (waiting on @mgartner, @RaduBerinde, @rharding6373, and @yuzefovich)


pkg/sql/colfetcher/cfetcher.go, line 1206 at r3 (raw file):

	if idx, ok := table.ColIdxMap.Get(colID); ok {
		if rf.traceKV {
			prettyKey = fmt.Sprintf("%s/%s", prettyKey, table.cols[idx].GetName())

nit: update the description of ColIdxMap to be more clear:

// ColIdxMap is a mapping from ColumnID of each column to its ordinal. Only
// needed columns are present.

Something like: "ColIdxMap is a mapping from ColumnID to the ordinal of the corresponding column within the cols field. Only needed columns are present".


pkg/sql/colfetcher/cfetcher.go, line 1044 at r7 (raw file):

// specified by colOrdinals. -1 in colOrdinals indicates that a column wasn't
// actually decoded (this is represented as "?" in the result). separator is
// inserted between each two consequent decoded column values (but not before

super nit: "consequent" => "subsequent"


pkg/sql/colfetcher/cfetcher_setup.go, line 82 at r8 (raw file):

// - neededColumns is a set containing the ordinals of all columns that need to
// be fetched. These ordinals are based on the schema of the whole table rather
// than only among the needed columns.

nit: Not sure you need the "rather than only among the needed columns". If it were the set of ordinals in needed columns, it would simply be the set of all ordinals in [0, n) where n is the number of needed columns, right?


pkg/sql/colfetcher/cfetcher_setup.go, line 139 at r8 (raw file):

	if neededColumns.Len() != len(cols) {
		idxMap := make([]int, len(cols))
		neededColIdx := 0

nit: keepColIdx might make it more clear that this variable is related to cols not neededColumns.


pkg/sql/colfetcher/cfetcher_setup.go, line 185 at r8 (raw file):

		for _, expr := range post.RenderExprs {
			ivarSeen = colexecutils.MaybeAllocateBoolArray(ivarSeen, numColumns)
			ivars := findIVarsInRange(expr.LocalExpr, 0 /* start */, numColumns, ivarSeen)

Why do we need to pass a start and end here? In what cases would the expression contain indexed vars outside of this range?


pkg/sql/colfetcher/cfetcher_setup.go, line 191 at r8 (raw file):

			if neededColumns.Len() == numColumns {
				// All columns are needed, so we can stop processing the
				// consequent render expressions.

super nit: "consequent" => "subsequent"


pkg/sql/opt/exec/execbuilder/testdata/window, line 34 at r4 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

Some keys have gotten shorter because we no longer decode the full key but only the needed part from it. Note that decoding the whole key was introduced recently in 8e40f1c.

Are the NULLs due to the confusion between actual NULLs and non-decoded values? I don't understand why some keys in the trace had values before but now have NULL...

Yes, this is the case. This is one of the questions that I want to get answered before merging this (#74236 (review)).

For example,

fetched: /kv/kv_pkey/1/s -> 'a'

is transformed into

fetched: /kv/kv_pkey/1 -> NULL

because s column is not needed, so we don't write the name of the column into the key part and keep the value part undecoded, so we log it as NULL.

I think this is mostly fine. One minor improvement would be to log undecoded values as <undecoded> or ? instead of NULL.

… cases

A couple of months ago when we taught the cFetcher to operate only on
needed columns, we refactored the meaning of `ColIdxMap` - now it
returns for the given ColumnID the ordinal of the column among all
needed columns whereas previously it would return the ordinal among all
columns in the table. In tracing we were relying on the old behavior to
append the column name to the key part, and we mistakenly used the
"needed" ordinal when accesing the "whole table" columns. This is now
fixed. I noticed it while working on the next commit.

Release note: None
In a recent change we made it so that the cFetcher would treat all
columns present in the index as "needed" when the KV tracing is enabled.
This led to some bugs (like reading of a virtual column that doesn't
exist in the index) but is also not very meaningful since the goal of
the tracing is to show what the cFetcher is doing without tracing. This
commit starts treating the KV tracing as the request to log all needed
operations without doing anything extra (like decoding unnecessary
columns).

A similar change is applied to the `row.Fetcher` as well.

Release note (sql change): The KV tracing of SQL queries (that could be
obtained with `\set auto_trace=on,kv`) has been adjusted slightly.
Previously, we would fully decode the key part of each key-value pair
even if some part of the key would not be decoded when tracing is
enabled. Now, we won't perform any extra decoding, and parts of the key
that aren't decoded are replaced with `?`.
Previously, the two users of the `cFetcher` (`ColBatchScan` and
`ColIndexJoin`) had different ways of figuring out which columns are
actually needed to be fetched (that information is needed to not decode
parts of the KV pairs unnecessarily). In one case we explicitly
propagated the information through the spec, and in another we did some
pre-processing to find the information.

This overall was more complicated than necessary (because we had complex
code path for pruning "unaccessible" columns from the secondary index
while keeping track of the ordinal mapping) as well as suboptimal (in
some cases `TableReaderSpec.NeededColumns` contained ordinals of the
columns that weren't actually needed by the post-processing stage), so
this commit unifies both ways into one addressing both of these
shortcomings.

Now, in order to find the set of needed columns, we examine the
post-processing spec all the time, but we do it in an efficient manner:
- we make sure to deserialize render expressions early
- we use a `tree.Visitor` rather than a heavy-weight `ExprHelper`.

As a result, we can remove `TableReaderSpec.NeededColumns` field as well
as not decode some columns in a handful of cases.

Release note: None
@yuzefovich yuzefovich force-pushed the fix-cfetcher-tracing branch from 5f55231 to ce1730d Compare January 7, 2022 18:32
Copy link
Member Author

@yuzefovich yuzefovich left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

TFTRs!

bors r+

Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 2 stale) (waiting on @mgartner, @RaduBerinde, and @rharding6373)


pkg/sql/colfetcher/cfetcher_setup.go, line 82 at r8 (raw file):

Previously, mgartner (Marcus Gartner) wrote…

nit: Not sure you need the "rather than only among the needed columns". If it were the set of ordinals in needed columns, it would simply be the set of all ordinals in [0, n) where n is the number of needed columns, right?

Good point, removed.


pkg/sql/colfetcher/cfetcher_setup.go, line 185 at r8 (raw file):

Previously, mgartner (Marcus Gartner) wrote…

Why do we need to pass a start and end here? In what cases would the expression contain indexed vars outside of this range?

This was a remnant of the past when findIVarsInRange was introduced. You're right that we don't need this, and I refactored the code to get rid off this method altogether.


pkg/sql/opt/exec/execbuilder/testdata/window, line 34 at r4 (raw file):

Previously, mgartner (Marcus Gartner) wrote…

I think this is mostly fine. One minor improvement would be to log undecoded values as <undecoded> or ? instead of NULL.

I like the suggestion with <undecoded>, so I implemented that in a separate commit.

@craig
Copy link
Contributor

craig bot commented Jan 7, 2022

Build failed:

Copy link
Collaborator

@mgartner mgartner left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Reviewed 28 of 28 files at r9, 13 of 13 files at r10, 18 of 18 files at r11, 12 of 12 files at r12, all commit messages.
Reviewable status: :shipit: complete! 0 of 0 LGTMs obtained (and 2 stale) (waiting on @rharding6373)

Copy link
Collaborator

@rharding6373 rharding6373 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

:lgtm:

Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (and 1 stale) (waiting on @mgartner and @yuzefovich)


pkg/sql/opt/exec/execbuilder/testdata/window, line 34 at r4 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

I like the suggestion with <undecoded>, so I implemented that in a separate commit.

The <undecoded> is nice.

Previously, if the value part of a key-value pair wasn't needed, we
would log it as `NULL`. However, that can be confusing whether an actual
`NULL` value was decoded or not. This commit replaces the undecoded
values with `<undecoded>` reducing the confusion (given that the
likelihood of the value actually being equal to `<undecoded>` is
negligible).

Release note: None
@yuzefovich yuzefovich force-pushed the fix-cfetcher-tracing branch from ce1730d to 58609b8 Compare January 7, 2022 22:43
@yuzefovich yuzefovich requested a review from a team January 7, 2022 22:43
@yuzefovich
Copy link
Member Author

Fixed up a couple of places I originally forgot to update based on the <undecoded> change, CI should be green now.

bors r+

@craig
Copy link
Contributor

craig bot commented Jan 7, 2022

Build succeeded:

@craig craig bot merged commit 927a4a1 into cockroachdb:master Jan 7, 2022
@yuzefovich yuzefovich deleted the fix-cfetcher-tracing branch January 7, 2022 23:47
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

sql: kv tracing crashes on not null virtual computed columns
5 participants