Skip to content

Commit

Permalink
sql: log undecoded values as <undecoded> in tracing
Browse files Browse the repository at this point in the history
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
  • Loading branch information
yuzefovich committed Jan 7, 2022
1 parent 2c23b80 commit 58609b8
Show file tree
Hide file tree
Showing 14 changed files with 171 additions and 171 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -618,7 +618,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
Scan /Table/62/1/"@"/10/0, /Table/62/1/"\x80"/10/0, /Table/62/1/"\xc0"/10/0
fetched: /child/child_pkey/?/10/c_p_id -> /10
Scan /Table/61/1/"@"/10/0, /Table/61/1/"\x80"/10/0, /Table/61/1/"\xc0"/10/0
fetched: /parent/parent_pkey/?/? -> NULL
fetched: /parent/parent_pkey/?/? -> <undecoded>

# Semi join with locality optimized search disabled.
query T
Expand Down Expand Up @@ -648,7 +648,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
Scan /Table/62/1/"@"/10/0, /Table/62/1/"\x80"/10/0, /Table/62/1/"\xc0"/10/0
fetched: /child/child_pkey/?/10/c_p_id -> /10
Scan /Table/61/1/"@"/10/0, /Table/61/1/"\x80"/10/0, /Table/61/1/"\xc0"/10/0
fetched: /parent/parent_pkey/?/? -> NULL
fetched: /parent/parent_pkey/?/? -> <undecoded>
output row: [10 10]

# Inner join with locality optimized search disabled.
Expand Down Expand Up @@ -679,7 +679,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
Scan /Table/62/1/"@"/10/0, /Table/62/1/"\x80"/10/0, /Table/62/1/"\xc0"/10/0
fetched: /child/child_pkey/?/10/c_p_id -> /10
Scan /Table/61/1/"@"/10/0, /Table/61/1/"\x80"/10/0, /Table/61/1/"\xc0"/10/0
fetched: /parent/parent_pkey/'ap-southeast-2'/10 -> NULL
fetched: /parent/parent_pkey/'ap-southeast-2'/10 -> <undecoded>
output row: [10 10 10]

# Left join with locality optimized search disabled.
Expand Down Expand Up @@ -710,7 +710,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
Scan /Table/62/1/"@"/10/0, /Table/62/1/"\x80"/10/0, /Table/62/1/"\xc0"/10/0
fetched: /child/child_pkey/?/10/c_p_id -> /10
Scan /Table/61/1/"@"/10/0, /Table/61/1/"\x80"/10/0, /Table/61/1/"\xc0"/10/0
fetched: /parent/parent_pkey/'ap-southeast-2'/10 -> NULL
fetched: /parent/parent_pkey/'ap-southeast-2'/10 -> <undecoded>
output row: [10 10 10]

statement ok
Expand Down Expand Up @@ -777,7 +777,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
Scan /Table/62/1/"@"/10/0
fetched: /child/child_pkey/?/10/c_p_id -> /10
Scan /Table/61/1/"@"/10/0
fetched: /parent/parent_pkey/?/? -> NULL
fetched: /parent/parent_pkey/?/? -> <undecoded>

statement ok
SET tracing = on,kv,results; SELECT * FROM child WHERE NOT EXISTS (SELECT * FROM parent WHERE p_id = c_p_id) AND c_id = 20; SET tracing = off
Expand All @@ -795,7 +795,7 @@ Scan /Table/62/1/"\x80"/20/0, /Table/62/1/"\xc0"/20/0
fetched: /child/child_pkey/?/20/c_p_id -> /20
Scan /Table/61/1/"@"/20/0
Scan /Table/61/1/"\x80"/20/0, /Table/61/1/"\xc0"/20/0
fetched: /parent/parent_pkey/?/? -> NULL
fetched: /parent/parent_pkey/?/? -> <undecoded>

# Semi join with locality optimized search enabled.
query T
Expand Down Expand Up @@ -853,7 +853,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
Scan /Table/62/1/"@"/10/0
fetched: /child/child_pkey/?/10/c_p_id -> /10
Scan /Table/61/1/"@"/10/0
fetched: /parent/parent_pkey/?/? -> NULL
fetched: /parent/parent_pkey/?/? -> <undecoded>
output row: [10 10]

