【 TiDB 使用环境】生产环境
【 TiDB 版本】v6.5.3
【复现路径】无
【遇到的问题：问题现象及影响】
执行时间超时，dashboard中显示sql执行时间1.1day，但是下面明细加起来不超过1分钟，grafana里内存、cpu、io都是正常的。
可能是哪里的原因？怎么排查？
slow log 里的明细看一下
Succ: false
tidb.log 用 txn_start_ts 都下有没有信息 
用 txn_start_ts 的值搜搜看。。。
“自然时间”（如果是指实际耗时）可能包括数据库执行时间、网络延迟、客户端处理时间等。
是，但是这个语句手工执行很快，实际不应该用了1天的时间才执行完。
有没有可能是包含在显示事务里了，事务没有提交的问题
这个语句是日终循环语句里的某一个，每次循环的表都是一样的。前一次循环和后一次循环都没问题。只有这一个循环里执行超时了，程序里是提示执行超时，但是数据库里看是执行了1天。
之前tidb 4.0遇到过jdbc版本过低可能会出现该问题，换一下jdbc试试
之前也遇到类似问题，已经换到8.0的驱动了。但是现在这个问题还不是稳定复现，但是最近出现的几次都是同一个sql语句。
不是稳定复现就比较难查，网络抓包可以看具体慢在哪，但是持续网络抓包代价比较大。。。之前我们这种问题也是持续查了一个月
8.0的驱动建议用比较新的版本，至少要8.0.33以上。
https://docs.pingcap.com/zh/tidb/v7.5/dev-guide-choose-driver-or-orm#java-drivers
关键是不慢，感觉是在tidb里被挂起了。但是不知道因为什么被挂起。
语句文本和执行计划呢，发出来看下
||id |task |estRows |operator info |actRows |execution info |memory |disk|
|---|---|---|---|---|---|---|---|---|
||Insert_1 |root |0 |N/A |0 |time:26h25m4.6s, loops:1 |0 Bytes |N/A|
||└─HashAgg_25 |root |1412223.79 |group by:enjoycrm_datacenter.tb_customer.c_no, funcs:firstrow(enjoycrm_datacenter.tb_customer.c_no)->enjoycrm_datacenter.tb_customer.c_no |0 |time:26h25m4.6s, loops:1, partial_worker:{wall_time:26h25m4.602867546s, concurrency:5, task_num:32, tot_wait:132h5m22.982021551s, tot_exec:25.525632ms, tot_time:132h5m23.011302034s, max:26h25m4.602789851s, p95:26h25m4.602789851s}, final_worker:{wall_time:26h25m4.601569114s, concurrency:5, task_num:0, tot_wait:132h5m23.007476331s, tot_exec:2.779µs, tot_time:132h5m23.00748276s, max:26h25m4.601502263s, p95:26h25m4.601502263s}|5.62 MB |N/A|
|| └─HashJoin_28 |root |1412223.79 |semi join, equal:[eq(enjoycrm_datacenter.tb_customer.c_no, enjoycrm_datacenter.tb_cust_store_qry_limit.c_cust_no)] |32768 |time:26h25m4.6s, loops:33, build_hash_table:{total:2.21s, fetch:1.4s, build:810.2ms}, probe:{concurrency:5, total:132h5m23s, max:26h25m4.6s, probe:62.1ms, fetch:132h5m22.9s} |116.8 MB|0 Bytes|
|| ├─HashJoin_69(Build) |root |13499780.80|semi join, equal:[eq(enjoycrm_datacenter.tb_cust_store_qry_limit.c_store_id, enjoycrm_datacenter.tb_store.c_id)] |1428211 |time:1.7s, loops:1398, build_hash_table:{total:3.28ms, fetch:3.27ms, build:11.2µs}, probe:{concurrency:5, total:11s, max:2.21s, probe:4.1s, fetch:6.94s} |1.84 KB |0 Bytes|
|| │ ├─HashJoin_79(Build) |root |204.80 |CARTESIAN semi join, other cond:like(enjoycrm_datacenter.tb_store.c_id_level, concat(enjoycrm_datacenter.tb_store.c_id_level, %), 92) |4 |time:3.25ms, loops:2, build_hash_table:{total:715.7µs, fetch:709.4µs, build:6.24µs}, probe:{concurrency:5, total:14.1ms, max:3.09ms, probe:351.3µs, fetch:13.7ms} |33.7 KB |0 Bytes|
|| │ │ ├─Point_Get_82(Build) |root |1 |table:tb_store, clustered index:PRIMARY(c_id) |1 |time:678.4µs, loops:2, Get:{num_rpc:1, total_time:607.1µs}, tikv_wall_time: 205.2µs, scan_detail: {total_process_keys: 1, total_process_keys_size: 119, total_keys: 1, get_snapshot_time: 13.3µs, rocksdb: {block: {cache_hit_count: 11}}} |N/A |N/A|
|| │ │ └─TableReader_81(Probe)|root |256 |data:TableFullScan_80 |256 |time:2.73ms, loops:2, cop_task: {num: 2, max: 1.61ms, min: 1.44ms, avg: 1.52ms, p95: 1.61ms, max_proc_keys: 224, p95_proc_keys: 224, rpc_num: 2, rpc_time: 3.02ms, copr_cache_hit_ratio: 0.00, distsql_concurrency: 15} |7.75 KB |N/A|
|| │ │ └─TableFullScan_80 |cop[tikv]|256 |table:ts1, keep order:false |256 |tikv_task:{proc max:1ms, min:1ms, avg: 1ms, p80:1ms, p95:1ms, iters:5, tasks:2}, scan_detail: {total_process_keys: 256, total_process_keys_size: 32953, total_keys: 258, get_snapshot_time: 1.07ms, rocksdb: {key_skipped_count: 256, block: {cache_hit_count: 28, read_count: 4, read_byte: 144.1 KB, read_time: 56.2µs}}} |N/A |N/A|
|| │ └─IndexReader_75(Probe) |root |16874726 |index:Selection_74 |16874726|time:1.37s, loops:16524, cop_task: {num: 588, max: 108.9ms, min: 404µs, avg: 45.3ms, p95: 91.8ms, max_proc_keys: 50144, p95_proc_keys: 50144, tot_proc: 24.4s, tot_wait: 219ms, rpc_num: 588, rpc_time: 26.6s, copr_cache_hit_ratio: 0.08, distsql_concurrency: 15} |8.35 MB |N/A|
|| │ └─Selection_74 |cop[tikv]|16874726 |eq(enjoycrm_datacenter.tb_cust_store_qry_limit.c_org_id, 8) |16874726|tikv_task:{proc max:100ms, min:0s, avg: 39.6ms, p80:69ms, p95:82ms, iters:18811, tasks:588}, scan_detail: {total_process_keys: 16790438, total_process_keys_size: 2047718239, total_keys: 16790980, get_snapshot_time: 432.7ms, rocksdb: {key_skipped_count: 16790438, block: {cache_hit_count: 25963, read_count: 3440, read_byte: 12.4 MB, read_time: 13.7ms}}} |N/A |N/A|
|| │ └─IndexFullScan_73 |cop[tikv]|16874726 |table:tb_cust_store_qry_limit, index:tb_cust_store_qry_limit_c_cust_no_IDX(c_cust_no), keep order:false |16874726|tikv_task:{proc max:97ms, min:0s, avg: 37.1ms, p80:65ms, p95:78ms, iters:18811, tasks:588} |N/A |N/A|
|| └─MergeJoin_30(Probe) |root |1765279.74 |inner join, left key:enjoycrm_datacenter.tb_customer_address.c_org_id, right key:enjoycrm_datacenter.tb_customer.c_org_id, other cond:eq(enjoycrm_datacenter.tb_customer_address.c_no, enjoycrm_datacenter.tb_customer.c_no)|66227 |time:26h25m4.6s, loops:65 |144.1 MB|0 Bytes|
|| ├─IndexReader_59(Build) |root |6064525 |index:IndexRangeScan_58 |6066172 |time:5.22s, loops:6648, cop_task: {num: 184, max: 99.4ms, min: 538.3µs, avg: 50.4ms, p95: 89.3ms, max_proc_keys: 50144, p95_proc_keys: 50144, tot_proc: 8.71s, tot_wait: 29ms, rpc_num: 184, rpc_time: 9.27s, copr_cache_hit_ratio: 0.03, distsql_concurrency: 15} |15.8 MB |N/A|
|| │ └─IndexRangeScan_58 |cop[tikv]|6064525 |table:td, index:idx_orgid_borndate(c_org_id, c_born_date), range:[8,8], keep order:true |6066172 |tikv_task:{proc max:93ms, min:0s, avg: 46ms, p80:74ms, p95:83ms, iters:6656, tasks:184}, scan_detail: {total_process_keys: 6043836, total_process_keys_size: 546046746, total_keys: 6050027, get_snapshot_time: 95.6ms, rocksdb: {delete_skipped_count: 6409, key_skipped_count: 6056258, block: {cache_hit_count: 1283, read_count: 7437, read_byte: 97.0 MB, read_time: 445.8ms}}} |N/A |N/A|
|| └─TableReader_57(Probe) |root |1677450.70 |data:Selection_56 |66685 |time:3.12ms, loops:66, cop_task: {num: 9, max: 214ms, min: 3.76ms, avg: 47.4ms, p95: 214ms, max_proc_keys: 141280, p95_proc_keys: 141280, tot_proc: 400ms, tot_wait: 3ms, rpc_num: 9, rpc_time: 426.7ms, copr_cache_hit_ratio: 0.00, distsql_concurrency: 15} |30.9 MB |N/A|
|| └─Selection_56 |cop[tikv]|1677450.70 |eq(enjoycrm_datacenter.tb_customer_address.c_city, 武汉市), eq(enjoycrm_datacenter.tb_customer_address.c_type, 家庭住址) |66685 |tikv_task:{proc max:202ms, min:2ms, avg: 43.9ms, p80:80ms, p95:202ms, iters:296, tasks:9}, scan_detail: {total_process_keys: 265952, total_process_keys_size: 79532810, total_keys: 265980, get_snapshot_time: 7.02ms, rocksdb: {key_skipped_count: 266001, block: {cache_hit_count: 580, read_count: 755, read_byte: 6.01 MB, read_time: 15.9ms}}} |N/A |N/A|
|| └─TableRangeScan_55 |cop[tikv]|4877038 |table:tca, range:[8,8], keep order:true |265952 |tikv_task:{proc max:159ms, min:2ms, avg: 36.1ms, p80:70ms, p95:159ms, iters:296, tasks:9} |N/A |N/A|
1 个赞
去看下执行快的时候，执行计划这里走的是 merge join 吗
哦，还真是，执行成功的是走的IndexJoin
||id |task |estRows |operator info |actRows |execution info |memory |disk|
|---|---|---|---|---|---|---|---|---|
||Insert_1 |root |0 |N/A |0 |time:21.9s, loops:1, prepare: 17.7s, check_insert: {total_time: 4.25s, mem_insert_time: 4.25s, prefetch: 79.5µs, fk_check: 593.4ms} |102.5 KB|N/A|
||└─HashAgg_25 |root |1419.62 |group by:enjoycrm_datacenter.tb_customer.c_no, funcs:firstrow(enjoycrm_datacenter.tb_customer.c_no)->enjoycrm_datacenter.tb_customer.c_no |509869 |time:17.4s, loops:501, partial_worker:{wall_time:17.294622798s, concurrency:5, task_num:545, tot_wait:1m25.939539375s, tot_exec:463.015167ms, tot_time:1m26.467337495s, max:17.294565384s, p95:17.294565384s}, final_worker:{wall_time:21.895520819s, concurrency:5, task_num:25, tot_wait:1m26.461881929s, tot_exec:22.734142674s, tot_time:1m49.196049199s, max:21.89545178s, p95:21.89545178s}|164.7 MB|N/A|
|| └─HashJoin_28 |root |1419.62 |semi join, equal:[eq(enjoycrm_datacenter.tb_customer.c_no, enjoycrm_datacenter.tb_cust_store_qry_limit.c_cust_no)] |555199 |time:17.3s, loops:546, build_hash_table:{total:2.22s, fetch:1.37s, build:855.8ms}, probe:{concurrency:5, total:1m26.4s, max:17.3s, probe:943.1ms, fetch:1m25.5s} |117.1 MB|0 Bytes|
|| ├─HashJoin_69(Build) |root |13540488.80|semi join, equal:[eq(enjoycrm_datacenter.tb_cust_store_qry_limit.c_store_id, enjoycrm_datacenter.tb_store.c_id)] |1437941 |time:1.64s, loops:1407, build_hash_table:{total:2.67ms, fetch:2.64ms, build:28.6µs}, probe:{concurrency:5, total:11.1s, max:2.22s, probe:4.61s, fetch:6.5s} |1.84 KB |0 Bytes|
|| │ ├─HashJoin_79(Build) |root |204.80 |CARTESIAN semi join, other cond:like(enjoycrm_datacenter.tb_store.c_id_level, concat(enjoycrm_datacenter.tb_store.c_id_level, %), 92) |4 |time:2.62ms, loops:2, build_hash_table:{total:1.8ms, fetch:1.79ms, build:6.29µs}, probe:{concurrency:5, total:10.7ms, max:2.45ms, probe:393.8µs, fetch:10.3ms} |33.7 KB |0 Bytes|
|| │ │ ├─Point_Get_82(Build) |root |1 |table:tb_store, clustered index:PRIMARY(c_id) |1 |time:1.76ms, loops:2, Get:{num_rpc:1, total_time:1.71ms}, tikv_wall_time: 1.31ms, scan_detail: {total_process_keys: 1, total_process_keys_size: 119, total_keys: 1, get_snapshot_time: 914.8µs, rocksdb: {block: {cache_hit_count: 10}}} |N/A |N/A|
|| │ │ └─TableReader_81(Probe)|root |256 |data:TableFullScan_80 |256 |time:2.05ms, loops:2, cop_task: {num: 2, max: 1.47ms, min: 985.9µs, avg: 1.23ms, p95: 1.47ms, max_proc_keys: 32, p95_proc_keys: 32, rpc_num: 2, rpc_time: 2.41ms, copr_cache_hit_ratio: 0.50, distsql_concurrency: 15} |7.74 KB |N/A|
|| │ │ └─TableFullScan_80 |cop[tikv]|256 |table:ts1, keep order:false |256 |tikv_task:{proc max:2ms, min:0s, avg: 1ms, p80:2ms, p95:2ms, iters:5, tasks:2}, scan_detail: {total_process_keys: 32, total_process_keys_size: 4124, total_keys: 33, get_snapshot_time: 910.2µs, rocksdb: {key_skipped_count: 32, block: {cache_hit_count: 16, read_count: 4, read_byte: 106.2 KB, read_time: 54.3µs}}} |N/A |N/A|
|| │ └─IndexReader_75(Probe) |root |16925611 |index:Selection_74 |16922059|time:1.31s, loops:16570, cop_task: {num: 589, max: 100.3ms, min: 351.4µs, avg: 44.5ms, p95: 89.4ms, max_proc_keys: 50144, p95_proc_keys: 50144, tot_proc: 23.9s, tot_wait: 211ms, rpc_num: 589, rpc_time: 26.2s, copr_cache_hit_ratio: 0.08, distsql_concurrency: 15} |13.1 MB |N/A|
|| │ └─Selection_74 |cop[tikv]|16925611 |eq(enjoycrm_datacenter.tb_cust_store_qry_limit.c_org_id, 8) |16922059|tikv_task:{proc max:90ms, min:0s, avg: 38.8ms, p80:70ms, p95:79ms, iters:18863, tasks:589}, scan_detail: {total_process_keys: 16800203, total_process_keys_size: 2049542006, total_keys: 16800744, get_snapshot_time: 415.9ms, rocksdb: {key_skipped_count: 16800203, block: {cache_hit_count: 30455, read_count: 46, read_byte: 442.9 KB, read_time: 1.96ms}}} |N/A |N/A|
|| │ └─IndexFullScan_73 |cop[tikv]|16925611 |table:tb_cust_store_qry_limit, index:tb_cust_store_qry_limit_c_cust_no_IDX(c_cust_no), keep order:false |16922059|tikv_task:{proc max:86ms, min:0s, avg: 36.4ms, p80:66ms, p95:75ms, iters:18863, tasks:589} |N/A |N/A|
|| └─IndexJoin_37(Probe) |root |1774.53 |inner join, inner:TableReader_33, outer key:enjoycrm_datacenter.tb_customer_address.c_org_id, enjoycrm_datacenter.tb_customer_address.c_no, inner key:enjoycrm_datacenter.tb_customer.c_org_id, enjoycrm_datacenter.tb_customer.c_no, equal cond:eq(enjoycrm_datacenter.tb_customer_address.c_no, enjoycrm_datacenter.tb_customer.c_no), eq(enjoycrm_datacenter.tb_customer_address.c_org_id, enjoycrm_datacenter.tb_customer.c_org_id)|1798769 |time:15.1s, loops:1758, inner:{total:1m10.1s, concurrency:5, task:78, construct:2.78s, fetch:1m6.6s, build:688.7ms}, probe:488.5ms |51.4 MB |N/A|
|| ├─TableReader_64(Build) |root |1680.83 |data:Selection_63 |1798769 |time:333.9ms, loops:1787, cop_task: {num: 167, max: 248.2ms, min: 2.13ms, avg: 46.1ms, p95: 189.4ms, max_proc_keys: 169952, p95_proc_keys: 120800, tot_proc: 7.1s, tot_wait: 64ms, rpc_num: 167, rpc_time: 7.7s, copr_cache_hit_ratio: 0.00, distsql_concurrency: 15} |33.7 MB |N/A|
|| │ └─Selection_63 |cop[tikv]|1680.83 |eq(enjoycrm_datacenter.tb_customer_address.c_city, 武汉市), eq(enjoycrm_datacenter.tb_customer_address.c_type, 家庭住址) |1798769 |tikv_task:{proc max:233ms, min:1ms, avg: 41.3ms, p80:73ms, p95:175ms, iters:5448, tasks:167}, scan_detail: {total_process_keys: 4889960, total_process_keys_size: 1417984674, total_keys: 4890483, get_snapshot_time: 121.6ms, rocksdb: {delete_skipped_count: 2, key_skipped_count: 4891650, block: {cache_hit_count: 2677, read_count: 21199, read_byte: 142.8 MB, read_time: 150.8ms}}} |N/A |N/A|
|| │ └─TableRangeScan_62 |cop[tikv]|4886853 |table:tca, range:[8,8], keep order:false |4889960 |tikv_task:{proc max:190ms, min:0s, avg: 34.3ms, p80:62ms, p95:143ms, iters:5448, tasks:167} |N/A |N/A|
|| └─TableReader_33(Probe) |root |1680.83 |data:Selection_32 |1510701 |time:1m4.6s, loops:1659, cop_task: {num: 1110, max: 731ms, min: 1.75ms, avg: 85.8ms, p95: 266.5ms, max_proc_keys: 9184, p95_proc_keys: 5088, tot_proc: 1m19.9s, tot_wait: 5.85s, rpc_num: 1110, rpc_time: 1m35.2s, copr_cache_hit_ratio: 0.00, distsql_concurrency: 15} |N/A |N/A|
|| └─Selection_32 |cop[tikv]|1680.83 |eq(enjoycrm_datacenter.tb_customer.c_org_id, 8) |1510701 |tikv_task:{proc max:707ms, min:0s, avg: 72.3ms, p80:121ms, p95:248ms, iters:5514, tasks:1110}, scan_detail: {total_process_keys: 1510701, total_process_keys_size: 471742749, total_keys: 3024253, get_snapshot_time: 4.05s, rocksdb: {key_skipped_count: 1512698, block: {cache_hit_count: 21965823, read_count: 10, read_byte: 448.4 KB, read_time: 209µs}}} |N/A |N/A|
|| └─TableRangeScan_31 |cop[tikv]|1680.83 |table:td, range: decided by [eq(enjoycrm_datacenter.tb_customer.c_no, enjoycrm_datacenter.tb_customer_address.c_no) eq(enjoycrm_datacenter.tb_customer.c_org_id, enjoycrm_datacenter.tb_customer_address.c_org_id)], keep order:false |1510701 |tikv_task:{proc max:707ms, min:0s, avg: 72.1ms, p80:120ms, p95:248ms, iters:5514, tasks:1110} |N/A |N/A|
