sql: add locking to sql/row/kv_batch_fetcher.go trace message

[michae2]

In sql/row/kv_batch_fetcher.go there are trace messages that print the Scan or Get operation. We should add locking information to these for better observability of SELECT FOR UPDATE and other locking statements.

Jira issue: CRDB-33843

Epic CRDB-34172

[michae2]

One way to see these log messages is to turn on auto_trace=kv in cockroach demo:

[email protected]:26257/demoapp/defaultdb> CREATE TABLE ab (a INT PRIMARY KEY, b INT);
CREATE TABLE

Time: 6ms total (execution 5ms / network 0ms)

[email protected]:26257/demoapp/defaultdb> INSERT INTO ab VALUES (3, 4);
INSERT 0 1

Time: 7ms total (execution 7ms / network 0ms)

[email protected]:26257/demoapp/defaultdb> \set auto_trace=kv
[email protected]:26257/demoapp/defaultdb> SELECT * FROM ab WHERE a = 3;
  a | b
----+----
  3 | 4
(1 row)

Time: 5ms total (execution 4ms / network 1ms)

            timestamp           |       age       |                                            message                                            |                            tag                             |                location                 |    operation     | span
--------------------------------+-----------------+-----------------------------------------------------------------------------------------------+------------------------------------------------------------+-----------------------------------------+------------------+-------
  2024-05-21 07:52:07.653925+00 | 00:00:00.002937 | Scan /Tenant/2/Table/104/1/3/0                                                                | [n1,client=127.0.0.1:62343,hostssl,user=demo]              | sql/row/kv_batch_fetcher.go:535         | colbatchscan     |    7
  2024-05-21 07:52:07.654008+00 | 00:00:00.00302  | querying next range at /Tenant/2/Table/104/1/3/0                                              | [n1,client=127.0.0.1:62343,hostssl,user=demo,txn=9bc7eada] | kv/kvclient/kvcoord/range_iter.go:188   | dist sender send |    9
  2024-05-21 07:52:07.654094+00 | 00:00:00.003106 | key: /Tenant/2/Table/104/1/3/0, desc: r81:/Tenant/{2/Table/104-3} [(n1,s1):1, next=2, gen=13] | [n1,client=127.0.0.1:62343,hostssl,user=demo,txn=9bc7eada] | kv/kvclient/kvcoord/range_iter.go:225   | dist sender send |    9
  2024-05-21 07:52:07.654145+00 | 00:00:00.003157 | r81: sending batch 1 Get to (n1,s1):1                                                         | [n1,client=127.0.0.1:62343,hostssl,user=demo,txn=9bc7eada] | kv/kvclient/kvcoord/dist_sender.go:2656 | dist sender send |    9
  2024-05-21 07:52:07.655236+00 | 00:00:00.004248 | fetched: /ab/ab_pkey/3/b -> /4                                                                | [n1,client=127.0.0.1:62343,hostssl,user=demo]              | sql/colfetcher/cfetcher.go:1021         | colbatchscan     |    7
  2024-05-21 07:52:07.655505+00 | 00:00:00.004517 | rows affected: 1                                                                              | [n1,client=127.0.0.1:62343,hostssl,user=demo]              | sql/conn_executor_exec.go:1150          | sql query        |    2
(6 rows)

Time: 3ms total (execution 3ms / network 0ms)

[email protected]:26257/demoapp/defaultdb> SELECT * FROM ab WHERE a = 3 FOR UPDATE;
  a | b
----+----
  3 | 4
(1 row)

Time: 8ms total (execution 6ms / network 3ms)

            timestamp           |       age       |                                            message                                            |                            tag                             |                location                 |    operation     | span
--------------------------------+-----------------+-----------------------------------------------------------------------------------------------+------------------------------------------------------------+-----------------------------------------+------------------+-------
  2024-05-21 07:52:22.98626+00  | 00:00:00.002421 | Scan /Tenant/2/Table/104/1/3/0                                                                | [n1,client=127.0.0.1:62343,hostssl,user=demo]              | sql/row/kv_batch_fetcher.go:535         | colbatchscan     |    7
  2024-05-21 07:52:22.986402+00 | 00:00:00.002563 | querying next range at /Tenant/2/Table/104/1/3/0                                              | [n1,client=127.0.0.1:62343,hostssl,user=demo,txn=cd4a7e62] | kv/kvclient/kvcoord/range_iter.go:188   | dist sender send |    9
  2024-05-21 07:52:22.986495+00 | 00:00:00.002656 | key: /Tenant/2/Table/104/1/3/0, desc: r81:/Tenant/{2/Table/104-3} [(n1,s1):1, next=2, gen=13] | [n1,client=127.0.0.1:62343,hostssl,user=demo,txn=cd4a7e62] | kv/kvclient/kvcoord/range_iter.go:225   | dist sender send |    9
  2024-05-21 07:52:22.98654+00  | 00:00:00.002701 | r81: sending batch 1 Get to (n1,s1):1                                                         | [n1,client=127.0.0.1:62343,hostssl,user=demo,txn=cd4a7e62] | kv/kvclient/kvcoord/dist_sender.go:2656 | dist sender send |    9
  2024-05-21 07:52:22.987711+00 | 00:00:00.003872 | fetched: /ab/ab_pkey/3/b -> /4                                                                | [n1,client=127.0.0.1:62343,hostssl,user=demo]              | sql/colfetcher/cfetcher.go:1021         | colbatchscan     |    7
  2024-05-21 07:52:22.987941+00 | 00:00:00.004102 | rows affected: 1                                                                              | [n1,client=127.0.0.1:62343,hostssl,user=demo]              | sql/conn_executor_exec.go:1150          | sql query        |    2
  2024-05-21 07:52:22.988157+00 | 00:00:00.004318 | querying next range at /Tenant/2/Table/104/1/3/0                                              | [n1,client=127.0.0.1:62343,hostssl,user=demo,txn=cd4a7e62] | kv/kvclient/kvcoord/range_iter.go:188   | dist sender send |   13
  2024-05-21 07:52:22.988204+00 | 00:00:00.004365 | key: /Tenant/2/Table/104/1/3/0, desc: r81:/Tenant/{2/Table/104-3} [(n1,s1):1, next=2, gen=13] | [n1,client=127.0.0.1:62343,hostssl,user=demo,txn=cd4a7e62] | kv/kvclient/kvcoord/range_iter.go:225   | dist sender send |   13
  2024-05-21 07:52:22.988232+00 | 00:00:00.004393 | r81: sending batch 1 EndTxn to (n1,s1):1                                                      | [n1,client=127.0.0.1:62343,hostssl,user=demo,txn=cd4a7e62] | kv/kvclient/kvcoord/dist_sender.go:2656 | dist sender send |   13
(9 rows)

Time: 4ms total (execution 3ms / network 1ms)

[michae2]

(We'll also want to add this to kv_batch_streamer.go, too.)