statement ok
Expand All @@ -872,7 +872,7 @@ Scan /Table/62/1/"\x80"/20/0, /Table/62/1/"\xc0"/20/0
fetched: /child/child_pkey/?/20/c_p_id -> /20
Scan /Table/61/1/"@"/20/0
Scan /Table/61/1/"\x80"/20/0, /Table/61/1/"\xc0"/20/0
fetched: /parent/parent_pkey/?/? -> NULL
fetched: /parent/parent_pkey/?/? -> <undecoded>
output row: [20 20]

# Inner join with locality optimized search enabled.
Expand Down Expand Up @@ -931,7 +931,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
Scan /Table/62/1/"@"/10/0
fetched: /child/child_pkey/?/10/c_p_id -> /10
Scan /Table/61/1/"@"/10/0
fetched: /parent/parent_pkey/'ap-southeast-2'/10 -> NULL
fetched: /parent/parent_pkey/'ap-southeast-2'/10 -> <undecoded>
output row: [10 10 10]

statement ok
Expand All @@ -950,7 +950,7 @@ Scan /Table/62/1/"\x80"/20/0, /Table/62/1/"\xc0"/20/0
fetched: /child/child_pkey/?/20/c_p_id -> /20
Scan /Table/61/1/"@"/20/0
Scan /Table/61/1/"\x80"/20/0, /Table/61/1/"\xc0"/20/0
fetched: /parent/parent_pkey/'ca-central-1'/20 -> NULL
fetched: /parent/parent_pkey/'ca-central-1'/20 -> <undecoded>
output row: [20 20 20]

# Left join with locality optimized search enabled.
Expand Down Expand Up @@ -1009,7 +1009,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
Scan /Table/62/1/"@"/10/0
fetched: /child/child_pkey/?/10/c_p_id -> /10
Scan /Table/61/1/"@"/10/0
fetched: /parent/parent_pkey/'ap-southeast-2'/10 -> NULL
fetched: /parent/parent_pkey/'ap-southeast-2'/10 -> <undecoded>
output row: [10 10 10]

statement ok
Expand All @@ -1028,7 +1028,7 @@ Scan /Table/62/1/"\x80"/20/0, /Table/62/1/"\xc0"/20/0
fetched: /child/child_pkey/?/20/c_p_id -> /20
Scan /Table/61/1/"@"/20/0
Scan /Table/61/1/"\x80"/20/0, /Table/61/1/"\xc0"/20/0
fetched: /parent/parent_pkey/'ca-central-1'/20 -> NULL
fetched: /parent/parent_pkey/'ca-central-1'/20 -> <undecoded>
output row: [20 20 20]

query T
Expand Down
2 changes: 1 addition & 1 deletion pkg/sql/colfetcher/cfetcher.go
Original file line number Diff line number Diff line change
Expand Up @@ -1176,7 +1176,7 @@ func (rf *cFetcher) processValue(ctx context.Context, familyID descpb.FamilyID)
}

if rf.traceKV && prettyValue == "" {
prettyValue = tree.DNull.String()
prettyValue = "<undecoded>"
}

return nil
Expand Down
8 changes: 4 additions & 4 deletions pkg/sql/opt/exec/execbuilder/testdata/aggregate
Original file line number Diff line number Diff line change
Expand Up @@ -727,7 +727,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /xyz/zyx/?/?/1 -> NULL
fetched: /xyz/zyx/?/?/1 -> <undecoded>
output row: [1]

query T
Expand Down Expand Up @@ -1082,13 +1082,13 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /xyz/xyz_pkey/1 -> NULL
fetched: /xyz/xyz_pkey/1 -> <undecoded>
fetched: /xyz/xyz_pkey/1/y -> 2
fetched: /xyz/xyz_pkey/1/z -> 3.0
fetched: /xyz/xyz_pkey/4 -> NULL
fetched: /xyz/xyz_pkey/4 -> <undecoded>
fetched: /xyz/xyz_pkey/4/y -> 5
fetched: /xyz/xyz_pkey/4/z -> 6.0
fetched: /xyz/xyz_pkey/7 -> NULL
fetched: /xyz/xyz_pkey/7 -> <undecoded>
fetched: /xyz/xyz_pkey/7/z -> 8.0
output row: [9 4.5 6.33333333333333]

