Lock RPC time does not include in execution info and slow query log

[jackysp]

Enhancement

The following execution info is only time:532.1µs, but it acturally has a long lock RPC time, which makes the user confused. It has the similar issue in slow query logs.

Query OK, 0 rows affected (0.00 sec)

mysql> insert into t values (1) on duplicate key update i = i + 1;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
mysql> select tidb_decode_plan('rALQMAkyN18xCTAJMAlOL0EJMAl0aW1lOjUzMi4xwrVzLCBsb29wczoxLCBwcmVwYXJlOiAyN8IBGVBjaGVja19pbnNlcnQ6IHt0b3RhbF8FPQwgNTA1BTwIbWVtDSENGRAzNjQuOAUbOHByZWZldGNoOiAxNDAuMwUUSHJwYzp7QmF0Y2hHZXQ6e251bV8BEwgyLCAdXQQ3OAUuCH19fQGcJGNrX2tleXM6IHsFeig1MHMsIHJlZ2lvbgGzBRsAMwESPHNvbHZlX2xvY2s6Ni42MW0F2QRjawVgLDQ5Ljk5NTM0MDk5NQE/ZHBjX2NvdW50OjUwfQk3MiBCeXRlcwlOL0EK');
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('rALQMAkyN18xCTAJMAlOL0EJMAl0aW1lOjUzMi4xwrVzLCBsb29wczoxLCBwcmVwYXJlOiAyN8IBGVBjaGVja19pbnNlcnQ6IHt0b3RhbF8FPQwgNTA1BTwIbWVtDSENGRAzNjQuOAUbOHByZWZldGNoOiAxNDAuMwUUSHJwYzp7QmF0Y2hHZXQ6e251bV8BEwgyLCAdXQQ3OAUuCH19fQGcJGNrX2tleXM6IHsFeig1MH                                                                                                                                                                                                                                                                                                                                                                                                                 |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 	id      	task	estRows	operator info	actRows	execution info                                                                                                                                                                                                                                                               	memory  	disk
	Insert_1	root	0      	N/A          	0      	time:532.1µs, loops:1, prepare: 27µs, check_insert: {total_time: 505µs, mem_insert_time: 364.8µs, prefetch: 140.3µs, rpc:{BatchGet:{num_rpc:2, total_time:78.3µs}}}, lock_keys: {time:50s, region:1, keys:3, resolve_lock:6.61ms, lock_rpc:49.995340995s, rpc_count:50}	72 Bytes	N/A       |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

# Time: 2024-03-28T11:45:47.482605+08:00
# Txn_start_ts: 448685012233486336
# User@Host: root[root] @ ::1 [::1]
# Conn_ID: 2097158
# Query_time: 50.003737875
# Parse_time: 0.000075166
# Compile_time: 0.000183459
# Rewrite_time: 0.000055583
# Optimize_time: 0.000021208
# Wait_TS: 0
# DB: test
# Is_internal: false
# Digest: 9bc9aa8738432dd182bf573d427d113801689c87630198efc06de39876a793b5
# Num_cop_tasks: 0
# Mem_max: 8264
# Prepared: false
# Plan_from_cache: false
# Plan_from_binding: false
# Has_more_results: false
# KV_total: 0
# PD_total: 0
# Backoff_total: 0
# Write_sql_response_total: 0
# Result_rows: 0
# Succ: false
# IsExplicitTxn: true
# IsSyncStatsFailed: false
# Plan: tidb_decode_plan('rALQMAkyN18xCTAJMAlOL0EJMAl0aW1lOjUzMi4xwrVzLCBsb29wczoxLCBwcmVwYXJlOiAyN8IBGVBjaGVja19pbnNlcnQ6IHt0b3RhbF8FPQwgNTA1BTwIbWVtDSENGRAzNjQuOAUbOHByZWZldGNoOiAxNDAuMwUUSHJwYzp7QmF0Y2hHZXQ6e251bV8BEwgyLCAdXQQ3OAUuCH19fQGcJGNrX2tleXM6IHsFeig1MHMsIHJlZ2lvbgGzBRsAMwESPHNvbHZlX2xvY2s6Ni42MW0F2QRjawVgLDQ5Ljk5NTM0MDk5NQE/ZHBjX2NvdW50OjUwfQk3MiBCeXRlcwlOL0EK')
# Binary_plan: tidb_decode_binary_plan('tQLwPAqwAgoISW5zZXJ0XzE4AUABUgNOL0FaFnRpbWU6NTMyLjHCtXMsIGxvb3BzOjFikQFwcmVwYXJlOiAyN8IBGhxjaGVja19pbgFCIDoge3RvdGFsXwU+ECA1MDXCASMIbWVtDSENGRAzNjQuOAUbOHByZWZldGNoOiAxNDAuMwUUSHJwYzp7QmF0Y2hHZXQ6e251bV8BEwgyLCAdXQQ3OAUuQH19fWJibG9ja19rZXlzOiB7BXo4NTBzLCByZWdpb246MSwgBRsAMwESFHNvbHZlXwEwGDo2LjYxbXMB2gRjawVgLDQ5Ljk5NTM0MDk5NQE/aHBjX2NvdW50OjUwfXBIeP///////////wEYAQ==')
# Resource_group: default
# Request_unit_read: 0.95
# Request_unit_write: 85.00000000000007
use test;
insert into t values (1) on duplicate key update i = i + 1;

[jackysp]

git hash: 8bca3dd

[jackysp]

Preparation:

create table t (i int, unique key (i));
insert into t values (1);

Txn1:

begin;
select * from t for update;

Txn2:

begin;
insert into t values (1) on duplicate key update i = i + 1;