1、硬件，4台(64G内存、16核、阿里云SSD盘)
2、日志
1) tidb_slow_query.log
Time: 2019-08-07T09:50:25.745265227+08:00
Txn_start_ts: 410292748296126475
Query_time: 0.703752069
Prewrite_time: 0.556934552 Commit_time: 0.145204897 Get_commit_ts_time: 0.000285525 Local_latch_wait_time: 5.963e-06 Write_keys: 3 Write_size: 84 Prewrite_region: 1
Is_internal: true
Digest: 8d1c7c8cd6c130cdb23dc1cf1743c3333a8b43d67136d0fa03e69a0d7308cf8c
Num_cop_tasks: 0
Cop_proc_avg: 0 Cop_proc_p90: 0 Cop_proc_max: 0 Cop_proc_addr:
Cop_wait_avg: 0 Cop_wait_p90: 0 Cop_wait_max: 0 Cop_wait_addr:
delete from mysql.stats_meta where table_id = 550489;
Time: 2019-08-07T09:50:26.287418085+08:00
Txn_start_ts: 410292748479627276
Query_time: 0.530500808
Prewrite_time: 0.327225982 Commit_time: 0.201623181 Get_commit_ts_time: 0.000287689 Local_latch_wait_time: 5e-06 Write_keys: 3 Write_size: 84 Prewrite_region: 1
Is_internal: true
Digest: 8d1c7c8cd6c130cdb23dc1cf1743c3333a8b43d67136d0fa03e69a0d7308cf8c
Num_cop_tasks: 0
Cop_proc_avg: 0 Cop_proc_p90: 0 Cop_proc_max: 0 Cop_proc_addr:
Cop_wait_avg: 0 Cop_wait_p90: 0 Cop_wait_max: 0 Cop_wait_addr:
delete from mysql.stats_meta where table_id = 550539;
Time: 2019-08-07T09:50:26.642814977+08:00
Txn_start_ts: 410292748374769665
Query_time: 1.3073201669999999
Prewrite_time: 0.723361959 Commit_time: 0.58228445 Get_commit_ts_time: 0.00029737 Local_latch_wait_time: 4.278e-06 Write_keys: 2 Write_size: 56 Prewrite_region: 1
Is_internal: true
Digest: c6cc6600d9e30e2c65d85988b59746e00e0306aced60ded10b7abdea6308b200
Num_cop_tasks: 0
Cop_proc_avg: 0 Cop_proc_p90: 0 Cop_proc_max: 0 Cop_proc_addr:
Cop_wait_avg: 0 Cop_wait_p90: 0 Cop_wait_max: 0 Cop_wait_addr:
DELETE FROM mysql.gc_delete_range_done WHERE job_id = 520158 AND element_id = 513959;
Time: 2019-08-07T09:50:26.837264282+08:00
Txn_start_ts: 410292748623806468
Query_time: 0.546290999
Prewrite_time: 0.10780567 Commit_time: 0.43682156 Get_commit_ts_time: 0.000319809 Local_latch_wait_time: 3.85e-06 Write_keys: 3 Write_size: 84 Prewrite_region: 1
…skipping…
Cop_wait_avg: 0 Cop_wait_p90: 0 Cop_wait_max: 0 Cop_wait_addr:
update mysql.stats_meta set version = 410407803483324418, count = count + 0, modify_count = modify_count + 4002 where table_id = 15;
Time: 2019-08-12T11:45:26.450522464+08:00
Txn_start_ts: 410407803588182020
Query_time: 0.306597233
Wait_time: 0.305 Request_count: 1 Total_keys: 1
Is_internal: true
Digest: 16e7ac941a71c9c110e4ef0b2a3be61537fb4e890c78d99a4ccd1fce5d8f240e
Stats: stats_feedback:pseudo
Num_cop_tasks: 1
Cop_proc_avg: 0 Cop_proc_p90: 0 Cop_proc_max: 0 Cop_proc_addr: 10.0.66.74:20160
Cop_wait_avg: 0.305 Cop_wait_p90: 0.305 Cop_wait_max: 0.305 Cop_wait_addr: 10.0.66.74:20160
Mem_max: 116
select table_id, hist_id, is_index, feedback from mysql.stats_feedback order by table_id, hist_id, is_index;
Time: 2019-08-12T11:45:28.205124917+08:00
Txn_start_ts: 410407803968290817
Query_time: 0.594862516
Wait_time: 0.593 Request_count: 2
Index_ids: [1]
Is_internal: true
Digest: ab6d79d3e75abdf0ba1e0fb7161312e07099349d4d14a13968fa9cc7767d66a1
Stats: tidb:pseudo
Num_cop_tasks: 2
Cop_proc_avg: 0 Cop_proc_p90: 0 Cop_proc_max: 0 Cop_proc_addr: 10.0.66.75:20160
Cop_wait_avg: 0.2965 Cop_wait_p90: 0.593 Cop_wait_max: 0.593 Cop_wait_addr: 10.0.66.75:20160
Mem_max: 9605
SELECT HIGH_PRIORITY (variable_value) FROM mysql.tidb WHERE variable_name=‘tikv_gc_leader_uuid’ FOR UPDATE;
Time: 2019-08-12T11:45:28.987246551+08:00
Txn_start_ts: 410407803968290817
Query_time: 0.490320554
Prewrite_time: 0.227371058 Commit_time: 0.262557179 Get_commit_ts_time: 0.000319775 Local_latch_wait_time: 3.181e-06 Write_keys: 1 Write_size: 119 Prewrite_region: 1
Is_internal: true
Digest: 9505cacb7c710ed17125fcc6cb3669e8ddca6c8cd8af6a31f6b3cd64604c3098
Num_cop_tasks: 0
Cop_proc_avg: 0 Cop_proc_p90: 0 Cop_proc_max: 0 Cop_proc_addr:
Cop_wait_avg: 0 Cop_wait_p90: 0 Cop_wait_max: 0 Cop_wait_addr:
COMMIT;
2) tidb.log
[2019/08/12 11:45:08.184 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:415.839879ms txnStartTS:410407798764732417 region_id:40 store_addr:10.0.66.75:20160 kv_wait_ms:415”]
[2019/08/12 11:45:20.348 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:580.253323ms txnStartTS:410407801910460417 region_id:40 store_addr:10.0.66.75:20160 kv_wait_ms:579”]
[2019/08/12 11:45:23.145 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:307.767041ms txnStartTS:410407802709999617 region_id:72 store_addr:10.0.66.74:20160 kv_wait_ms:307”]
[2019/08/12 11:45:26.450 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:306.218368ms txnStartTS:410407803588182020 region_id:60 store_addr:10.0.66.74:20160 kv_wait_ms:305”]
[2019/08/12 11:45:28.204 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:593.856442ms txnStartTS:410407803968290817 region_id:32 store_addr:10.0.66.75:20160 kv_wait_ms:593”]
[2019/08/12 11:45:28.987 +08:00] [INFO] [gc_worker.go:244] [“[gc worker] there’s already a gc job running, skipped”] [“leaderTick on”=5b1d6f5d5d40001]
[2019/08/12 11:45:53.199 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:427.567562ms txnStartTS:410407810561212418 region_id:28 store_addr:10.0.66.74:20160 kv_wait_ms:427”]
[2019/08/12 11:45:56.166 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:395.938585ms txnStartTS:410407811347644418 region_id:60 store_addr:10.0.66.74:20160 kv_wait_ms:395”]
[2019/08/12 11:45:56.361 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:592.610156ms txnStartTS:410407811347644417 region_id:40 store_addr:10.0.66.75:20160 kv_wait_ms:592”]
[2019/08/12 11:46:08.420 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:651.9527ms txnStartTS:410407814493372417 region_id:40 store_addr:10.0.66.75:20160 kv_wait_ms:651”]
[2019/08/12 11:46:09.476 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:414.087099ms txnStartTS:410407814834159617 region_id:72 store_addr:10.0.66.74:20160 kv_wait_ms:413”]
[2019/08/12 11:46:17.209 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:439.179506ms txnStartTS:410407816852668418 region_id:28 store_addr:10.0.66.74:20160 kv_wait_ms:438”]
[2019/08/12 11:46:20.270 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:501.600465ms txnStartTS:410407817639100417 region_id:40 store_addr:10.0.66.75:20160 kv_wait_ms:501”]
[2019/08/12 11:46:28.302 +08:00] [INFO] [gc_worker.go:244] [“[gc worker] there’s already a gc job running, skipped”] [“leaderTick on”=5b1d6f5d5d40001]
[2019/08/12 11:46:32.398 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:630.161982ms txnStartTS:410407820784828417 region_id:40 store_addr:10.0.66.75:20160 kv_wait_ms:629”]
[2019/08/12 11:46:44.381 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:613.108838ms txnStartTS:410407823930556417 region_id:40 store_addr:10.0.66.75:20160 kv_wait_ms:612”]
[2019/08/12 11:46:56.314 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:545.499854ms txnStartTS:410407827076284417 region_id:40 store_addr:10.0.66.75:20160 kv_wait_ms:545”]
[2019/08/12 11:47:05.189 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:556.198081ms txnStartTS:410407829396258817 region_id:72 store_addr:10.0.66.74:20160 kv_wait_ms:556”]
[2019/08/12 11:47:08.246 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:476.202059ms txnStartTS:410407830222012418 region_id:28 store_addr:10.0.66.74:20160 kv_wait_ms:469”]
[2019/08/12 11:47:08.259 +08:00] [INFO] [coprocessor.go:726] [“[TIME_COP_WAIT] resp_time:490.956018ms txnStartTS:410407830222012417 region_id:40 store_addr:10.0.66.75:20160 kv_wait_ms:490”]
3、SQL
explain ANALYZE
SELECT
version,
table_id,
modify_count,
count
FROM
mysql.stats_meta
WHERE
version > 410406893660143619
ORDER BY
version;
结果如下：
| Projection_18 | 3333.33 | root | mysql.stats_meta.version, mysql.stats_meta.table_id, mysql.stats_meta.modify_count, mysql.stats_meta.count | time:235.79554ms, loops:2, rows:12 |
|---|---|---|---|---|
| └─IndexLookUp_17 | 3333.33 | root | time:235.740265ms, loops:2, rows:12 | |
| ├─IndexScan_15 | 3333.33 | cop | table:stats_meta, index:version, range:(410406893660143619,+inf], keep order:true, stats:pseudo | time:0s, loops:1, rows:12 |
| └─TableScan_16 | 3333.33 | cop | table:stats_meta, keep order:false, stats:pseudo | time:0s, loops:1, rows:12 |