Expand Down
12 changes: 6 additions & 6 deletions pkg/sql/opt/exec/execbuilder/testdata/ddl
Original file line number Diff line number Diff line change
Expand Up @@ -137,7 +137,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /t/t_pkey/1 -> NULL
fetched: /t/t_pkey/1 -> <undecoded>
fetched: /t/t_pkey/1/b -> 1
output row: [1 1]

Expand All @@ -163,7 +163,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /t/foo/1/1 -> NULL
fetched: /t/foo/1/1 -> <undecoded>
output row: [1 1]

statement ok
Expand All @@ -177,8 +177,8 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /t/foo/1/1 -> NULL
fetched: /t/foo/1/2 -> NULL
fetched: /t/foo/1/1 -> <undecoded>
fetched: /t/foo/1/2 -> <undecoded>
output row: [1 1]
output row: [2 1]

Expand Down Expand Up @@ -213,8 +213,8 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /t/b_desc/?/2 -> NULL
fetched: /t/b_desc/?/1 -> NULL
fetched: /t/b_desc/?/2 -> <undecoded>
fetched: /t/b_desc/?/1 -> <undecoded>
fetched: /t/t_pkey/1/b/c -> /1/1
fetched: /t/t_pkey/2/b/c -> /2/2
output row: [1 1 1]
Expand Down
78 changes: 39 additions & 39 deletions pkg/sql/opt/exec/execbuilder/testdata/insert
Original file line number Diff line number Diff line change
Expand Up @@ -31,19 +31,19 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /kv/kv_pkey/'A' -> NULL
fetched: /kv/kv_pkey/'a' -> NULL
fetched: /kv/kv_pkey/'A' -> <undecoded>
fetched: /kv/kv_pkey/'a' -> <undecoded>
fetched: /kv/kv_pkey/'a'/v -> 'b'
fetched: /kv/kv_pkey/'c' -> NULL
fetched: /kv/kv_pkey/'c' -> <undecoded>
fetched: /kv/kv_pkey/'c'/v -> 'd'
fetched: /kv/kv_pkey/'e' -> NULL
fetched: /kv/kv_pkey/'e' -> <undecoded>
fetched: /kv/kv_pkey/'e'/v -> 'f'
fetched: /kv/kv_pkey/'g' -> NULL
fetched: /kv/kv_pkey/'g' -> <undecoded>
fetched: /kv/kv_pkey/'g'/v -> ''
fetched: /kv/kv_pkey/'nil1' -> NULL
fetched: /kv/kv_pkey/'nil2' -> NULL
fetched: /kv/kv_pkey/'nil3' -> NULL
fetched: /kv/kv_pkey/'nil4' -> NULL
fetched: /kv/kv_pkey/'nil1' -> <undecoded>
fetched: /kv/kv_pkey/'nil2' -> <undecoded>
fetched: /kv/kv_pkey/'nil3' -> <undecoded>
fetched: /kv/kv_pkey/'nil4' -> <undecoded>
output row: ['A' NULL]
output row: ['a' 'b']
output row: ['c' 'd']
Expand Down Expand Up @@ -92,19 +92,19 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /kv/kv_pkey/'A' -> NULL
fetched: /kv/kv_pkey/'a' -> NULL
fetched: /kv/kv_pkey/'A' -> <undecoded>
fetched: /kv/kv_pkey/'a' -> <undecoded>
fetched: /kv/kv_pkey/'a'/v -> 'b'
fetched: /kv/kv_pkey/'c' -> NULL
fetched: /kv/kv_pkey/'c' -> <undecoded>
fetched: /kv/kv_pkey/'c'/v -> 'd'
fetched: /kv/kv_pkey/'e' -> NULL
fetched: /kv/kv_pkey/'e' -> <undecoded>
fetched: /kv/kv_pkey/'e'/v -> 'f'
fetched: /kv/kv_pkey/'g' -> NULL
fetched: /kv/kv_pkey/'g' -> <undecoded>
fetched: /kv/kv_pkey/'g'/v -> ''
fetched: /kv/kv_pkey/'nil1' -> NULL
fetched: /kv/kv_pkey/'nil2' -> NULL
fetched: /kv/kv_pkey/'nil3' -> NULL
fetched: /kv/kv_pkey/'nil4' -> NULL
fetched: /kv/kv_pkey/'nil1' -> <undecoded>
fetched: /kv/kv_pkey/'nil2' -> <undecoded>
fetched: /kv/kv_pkey/'nil3' -> <undecoded>
fetched: /kv/kv_pkey/'nil4' -> <undecoded>
output row: ['A' NULL]
output row: ['a' 'b']
output row: ['c' 'd']
Expand Down Expand Up @@ -153,21 +153,21 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /kv/kv_pkey/'A' -> NULL
fetched: /kv/kv_pkey/'a' -> NULL
fetched: /kv/kv_pkey/'A' -> <undecoded>
fetched: /kv/kv_pkey/'a' -> <undecoded>
fetched: /kv/kv_pkey/'a'/v -> 'b'
fetched: /kv/kv_pkey/'c' -> NULL
fetched: /kv/kv_pkey/'c' -> <undecoded>
fetched: /kv/kv_pkey/'c'/v -> 'd'
fetched: /kv/kv_pkey/'e' -> NULL
fetched: /kv/kv_pkey/'e' -> <undecoded>
fetched: /kv/kv_pkey/'e'/v -> 'f'
fetched: /kv/kv_pkey/'f' -> NULL
fetched: /kv/kv_pkey/'f' -> <undecoded>
fetched: /kv/kv_pkey/'f'/v -> 'g'
fetched: /kv/kv_pkey/'g' -> NULL
fetched: /kv/kv_pkey/'g' -> <undecoded>
fetched: /kv/kv_pkey/'g'/v -> ''
fetched: /kv/kv_pkey/'nil1' -> NULL
fetched: /kv/kv_pkey/'nil2' -> NULL
fetched: /kv/kv_pkey/'nil3' -> NULL
fetched: /kv/kv_pkey/'nil4' -> NULL
fetched: /kv/kv_pkey/'nil1' -> <undecoded>
fetched: /kv/kv_pkey/'nil2' -> <undecoded>
fetched: /kv/kv_pkey/'nil3' -> <undecoded>
fetched: /kv/kv_pkey/'nil4' -> <undecoded>
output row: ['A' NULL]
output row: ['a' 'b']
output row: ['c' 'd']
Expand Down Expand Up @@ -219,21 +219,21 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /kv/kv_pkey/'A' -> NULL
fetched: /kv/kv_pkey/'a' -> NULL
fetched: /kv/kv_pkey/'A' -> <undecoded>
fetched: /kv/kv_pkey/'a' -> <undecoded>
fetched: /kv/kv_pkey/'a'/v -> 'b'
fetched: /kv/kv_pkey/'c' -> NULL
fetched: /kv/kv_pkey/'c' -> <undecoded>
fetched: /kv/kv_pkey/'c'/v -> 'd'
fetched: /kv/kv_pkey/'e' -> NULL
fetched: /kv/kv_pkey/'e' -> <undecoded>
fetched: /kv/kv_pkey/'e'/v -> 'f'
fetched: /kv/kv_pkey/'f' -> NULL
fetched: /kv/kv_pkey/'f' -> <undecoded>
fetched: /kv/kv_pkey/'f'/v -> 'g'
fetched: /kv/kv_pkey/'g' -> NULL
fetched: /kv/kv_pkey/'g' -> <undecoded>
fetched: /kv/kv_pkey/'g'/v -> ''
fetched: /kv/kv_pkey/'nil1' -> NULL
fetched: /kv/kv_pkey/'nil2' -> NULL
fetched: /kv/kv_pkey/'nil3' -> NULL
fetched: /kv/kv_pkey/'nil4' -> NULL
fetched: /kv/kv_pkey/'nil1' -> <undecoded>
fetched: /kv/kv_pkey/'nil2' -> <undecoded>
fetched: /kv/kv_pkey/'nil3' -> <undecoded>
fetched: /kv/kv_pkey/'nil4' -> <undecoded>
output row: ['A' NULL]
output row: ['a' 'b']
output row: ['c' 'd']
Expand Down Expand Up @@ -292,7 +292,7 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /kv5/a/NULL/'a' -> NULL
fetched: /kv5/a/NULL/'a' -> <undecoded>
output row: ['a' NULL]

statement ok
Expand Down
16 changes: 8 additions & 8 deletions pkg/sql/opt/exec/execbuilder/testdata/orderby
Original file line number Diff line number Diff line change
Expand Up @@ -302,9 +302,9 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /abc/abc_pkey/1/2/3 -> NULL
fetched: /abc/abc_pkey/1/2/3 -> <undecoded>
fetched: /abc/abc_pkey/1/2/3/d -> 'one'
fetched: /abc/abc_pkey/4/5/6 -> NULL
fetched: /abc/abc_pkey/4/5/6 -> <undecoded>
fetched: /abc/abc_pkey/4/5/6/d -> 'Two'
output row: [1 2 3 'one']
output row: [4 5 6 'Two']
Expand All @@ -317,8 +317,8 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /abc/ba/2/1/? -> NULL
fetched: /abc/ba/5/4/? -> NULL
fetched: /abc/ba/2/1/? -> <undecoded>
fetched: /abc/ba/5/4/? -> <undecoded>
output row: [1 2]
output row: [4 5]

Expand Down Expand Up @@ -490,10 +490,10 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WITH ORDINALITY
WHERE message LIKE 'fetched:%' OR message LIKE 'output row%'
ORDER BY message LIKE 'fetched:%' DESC, ordinality ASC
----
fetched: /abc/abc_pkey/4/?/? -> NULL
fetched: /abc/abc_pkey/4/?/? -> NULL
fetched: /abc/abc_pkey/1/?/? -> NULL
fetched: /abc/abc_pkey/1/?/? -> NULL
fetched: /abc/abc_pkey/4/?/? -> <undecoded>
fetched: /abc/abc_pkey/4/?/? -> <undecoded>
fetched: /abc/abc_pkey/1/?/? -> <undecoded>
fetched: /abc/abc_pkey/1/?/? -> <undecoded>
output row: [4]
output row: [1]

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -59,7 +59,7 @@ query T
SELECT message FROM [SHOW KV TRACE FOR SESSION] WHERE
message LIKE 'fetched: /t1/nonuniqueidx/%'
----
fetched: /t1/nonuniqueidx/1/? -> NULL
fetched: /t1/nonuniqueidx/1/? -> <undecoded>

query I
SET TRACING=on,kv,results;
Expand All @@ -85,7 +85,7 @@ query T
SELECT message FROM [SHOW KV TRACE FOR SESSION] WHERE
message LIKE 'fetched: /t1/nonuniqueidxstoring/%'
----
fetched: /t1/nonuniqueidxstoring/1/1 -> NULL
fetched: /t1/nonuniqueidxstoring/1/1 -> <undecoded>
fetched: /t1/nonuniqueidxstoring/1/1/z -> /1
fetched: /t1/nonuniqueidxstoring/1/1/a/b -> /1/1

Expand Down Expand Up @@ -319,11 +319,11 @@ SELECT message FROM [SHOW KV TRACE FOR SESSION] WHERE
message LIKE 'fetched%'
ORDER BY message
----
fetched: /t/i/2/1 -> NULL
fetched: /t/i/2/1 -> <undecoded>
fetched: /t/i/2/1/w -> /3
fetched: /t/i/5/4 -> NULL
fetched: /t/i/5/4 -> <undecoded>
fetched: /t/i/5/4/z -> /6
fetched: /t/i/9/8 -> NULL
fetched: /t/i/9/8 -> <undecoded>

statement ok
DROP TABLE IF EXISTS t;
Expand Down
Loading

0 comments on commit 58609b8

Please sign in to comment.