为提高效率，提问时请提供以下信息，问题描述清晰可优先响应。
- 【TiDB 版本】：2.1.9
- 【问题描述】：
遇到写入性能瓶颈，但是tikv性能不高，是否需要调参"scheduler-worker-pool-size = 4"
导一份监控出来，看下具体是哪里的瓶颈，另外也可以提供下 tidb.log 和 tikv.log 。
该脚本需要在中控机 tidb-ansible 目录下执行，并赋予执行权限 chmod +x info_gathering.py eg：cd /home/tidb/tidb-ansible & python info_gathering.py
主要就是最近的写的任务需求变大了，然后任务的单位执行时间变长了，但是从机器的性能指标来看利用率并没有达到饱和
这个是tikv机器一天内的监控指标图
tikv的机器都是8c64g的配置哦
tidb.log
[2019/11/15 10:56:40.009 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 222593, meta: id:222593 start_key:"t\200\000\000\000\000\002\203\300_i\200\000\000\000\000\000\000\001\00120190608\37717262613\377358\000\000\000\000\000\372" end_key:"t\200\000\000\000\000\002\203\300_i\200\000\000\000\000\000\000\002\00120170828\37716123317\377995\000\000\000\000\000\372\004\000\000\000\000\000\000\000\005" region_epoch:<conf_ver:38 version:20428 > peers:<id:3590759 store_id:5 > peers:<id:3690391 store_id:817018 > peers:<id:3717987 store_id:4 > , peer: id:3590759 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:41.624 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:494.510055ms txnStartTS:412558714757971978 region_id:2358986 store_addr:10.1.195.199:20160 kv_wait_ms:493"]
[2019/11/15 10:56:41.933 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:307.878332ms txnStartTS:412558714889043971 region_id:7665 store_addr:10.1.195.64:20160 kv_wait_ms:307"]
[2019/11/15 10:56:42.619 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:680.379799ms txnStartTS:412558714967687171 region_id:3147388 store_addr:10.1.195.63:20160 kv_wait_ms:676"]
[2019/11/15 10:56:43.214 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 126221, meta: id:126221 start_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\002\004\000\000\000\000\006\213\335\264\003\200\000\000\000\006\213\275\244" end_key:"t\200\000\000\000\000\000\362#_r\200\000\000\000\001\202\353\t" region_epoch:<conf_ver:53 version:6971 > peers:<id:3402592 store_id:5 > peers:<id:3808045 store_id:40549 > peers:<id:4155663 store_id:817018 > , peer: id:3402592 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:43.214 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 126241, meta: id:126241 start_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\001\004\000\000\000\000\000\000\000&\003\200\000\000\000\006\213u\t" end_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\002\004\000\000\000\000\001\214\307\013\003\200\000\000\000\001\214\276\275" region_epoch:<conf_ver:41 version:6972 > peers:<id:1935755 store_id:5 > peers:<id:3470883 store_id:40549 > peers:<id:4267031 store_id:4 > , peer: id:1935755 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:43.214 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 109985, meta: id:109985 start_key:"t\200\000\000\000\000\000\361\201_i\200\000\000\000\000\000\000\005\004\000\000\000\000\006\223AS\003\200\000\000\000\000\000\000\001\003\200\000\000\000\213\332,a" end_key:"t\200\000\000\000\000\000\361\201_r\200\000\000\000\007\303T\002" region_epoch:<conf_ver:59 version:7119 > peers:<id:2961391 store_id:5 > peers:<id:3976070 store_id:4 > peers:<id:4110487 store_id:40549 > , peer: id:2961391 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:44.370 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 126241, meta: id:126241 start_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\001\004\000\000\000\000\000\000\000&\003\200\000\000\000\006\213u\t" end_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\002\004\000\000\000\000\001\214\307\013\003\200\000\000\000\001\214\276\275" region_epoch:<conf_ver:41 version:6972 > peers:<id:1935755 store_id:5 > peers:<id:3470883 store_id:40549 > peers:<id:4267031 store_id:4 > , peer: id:1935755 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:44.370 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 126241, meta: id:126241 start_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\001\004\000\000\000\000\000\000\000&\003\200\000\000\000\006\213u\t" end_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\002\004\000\000\000\000\001\214\307\013\003\200\000\000\000\001\214\276\275" region_epoch:<conf_ver:41 version:6972 > peers:<id:1935755 store_id:5 > peers:<id:3470883 store_id:40549 > peers:<id:4267031 store_id:4 > , peer: id:1935755 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:44.370 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 126221, meta: id:126221 start_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\002\004\000\000\000\000\006\213\335\264\003\200\000\000\000\006\213\275\244" end_key:"t\200\000\000\000\000\000\362#_r\200\000\000\000\001\202\353\t" region_epoch:<conf_ver:53 version:6971 > peers:<id:3402592 store_id:5 > peers:<id:3808045 store_id:40549 > peers:<id:4155663 store_id:817018 > , peer: id:3402592 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:44.370 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 126221, meta: id:126221 start_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\002\004\000\000\000\000\006\213\335\264\003\200\000\000\000\006\213\275\244" end_key:"t\200\000\000\000\000\000\362#_r\200\000\000\000\001\202\353\t" region_epoch:<conf_ver:53 version:6971 > peers:<id:3402592 store_id:5 > peers:<id:3808045 store_id:40549 > peers:<id:4155663 store_id:817018 > , peer: id:3402592 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:44.370 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 109985, meta: id:109985 start_key:"t\200\000\000\000\000\000\361\201_i\200\000\000\000\000\000\000\005\004\000\000\000\000\006\223AS\003\200\000\000\000\000\000\000\001\003\200\000\000\000\213\332,a" end_key:"t\200\000\000\000\000\000\361\201_r\200\000\000\000\007\303T\002" region_epoch:<conf_ver:59 version:7119 > peers:<id:2961391 store_id:5 > peers:<id:3976070 store_id:4 > peers:<id:4110487 store_id:40549 > , peer: id:2961391 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:44.370 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 126221, meta: id:126221 start_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\002\004\000\000\000\000\006\213\335\264\003\200\000\000\000\006\213\275\244" end_key:"t\200\000\000\000\000\000\362#_r\200\000\000\000\001\202\353\t" region_epoch:<conf_ver:53 version:6971 > peers:<id:3402592 store_id:5 > peers:<id:3808045 store_id:40549 > peers:<id:4155663 store_id:817018 > , peer: id:3402592 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:44.371 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 109985, meta: id:109985 start_key:"t\200\000\000\000\000\000\361\201_i\200\000\000\000\000\000\000\005\004\000\000\000\000\006\223AS\003\200\000\000\000\000\000\000\001\003\200\000\000\000\213\332,a" end_key:"t\200\000\000\000\000\000\361\201_r\200\000\000\000\007\303T\002" region_epoch:<conf_ver:59 version:7119 > peers:<id:2961391 store_id:5 > peers:<id:3976070 store_id:4 > peers:<id:4110487 store_id:40549 > , peer: id:2961391 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:44.371 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 126241, meta: id:126241 start_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\001\004\000\000\000\000\000\000\000&\003\200\000\000\000\006\213u\t" end_key:"t\200\000\000\000\000\000\362#_i\200\000\000\000\000\000\000\002\004\000\000\000\000\001\214\307\013\003\200\000\000\000\001\214\276\275" region_epoch:<conf_ver:41 version:6972 > peers:<id:1935755 store_id:5 > peers:<id:3470883 store_id:40549 > peers:<id:4267031 store_id:4 > , peer: id:1935755 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:44.371 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 109985, meta: id:109985 start_key:"t\200\000\000\000\000\000\361\201_i\200\000\000\000\000\000\000\005\004\000\000\000\000\006\223AS\003\200\000\000\000\000\000\000\001\003\200\000\000\000\213\332,a" end_key:"t\200\000\000\000\000\000\361\201_r\200\000\000\000\007\303T\002" region_epoch:<conf_ver:59 version:7119 > peers:<id:2961391 store_id:5 > peers:<id:3976070 store_id:4 > peers:<id:4110487 store_id:40549 > , peer: id:2961391 store_id:5 , addr: 10.1.195.63:20160"]
[2019/11/15 10:56:44.835 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:719.992622ms txnStartTS:412558715544403972 region_id:3736282 store_addr:10.1.195.63:20160 kv_wait_ms:717"]
[2019/11/15 10:56:47.914 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:480.117664ms txnStartTS:412558716409479173 region_id:4287177 store_addr:10.1.195.199:20160 kv_wait_ms:479"]
[2019/11/15 10:56:48.101 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:667.025593ms txnStartTS:412558716409479173 region_id:4295244 store_addr:10.1.195.63:20160 kv_wait_ms:665"]
[2019/11/15 10:56:53.543 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:430.515292ms txnStartTS:412558717903699971 region_id:3340545 store_addr:10.1.195.63:20160 kv_wait_ms:428"]
[2019/11/15 10:56:54.141 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:595.366583ms txnStartTS:412558718008557574 region_id:3736282 store_addr:10.1.195.63:20160 kv_wait_ms:594"]
[2019/11/15 10:56:54.731 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:588.144871ms txnStartTS:412558718165843976 region_id:4058582 store_addr:10.1.195.63:20160 kv_wait_ms:585"]
[2019/11/15 10:56:54.732 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:589.010724ms txnStartTS:412558718165843976 region_id:4058582 store_addr:10.1.195.63:20160 kv_wait_ms:585"]
[2019/11/15 10:56:55.119 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:377.306157ms txnStartTS:412558718323130384 region_id:4209451 store_addr:10.1.195.199:20160 kv_wait_ms:376"]
[2019/11/15 10:56:55.120 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:378.262524ms txnStartTS:412558718323130384 region_id:4209451 store_addr:10.1.195.199:20160 kv_wait_ms:376"]
[2019/11/15 10:56:55.810 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:687.431936ms txnStartTS:412558718427987970 region_id:3338459 store_addr:10.1.195.63:20160 kv_wait_ms:685"]
[2019/11/15 10:56:56.749 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:585.075882ms txnStartTS:412558718703239173 region_id:3933162 store_addr:10.1.195.199:20160 kv_wait_ms:584"]
[2019/11/15 10:57:00.078 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:941.400386ms txnStartTS:412558719476563983 region_id:4274981 store_addr:10.1.195.199:20160 kv_wait_ms:940"]
[2019/11/15 10:57:00.080 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:943.567975ms txnStartTS:412558719476563983 region_id:4274981 store_addr:10.1.195.199:20160 kv_wait_ms:940"]
[2019/11/15 10:57:02.427 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:322.570401ms txnStartTS:412558720262995969 region_id:22 store_addr:10.1.195.200:20160 kv_wait_ms:321"]
[2019/11/15 10:57:02.614 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:427.474227ms txnStartTS:412558720276103172 region_id:18 store_addr:10.1.195.200:20160 kv_wait_ms:426"]
[2019/11/15 10:57:02.926 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:496.523998ms txnStartTS:412558720341639171 region_id:7665 store_addr:10.1.195.64:20160 kv_wait_ms:496"]
[2019/11/15 10:57:03.446 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:515.591009ms txnStartTS:412558720472711178 region_id:3644810 store_addr:10.1.195.199:20160 kv_wait_ms:513"]
[2019/11/15 10:57:03.596 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:664.97638ms txnStartTS:412558720472711178 region_id:4233389 store_addr:10.1.195.200:20160 kv_wait_ms:621"]
[2019/11/15 10:57:03.946 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:323.551711ms txnStartTS:412558720656211992 region_id:4169145 store_addr:10.1.195.199:20160 kv_wait_ms:322"]
[2019/11/15 10:57:04.323 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:374.924282ms txnStartTS:412558720734855174 region_id:4281945 store_addr:10.1.195.64:20160 kv_wait_ms:373"]
[2019/11/15 10:57:04.324 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:375.585218ms txnStartTS:412558720734855174 region_id:4281945 store_addr:10.1.195.64:20160 kv_wait_ms:374"]
[2019/11/15 10:57:20.831 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:800.605715ms txnStartTS:412558724955373579 region_id:3644810 store_addr:10.1.195.199:20160 kv_wait_ms:799"]
[2019/11/15 10:57:21.135 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:300.801164ms txnStartTS:412558725165088785 region_id:3973671 store_addr:10.1.195.200:20160 kv_wait_ms:300"]
[2019/11/15 10:57:21.136 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:301.878437ms txnStartTS:412558725165088785 region_id:3906840 store_addr:10.1.195.200:20160 kv_wait_ms:299"]
[2019/11/15 10:57:21.643 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:504.627995ms txnStartTS:412558725243731976 region_id:4209451 store_addr:10.1.195.199:20160 kv_wait_ms:504"]
[2019/11/15 10:57:21.644 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:505.220343ms txnStartTS:412558725243731976 region_id:4209451 store_addr:10.1.195.199:20160 kv_wait_ms:504"]
[2019/11/15 10:57:22.055 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:409.646827ms txnStartTS:412558725374803970 region_id:7665 store_addr:10.1.195.64:20160 kv_wait_ms:409"]
[2019/11/15 10:57:22.615 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:363.282892ms txnStartTS:412558725545197570 region_id:3864654 store_addr:10.1.195.199:20160 kv_wait_ms:362"]
[2019/11/15 10:57:22.615 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:363.481671ms txnStartTS:412558725545197570 region_id:3864654 store_addr:10.1.195.199:20160 kv_wait_ms:362"]
[2019/11/15 10:57:22.615 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:363.681093ms txnStartTS:412558725545197570 region_id:3933162 store_addr:10.1.195.199:20160 kv_wait_ms:362"]
[2019/11/15 10:57:23.118 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:500.816647ms txnStartTS:412558725636947969 region_id:4287177 store_addr:10.1.195.199:20160 kv_wait_ms:500"]
[2019/11/15 10:57:23.983 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:666.318794ms txnStartTS:412558725820448784 region_id:2449009 store_addr:10.1.195.64:20160 kv_wait_ms:664"]
[2019/11/15 10:57:23.984 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:667.921831ms txnStartTS:412558725820448784 region_id:2449009 store_addr:10.1.195.64:20160 kv_wait_ms:663"]
[2019/11/15 10:57:26.147 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 122561, meta: id:122561 start_key:"t\200\000\000\000\000\001F\324" end_key:"t\200\000\000\000\000\001F\326" region_epoch:<conf_ver:50 version:8718 > peers:<id:2609816 store_id:5 > peers:<id:3818612 store_id:4 > peers:<id:3864850 store_id:816585 > , peer: id:3864850 store_id:816585 , addr: 10.1.195.199:20160"]
[2019/11/15 10:57:27.270 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:699.680662ms txnStartTS:412558726672416787 region_id:549961 store_addr:10.1.195.64:20160 kv_wait_ms:698"]
[2019/11/15 10:57:29.829 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:712.417069ms txnStartTS:412558727340883973 region_id:4058582 store_addr:10.1.195.63:20160 kv_wait_ms:711"]
[2019/11/15 10:57:30.173 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:321.508392ms txnStartTS:412558727537491972 region_id:786937 store_addr:10.1.195.64:20160 kv_wait_ms:320"]
[2019/11/15 10:57:30.989 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:597.455743ms txnStartTS:412558727668563973 region_id:4304035 store_addr:10.1.195.200:20160 kv_wait_ms:562"]
[2019/11/15 10:57:31.294 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:304.017716ms txnStartTS:412558727825850381 region_id:7665 store_addr:10.1.195.64:20160 kv_wait_ms:303"]
[2019/11/15 10:57:38.700 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:590.779352ms txnStartTS:412558729700179970 region_id:3403835 store_addr:10.1.195.200:20160 kv_wait_ms:589"]
[2019/11/15 10:57:39.355 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:653.003337ms txnStartTS:412558729857466371 region_id:4169145 store_addr:10.1.195.199:20160 kv_wait_ms:652"]
[2019/11/15 10:57:39.355 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:653.516401ms txnStartTS:412558729857466371 region_id:4169145 store_addr:10.1.195.199:20160 kv_wait_ms:652"]
[2019/11/15 10:57:39.835 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:477.550047ms txnStartTS:412558730027859971 region_id:3198829 store_addr:10.1.195.200:20160 kv_wait_ms:476"]
[2019/11/15 10:57:40.566 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:552.106576ms txnStartTS:412558730198253569 region_id:4281945 store_addr:10.1.195.64:20160 kv_wait_ms:550"]
[2019/11/15 10:57:41.937 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:700.959039ms txnStartTS:412558730513350663 region_id:3933162 store_addr:10.1.195.199:20160 kv_wait_ms:699"]
[2019/11/15 10:57:50.552 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:443.964184ms txnStartTS:412558732845907970 region_id:7665 store_addr:10.1.195.64:20160 kv_wait_ms:443"]
[2019/11/15 10:57:59.778 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:664.234762ms txnStartTS:412558735205203972 region_id:7665 store_addr:10.1.195.64:20160 kv_wait_ms:663"]
[2019/11/15 10:58:00.710 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:758.26765ms txnStartTS:412558735428026373 region_id:4209451 store_addr:10.1.195.199:20160 kv_wait_ms:757"]
[2019/11/15 10:58:00.710 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:759.096979ms txnStartTS:412558735428026373 region_id:4209451 store_addr:10.1.195.199:20160 kv_wait_ms:757"]
[2019/11/15 10:58:02.664 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:478.718281ms txnStartTS:412558736004743175 region_id:16 store_addr:10.1.195.63:20160 kv_wait_ms:478"]
[2019/11/15 10:58:02.697 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:588.302746ms txnStartTS:412558735991635970 region_id:679765 store_addr:10.1.195.63:20160 kv_wait_ms:587"]
[2019/11/15 10:58:03.865 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:621.479464ms txnStartTS:412558736279994372 region_id:4295244 store_addr:10.1.195.63:20160 kv_wait_ms:620"]
[2019/11/15 10:58:04.220 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:349.28752ms txnStartTS:412558736450387978 region_id:4274981 store_addr:10.1.195.199:20160 kv_wait_ms:347"]
[2019/11/15 10:58:04.220 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:349.911433ms txnStartTS:412558736450387978 region_id:4274981 store_addr:10.1.195.199:20160 kv_wait_ms:347"]
[2019/11/15 10:58:05.048 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:823.116664ms txnStartTS:412558736542138378 region_id:4270986 store_addr:10.1.195.63:20160 kv_wait_ms:820"]
[2019/11/15 10:58:14.913 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:798.046263ms txnStartTS:412558739137363971 region_id:4295244 store_addr:10.1.195.63:20160 kv_wait_ms:797"]
[2019/11/15 10:58:15.320 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:362.92916ms txnStartTS:412558739360186372 region_id:1924579 store_addr:10.1.195.199:20160 kv_wait_ms:361"]
[2019/11/15 10:58:15.592 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:634.590749ms txnStartTS:412558739360186372 region_id:1896850 store_addr:10.1.195.63:20160 kv_wait_ms:633"]
[2019/11/15 10:58:16.098 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:498.538743ms txnStartTS:412558739530579971 region_id:3403835 store_addr:10.1.195.200:20160 kv_wait_ms:498"]
[2019/11/15 10:58:16.816 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:716.271773ms txnStartTS:412558739661651970 region_id:3934067 store_addr:10.1.195.64:20160 kv_wait_ms:716"]
[2019/11/15 10:58:16.816 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:716.514966ms txnStartTS:412558739661651970 region_id:3934067 store_addr:10.1.195.64:20160 kv_wait_ms:716"]
[2019/11/15 10:58:17.204 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:385.297384ms txnStartTS:412558739845152770 region_id:706933 store_addr:10.1.195.63:20160 kv_wait_ms:384"]
[2019/11/15 10:58:20.476 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:371.102837ms txnStartTS:412558740710227969 region_id:22 store_addr:10.1.195.200:20160 kv_wait_ms:370"]
[2019/11/15 10:58:21.081 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:602.430661ms txnStartTS:412558740801978373 region_id:7665 store_addr:10.1.195.64:20160 kv_wait_ms:602"]
[2019/11/15 10:58:21.471 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:389.08005ms txnStartTS:412558740801978373 region_id:4304035 store_addr:10.1.195.200:20160 kv_wait_ms:389"]
[2019/11/15 10:58:22.610 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:957.943784ms txnStartTS:412558741116551175 region_id:771489 store_addr:10.1.195.199:20160 kv_wait_ms:957"]
[2019/11/15 10:58:26.651 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:539.205066ms txnStartTS:412558742283091971 region_id:4295244 store_addr:10.1.195.63:20160 kv_wait_ms:539"]
[2019/11/15 10:58:27.241 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:339.942193ms txnStartTS:412558742492807171 region_id:1924579 store_addr:10.1.195.199:20160 kv_wait_ms:338"]
[2019/11/15 10:58:27.855 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:604.364269ms txnStartTS:412558742584557569 region_id:3934067 store_addr:10.1.195.64:20160 kv_wait_ms:603"]
[2019/11/15 10:58:27.855 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:604.761003ms txnStartTS:412558742584557569 region_id:3934067 store_addr:10.1.195.64:20160 kv_wait_ms:603"]
[2019/11/15 10:58:28.257 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:399.996674ms txnStartTS:412558742741843970 region_id:706933 store_addr:10.1.195.63:20160 kv_wait_ms:399"]
[2019/11/15 10:58:29.470 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:330.730399ms txnStartTS:412558743069523987 region_id:3416179 store_addr:10.1.195.64:20160 kv_wait_ms:329"]
[2019/11/15 10:58:41.636 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:522.279264ms txnStartTS:412558746215251972 region_id:2358986 store_addr:10.1.195.199:20160 kv_wait_ms:521"]
[2019/11/15 10:58:47.507 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 185113, meta: id:185113 start_key:"t\200\000\000\000\000\002#\241_r\200\000\000\000\001\216f\002" end_key:"t\200\000\000\000\000\002#\243" region_epoch:<conf_ver:23 version:16348 > peers:<id:1250571 store_id:4 > peers:<id:1659419 store_id:816585 > peers:<id:2570452 store_id:817018 > , peer: id:2570452 store_id:817018 , addr: 10.1.195.200:20160"]
[2019/11/15 10:58:47.638 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 4286105, meta: id:4286105 start_key:"t\200\000\000\000\000\0060y" end_key:"t\200\000\000\000\000\0060{" region_epoch:<conf_ver:2138 version:74429 > peers:<id:4286106 store_id:40549 > peers:<id:4286107 store_id:4 > peers:<id:4286108 store_id:817018 > , peer: id:4286108 store_id:817018 , addr: 10.1.195.200:20160"]
[2019/11/15 10:58:47.687 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 131197, meta: id:131197 start_key:"t\200\000\000\000\000\000\362\007_i\200\000\000\000\000\000\000\005\004\000\000\000\000\000\000\000\000\003\200\000\000\000\000\004\230\007" end_key:"t\200\000\000\000\000\000\362\007_i\200\000\000\000\000\000\000\005\004\031\241\252\256\260\000\000\000\003\200\000\000\000\000\003\307e" region_epoch:<conf_ver:38 version:6942 > peers:<id:3011631 store_id:816585 > peers:<id:3036394 store_id:4 > peers:<id:3838163 store_id:817018 > , peer: id:3838163 store_id:817018 , addr: 10.1.195.200:20160"]
[2019/11/15 10:58:47.687 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 124509, meta: id:124509 start_key:"t\200\000\000\000\000\000\361\177_i\200\000\000\000\000\000\000\001\00120191028\37719042345\377574\000\000\000\000\000\372\004\000\000\000\000\003K\216/\004\000\000\000\000\000\000\000\004\003\200\000\000\000\000\211${" end_key:"t\200\000\000\000\000\000\361\177_r\200\000\000\000\000\003\231U" region_epoch:<conf_ver:44 version:6880 > peers:<id:1645444 store_id:4 > peers:<id:3736872 store_id:816585 > peers:<id:3985778 store_id:817018 > , peer: id:3985778 store_id:817018 , addr: 10.1.195.200:20160"]
[2019/11/15 10:58:47.687 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 124509, meta: id:124509 start_key:"t\200\000\000\000\000\000\361\177_i\200\000\000\000\000\000\000\001\00120191028\37719042345\377574\000\000\000\000\000\372\004\000\000\000\000\003K\216/\004\000\000\000\000\000\000\000\004\003\200\000\000\000\000\211${" end_key:"t\200\000\000\000\000\000\361\177_r\200\000\000\000\000\003\231U" region_epoch:<conf_ver:44 version:6880 > peers:<id:1645444 store_id:4 > peers:<id:3736872 store_id:816585 > peers:<id:3985778 store_id:817018 > , peer: id:3985778 store_id:817018 , addr: 10.1.195.200:20160"]
[2019/11/15 10:58:47.687 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 124509, meta: id:124509 start_key:"t\200\000\000\000\000\000\361\177_i\200\000\000\000\000\000\000\001\00120191028\37719042345\377574\000\000\000\000\000\372\004\000\000\000\000\003K\216/\004\000\000\000\000\000\000\000\004\003\200\000\000\000\000\211${" end_key:"t\200\000\000\000\000\000\361\177_r\200\000\000\000\000\003\231U" region_epoch:<conf_ver:44 version:6880 > peers:<id:1645444 store_id:4 > peers:<id:3736872 store_id:816585 > peers:<id:3985778 store_id:817018 > , peer: id:3985778 store_id:817018 , addr: 10.1.195.200:20160"]
[2019/11/15 10:58:53.467 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:354.979564ms txnStartTS:412558749360979971 region_id:3718951 store_addr:10.1.195.62:20160 kv_wait_ms:353"]
[2019/11/15 10:58:53.468 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:356.040575ms txnStartTS:412558749360979971 region_id:3718951 store_addr:10.1.195.62:20160 kv_wait_ms:354"]
[2019/11/15 10:58:56.630 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:520.523408ms txnStartTS:412558750147411970 region_id:4295244 store_addr:10.1.195.63:20160 kv_wait_ms:519"]
[2019/11/15 10:58:58.933 +08:00] [WARN] [region_request.go:228] ["tikv reports `ServerIsBusy` retry later"] [reason="raftstore is busy"] [ctx="region ID: 382377, meta: id:382377 start_key:"t\200\000\000\000\000\003\3676_i\200\000\000\000\000\000\000\003\00142837172\3777616\000\000\000\000\373\003\200\000\000\000\0019\247:" end_key:"t\200\000\000\000\000\003\3676_i\200\000\000\000\000\000\000\003\00151501367\3776402307\000\376\003\200\000\000\000\001/\247\361" region_epoch:<conf_ver:35 version:37474 > peers:<id:3454834 store_id:816585 > peers:<id:3483718 store_id:817018 > peers:<id:4238254 store_id:4 > , peer: id:3454834 store_id:816585 , addr: 10.1.195.199:20160"]
[2019/11/15 10:58:59.886 +08:00] [INFO] [coprocessor.go:709] ["[TIME_COP_WAIT] resp_time:616.680381ms txnStartTS:412558750973165580 region_id:4233389 store_addr:10.1.195.200:20160 kv_wait_ms:615"]tikv.log
2019/11/15 11:00:42.295 INFO <unknown>:1108: [region 245689] 4049472 [logterm: 151, index: 194, vote: 0] cast MsgRequestVote for 4213362 [logterm: 151, index: 194] at term 152
2019/11/15 11:00:42.301 INFO <unknown>:1650: [region 268213] 3500114 [term 108] received MsgTimeoutNow from 3320045 and starts an election to get leadership.
2019/11/15 11:00:42.301 INFO <unknown>:1094: [region 268213] 3500114 is starting a new election at term 108
2019/11/15 11:00:42.301 INFO <unknown>:743: [region 268213] 3500114 became candidate at term 109
2019/11/15 11:00:42.301 INFO <unknown>:858: [region 268213] 3500114 received MsgRequestVoteResponse from 3500114 at term 109
2019/11/15 11:00:42.301 INFO <unknown>:832: [region 268213] 3500114 [logterm: 108, index: 172] sent MsgRequestVote request to 3753337 at term 109
2019/11/15 11:00:42.301 INFO <unknown>:832: [region 268213] 3500114 [logterm: 108, index: 172] sent MsgRequestVote request to 3320045 at term 109
2019/11/15 11:00:42.396 INFO <unknown>:858: [region 268213] 3500114 received MsgRequestVoteResponse from 3320045 at term 109
2019/11/15 11:00:42.396 INFO <unknown>:1575: [region 268213] 3500114 [quorum:2] has received 2 MsgRequestVoteResponse votes and 0 vote rejections
2019/11/15 11:00:42.396 INFO <unknown>:793: [region 268213] 3500114 became leader at term 109
2019/11/15 11:00:42.397 INFO <unknown>:1650: [region 206161] 1408553 [term 156] received MsgTimeoutNow from 4119337 and starts an election to get leadership.
2019/11/15 11:00:42.397 INFO <unknown>:1094: [region 206161] 1408553 is starting a new election at term 156
2019/11/15 11:00:42.397 INFO <unknown>:743: [region 206161] 1408553 became candidate at term 157
2019/11/15 11:00:42.397 INFO <unknown>:858: [region 206161] 1408553 received MsgRequestVoteResponse from 1408553 at term 157
2019/11/15 11:00:42.397 INFO <unknown>:832: [region 206161] 1408553 [logterm: 156, index: 551] sent MsgRequestVote request to 2753719 at term 157
2019/11/15 11:00:42.397 INFO <unknown>:832: [region 206161] 1408553 [logterm: 156, index: 551] sent MsgRequestVote request to 4119337 at term 157
2019/11/15 11:00:42.665 INFO <unknown>:858: [region 206161] 1408553 received MsgRequestVoteResponse from 4119337 at term 157
2019/11/15 11:00:42.665 INFO <unknown>:1575: [region 206161] 1408553 [quorum:2] has received 2 MsgRequestVoteResponse votes and 0 vote rejections
2019/11/15 11:00:42.665 INFO <unknown>:793: [region 206161] 1408553 became leader at term 157
2019/11/15 11:00:42.666 INFO <unknown>:1650: [region 333657] 3488902 [term 93] received MsgTimeoutNow from 2789011 and starts an election to get leadership.
2019/11/15 11:00:42.666 INFO <unknown>:1094: [region 333657] 3488902 is starting a new election at term 93
2019/11/15 11:00:42.666 INFO <unknown>:743: [region 333657] 3488902 became candidate at term 94
2019/11/15 11:00:42.666 INFO <unknown>:858: [region 333657] 3488902 received MsgRequestVoteResponse from 3488902 at term 94
2019/11/15 11:00:42.666 INFO <unknown>:832: [region 333657] 3488902 [logterm: 93, index: 724] sent MsgRequestVote request to 4178144 at term 94
2019/11/15 11:00:42.666 INFO <unknown>:832: [region 333657] 3488902 [logterm: 93, index: 724] sent MsgRequestVote request to 2789011 at term 94
2019/11/15 11:00:42.718 INFO apply.rs:902: [region 40473] 4309067 execute admin command cmd_type: ChangePeer change_peer {peer {id: 4309067 store_id: 40549}} at [term: 366, index: 687]
2019/11/15 11:00:42.718 INFO apply.rs:951: [region 40473] 4309067 exec ConfChange "AddNode", epoch: conf_ver: 48 version: 1330
2019/11/15 11:00:42.718 INFO apply.rs:1002: [region 40473] 4309067 add peer id: 4309067 store_id: 40549 to region id: 40473 start_key: "t200\000\000\000\000\000\013377\037_r200\000\000\000\001377\024\010177\000\000\000\000\000372" end_key: "t200\000\000\000\000\000\013377\037_r200\000\000\000\001377\025320242\000\000\000\000\000372" region_epoch {conf_ver: 48 version: 1330} peers {id: 3330187 store_id: 816585} peers {id: 3865338 store_id: 5} peers {id: 4305674 store_id: 4} peers {id: 4309067 store_id: 40549 is_learner: true}
2019/11/15 11:00:43.027 INFO <unknown>:858: [region 333657] 3488902 received MsgRequestVoteResponse from 4178144 at term 94
2019/11/15 11:00:43.027 INFO <unknown>:1575: [region 333657] 3488902 [quorum:2] has received 2 MsgRequestVoteResponse votes and 0 vote rejections
2019/11/15 11:00:43.027 INFO <unknown>:793: [region 333657] 3488902 became leader at term 94
2019/11/15 11:00:43.203 INFO pd.rs:558: [region 1369956] try to change peer AddNode id: 4309069 store_id: 5
2019/11/15 11:00:43.286 INFO peer.rs:1860: [region 1369956] 2834829 propose conf change AddNode peer 4309069
2019/11/15 11:00:43.294 INFO <unknown>:1650: [region 320925] 320928 [term 94] received MsgTimeoutNow from 4159052 and starts an election to get leadership.
2019/11/15 11:00:43.294 INFO <unknown>:1094: [region 320925] 320928 is starting a new election at term 94
2019/11/15 11:00:43.294 INFO <unknown>:743: [region 320925] 320928 became candidate at term 95
2019/11/15 11:00:43.294 INFO <unknown>:858: [region 320925] 320928 received MsgRequestVoteResponse from 320928 at term 95
2019/11/15 11:00:43.294 INFO <unknown>:832: [region 320925] 320928 [logterm: 94, index: 128] sent MsgRequestVote request to 4159052 at term 95
2019/11/15 11:00:43.294 INFO <unknown>:832: [region 320925] 320928 [logterm: 94, index: 128] sent MsgRequestVote request to 3641129 at term 95
2019/11/15 11:00:43.294 INFO <unknown>:1650: [region 66141] 3320968 [term 347] received MsgTimeoutNow from 4191803 and starts an election to get leadership.
2019/11/15 11:00:43.294 INFO <unknown>:1094: [region 66141] 3320968 is starting a new election at term 347
2019/11/15 11:00:43.294 INFO apply.rs:902: [region 40473] 4309067 execute admin command cmd_type: ChangePeer change_peer {change_type: RemoveNode peer {id: 4305674 store_id: 4}} at [term: 366, index: 688]
2019/11/15 11:00:43.294 INFO <unknown>:743: [region 66141] 3320968 became candidate at term 348
2019/11/15 11:00:43.294 INFO <unknown>:858: [region 66141] 3320968 received MsgRequestVoteResponse from 3320968 at term 348
2019/11/15 11:00:43.294 INFO <unknown>:832: [region 66141] 3320968 [logterm: 347, index: 275013] sent MsgRequestVote request to 3047947 at term 348
2019/11/15 11:00:43.294 INFO <unknown>:832: [region 66141] 3320968 [logterm: 347, index: 275013] sent MsgRequestVote request to 4191803 at term 348
2019/11/15 11:00:43.294 INFO apply.rs:951: [region 40473] 4309067 exec ConfChange "RemoveNode", epoch: conf_ver: 49 version: 1330
2019/11/15 11:00:43.294 INFO apply.rs:1045: [region 40473] 4309067 remove 4305674 from region:id: 40473 start_key: "t200\000\000\000\000\000\013377\037_r200\000\000\000\001377\024\010177\000\000\000\000\000372" end_key: "t200\000\000\000\000\000\013377\037_r200\000\000\000\001377\025320242\000\000\000\000\000372" region_epoch {conf_ver: 49 version: 1330} peers {id: 3330187 store_id: 816585} peers {id: 3865338 store_id: 5} peers {id: 4305674 store_id: 4} peers {id: 4309067 store_id: 40549}
2019/11/15 11:00:43.368 INFO <unknown>:924: [region 3600042] 4302198 [term: 9] received a MsgRequestVote message with higher term from 3749075 [term: 10]
2019/11/15 11:00:43.368 INFO <unknown>:723: [region 3600042] 4302198 became follower at term 10
2019/11/15 11:00:43.368 INFO <unknown>:1108: [region 3600042] 4302198 [logterm: 9, index: 3988, vote: 0] cast MsgRequestVote for 3749075 [logterm: 9, index: 3988] at term 10
2019/11/15 11:00:43.400 INFO <unknown>:858: [region 66141] 3320968 received MsgRequestVoteResponse from 3047947 at term 348
2019/11/15 11:00:43.400 INFO <unknown>:1575: [region 66141] 3320968 [quorum:2] has received 2 MsgRequestVoteResponse votes and 0 vote rejections
2019/11/15 11:00:43.400 INFO <unknown>:793: [region 66141] 3320968 became leader at term 348
2019/11/15 11:00:43.400 INFO <unknown>:858: [region 320925] 320928 received MsgRequestVoteResponse from 3641129 at term 95
2019/11/15 11:00:43.400 INFO <unknown>:1575: [region 320925] 320928 [quorum:2] has received 2 MsgRequestVoteResponse votes and 0 vote rejections
2019/11/15 11:00:43.400 INFO <unknown>:793: [region 320925] 320928 became leader at term 95
2019/11/15 11:00:43.413 INFO <unknown>:1650: [region 716673] 4057655 [term 68] received MsgTimeoutNow from 4186965 and starts an election to get leadership.
2019/11/15 11:00:43.413 INFO <unknown>:1094: [region 716673] 4057655 is starting a new election at term 68
2019/11/15 11:00:43.413 INFO <unknown>:743: [region 716673] 4057655 became candidate at term 69
2019/11/15 11:00:43.413 INFO <unknown>:858: [region 716673] 4057655 received MsgRequestVoteResponse from 4057655 at term 69
2019/11/15 11:00:43.413 INFO <unknown>:832: [region 716673] 4057655 [logterm: 68, index: 10070] sent MsgRequestVote request to 4074798 at term 69
2019/11/15 11:00:43.413 INFO <unknown>:832: [region 716673] 4057655 [logterm: 68, index: 10070] sent MsgRequestVote request to 4186965 at term 69
2019/11/15 11:00:43.415 INFO apply.rs:902: [region 1369956] 2834829 execute admin command cmd_type: ChangePeer change_peer {peer {id: 4309069 store_id: 5}} at [term: 42, index: 77]
2019/11/15 11:00:43.415 INFO apply.rs:951: [region 1369956] 2834829 exec ConfChange "AddNode", epoch: conf_ver: 216 version: 62289
2019/11/15 11:00:43.415 INFO apply.rs:1002: [region 1369956] 2834829 add peer id: 4309069 store_id: 5 to region id: 1369956 start_key: "t200\000\000\000\000\005\377353_r200\000\000\000\000377\027\026367\000\000\000\000\000372" end_key: "t200\000\000\000\000\005\377353_r200\000\000\000\000377 GT\000\000\000\000\000372" region_epoch {conf_ver: 216 version: 62289} peers {id: 2834829 store_id: 40549} peers {id: 4267027 store_id: 4} peers {id: 4304636 store_id: 816585} peers {id: 4309069 store_id: 5 is_learner: true}
2019/11/15 11:00:43.415 INFO <unknown>:858: [region 716673] 4057655 received MsgRequestVoteResponse from 4186965 at term 69
2019/11/15 11:00:43.415 INFO <unknown>:1575: [region 716673] 4057655 [quorum:2] has received 2 MsgRequestVoteResponse votes and 0 vote rejections
2019/11/15 11:00:43.415 INFO <unknown>:793: [region 716673] 4057655 became leader at term 69
2019/11/15 11:00:43.421 INFO peer.rs:1022: [region 1369956] 2834829 notify pd with change peer region id: 1369956 start_key: "t200\000\000\000\000\005\377353_r200\000\000\000\000377\027\026367\000\000\000\000\000372" end_key: "t200\000\000\000\000\005\377353_r200\000\000\000\000377 GT\000\000\000\000\000372" region_epoch {conf_ver: 217 version: 62289} peers {id: 2834829 store_id: 40549} peers {id: 4267027 store_id: 4} peers {id: 4304636 store_id: 816585} peers {id: 4309069 store_id: 5}
2019/11/15 11:00:43.423 INFO pd.rs:558: [region 1369956] try to change peer RemoveNode id: 4267027 store_id: 4
2019/11/15 11:00:43.424 INFO peer.rs:1860: [region 1369956] 2834829 propose conf change RemoveNode peer 4267027
2019/11/15 11:00:43.503 INFO <unknown>:924: [region 679529] 2823745 [term: 69] received a MsgRequestVote message with higher term from 1095913 [term: 70]
2019/11/15 11:00:43.503 INFO <unknown>:723: [region 679529] 2823745 became follower at term 70
2019/11/15 11:00:43.503 INFO <unknown>:1108: [region 679529] 2823745 [logterm: 69, index: 119307, vote: 0] cast MsgRequestVote for 1095913 [logterm: 69, index: 119307] at term 70
2019/11/15 11:00:43.503 INFO pd.rs:558: [region 1369956] try to change peer RemoveNode id: 4267027 store_id: 4
2019/11/15 11:00:43.504 INFO peer.rs:1838: [region 1369956] 2834829 there is a pending conf change, try later
2019/11/15 11:00:43.706 INFO apply.rs:902: [region 1369956] 2834829 execute admin command cmd_type: ChangePeer change_peer {change_type: RemoveNode peer {id: 4267027 store_id: 4}} at [term: 42, index: 78]
2019/11/15 11:00:43.706 INFO apply.rs:951: [region 1369956] 2834829 exec ConfChange "RemoveNode", epoch: conf_ver: 217 version: 62289
2019/11/15 11:00:43.706 INFO apply.rs:1045: [region 1369956] 2834829 remove 4267027 from region:id: 1369956 start_key: "t200\000\000\000\000\005\377353_r200\000\000\000\000377\027\026367\000\000\000\000\000372" end_key: "t200\000\000\000\000\005\377353_r200\000\000\000\000377 GT\000\000\000\000\000372" region_epoch {conf_ver: 217 version: 62289} peers {id: 2834829 store_id: 40549} peers {id: 4267027 store_id: 4} peers {id: 4304636 store_id: 816585} peers {id: 4309069 store_id: 5}
2019/11/15 11:00:43.708 INFO <unknown>:924: [region 725773] 3626158 [term: 65] received a MsgRequestVote message with higher term from 3990121 [term: 66]
2019/11/15 11:00:43.708 INFO <unknown>:723: [region 725773] 3626158 became follower at term 66
2019/11/15 11:00:43.708 INFO <unknown>:1108: [region 725773] 3626158 [logterm: 65, index: 3179, vote: 0] cast MsgRequestVote for 3990121 [logterm: 65, index: 3179] at term 66
2019/11/15 11:00:43.763 INFO peer.rs:1022: [region 1369956] 2834829 notify pd with change peer region id: 1369956 start_key: "t200\000\000\000\000\005\377353_r200\000\000\000\000377\027\026367\000\000\000\000\000372" end_key: "t200\000\000\000\000\005\377353_r200\000\000\000\000377 GT\000\000\000\000\000372" region_epoch {conf_ver: 218 version: 62289} peers {id: 2834829 store_id: 40549} peers {id: 4304636 store_id: 816585} peers {id: 4309069 store_id: 5}
2019/11/15 11:00:43.763 INFO apply.rs:902: [region 375517] 3254538 execute admin command cmd_type: ChangePeer change_peer {peer {id: 4309068 store_id: 816585}} at [term: 89, index: 114]
2019/11/15 11:00:43.763 INFO apply.rs:951: [region 375517] 3254538 exec ConfChange "AddNode", epoch: conf_ver: 30 version: 36309
2019/11/15 11:00:43.763 INFO apply.rs:1002: [region 375517] 3254538 add peer id: 4309068 store_id: 816585 to region id: 375517 start_key: "t200\000\000\000\000\003356377\007_r200\000\000\000\017377225375237\000\000\000\000\000372" end_key: "t200\000\000\000\000\003356377\007_r200\000\000\000\0203775|d\000\000\000\000\000372" region_epoch {conf_ver: 30 version: 36309} peers {id: 1662079 store_id: 4} peers {id: 2944023 store_id: 5} peers {id: 3254538 store_id: 40549} peers {id: 4309068 store_id: 816585 is_learner: true}
2019/11/15 11:00:43.803 INFO <unknown>:924: [region 383361] 4067017 [term: 69] received a MsgRequestVote message with higher term from 2694921 [term: 70]
2019/11/15 11:00:43.804 INFO <unknown>:723: [region 383361] 4067017 became follower at term 70
2019/11/15 11:00:43.804 INFO <unknown>:1108: [region 383361] 4067017 [logterm: 69, index: 2568, vote: 0] cast MsgRequestVote for 2694921 [logterm: 69, index: 2568] at term 70
2019/11/15 11:00:43.804 INFO <unknown>:924: [region 222909] 3785398 [term: 121] received a MsgRequestVote message with higher term from 4306391 [term: 122]
2019/11/15 11:00:43.804 INFO <unknown>:723: [region 222909] 3785398 became follower at term 122
2019/11/15 11:00:43.804 INFO <unknown>:1108: [region 222909] 3785398 [logterm: 121, index: 15321, vote: 0] cast MsgRequestVote for 4306391 [logterm: 121, index: 15321] at term 122
2019/11/15 11:00:43.828 INFO apply.rs:902: [region 3137789] 3922331 execute admin command cmd_type: CompactLog compact_log {compact_index: 4568678 compact_term: 24} at [term: 24, index: 4568681]
2019/11/15 11:00:43.862 INFO apply.rs:902: [region 375517] 3254538 execute admin command cmd_type: ChangePeer change_peer {change_type: RemoveNode peer {id: 1662079 store_id: 4}} at [term: 89, index: 115]
2019/11/15 11:00:43.862 INFO apply.rs:951: [region 375517] 3254538 exec ConfChange "RemoveNode", epoch: conf_ver: 31 version: 36309
2019/11/15 11:00:43.862 INFO apply.rs:1045: [region 375517] 3254538 remove 1662079 from region:id: 375517 start_key: "t200\000\000\000\000\003356377\007_r200\000\000\000\017377225375237\000\000\000\000\000372" end_key: "t200\000\000\000\000\003356377\007_r200\000\000\000\0203775|d\000\000\000\000\000372" region_epoch {conf_ver: 31 version: 36309} peers {id: 1662079 store_id: 4} peers {id: 2944023 store_id: 5} peers {id: 3254538 store_id: 40549} peers {id: 4309068 store_id: 816585}
2019/11/15 11:00:44.142 INFO apply.rs:902: [region 541469] 4297053 execute admin command cmd_type: CompactLog compact_log {compact_index: 2061 compact_term: 1816} at [term: 1817, index: 2063]
2019/11/15 11:00:44.147 INFO peer.rs:430: [region 1369956] raft message MsgAppendResponse is stale, current conf_ver: 218 version: 62289, ignore it
2019/11/15 11:00:44.171 INFO apply.rs:902: [region 3132843] 4282313 execute admin command cmd_type: CompactLog compact_log {compact_index: 5197777 compact_term: 167} at [term: 167, index: 5197780]
脚本输出
系统信息
+-------------------------+---------------------------+
| Host | Release |
+-------------------------+---------------------------+
| iZbp1gw4cdwckg9a3gfv6uZ | 3.10.0-693.2.2.el7.x86_64 |
| tikv4 | 3.10.0-693.2.2.el7.x86_64 |
| tikv5 | 3.10.0-693.2.2.el7.x86_64 |
| tikv1 | 3.10.0-693.2.2.el7.x86_64 |
| tikv2 | 3.10.0-693.2.2.el7.x86_64 |
| tikv3 | 3.10.0-693.2.2.el7.x86_64 |
| tipd1 | 3.10.0-693.2.2.el7.x86_64 |
| tipd2 | 3.10.0-693.2.2.el7.x86_64 |
| tipd3 | 3.10.0-693.2.2.el7.x86_64 |
| tidb1 | 3.10.0-693.2.2.el7.x86_64 |
| tidb2 | 3.10.0-693.2.2.el7.x86_64 |
| tidb-grafana | 3.10.0-693.2.2.el7.x86_64 |
+-------------------------+---------------------------+
TiDB 集群信息
+--------------------+--------------+------+----+------+
| TiDB_version | Clu_replicas | TiDB | PD | TiKV |
+--------------------+--------------+------+----+------+
| 5.7.25-TiDB-v2.1.9 | 3 | 3 | 3 | 5 |
+--------------------+--------------+------+----+------+
集群节点信息
+-------------+-------------+
| Node_IP | Server_info |
+-------------+-------------+
| instance_0 | tidb |
| instance_1 | tidb |
| instance_2 | tikv |
| instance_3 | tikv |
| instance_4 | tikv |
| instance_5 | tikv |
| instance_6 | pd |
| instance_7 | tidb |
| instance_8 | pd |
| instance_9 | tikv |
| instance_10 | pd |
+-------------+-------------+
容量 & region 数量
+---------------------+-----------------+--------------+
| Storage_capacity_GB | Storage_uesd_GB | Region_count |
+---------------------+-----------------+--------------+
| 8799.05 | 806.78 | 868464 |
+---------------------+-----------------+--------------+
QPS
+---------+----------------+-----------------+
| Clu_QPS | Duration_99_MS | Duration_999_MS |
+---------+----------------+-----------------+
| 379.29 | 1748.92 | 3925.20 |
+---------+----------------+-----------------+
热点 region 信息
+--------------------+----------+-----------+
| Store | Hot_read | Hot_write |
+--------------------+----------+-----------+
| store-store_40549 | 0 | 2 |
| store-store_817018 | 0 | 3 |
| store-store_5 | 0 | 2 |
| store-store_4 | 1 | 3 |
| store-store_1 | 0 | 0 |
| store-store_816585 | 0 | 2 |
+--------------------+----------+-----------+
磁盘延迟信息
+--------+----------+-------------+--------------+
| Device | Instance | Read_lat_MS | Write_lat_MS |
+--------+----------+-------------+--------------+
+--------+----------+-------------+--------------+
1 个赞
需要看 tidb 的 grafana 监控，重点看一下 tikv 分组中每个组件 CPU 的使用情况
raft store cpu 使用率较高，可能是 region 数量太多引起的，目前每个 tikv 上有多少 region？ 另外看一下 Propose wait duration，这个监控项在 TiKV 监控页面的 Raft Propose 组中。
已经重新编辑啦 上周tikv加了一台机器，原本是5台的
TiDB 3.0 的多线程 raftstore 机制可以显著增加 raft store 处理能力的上线，目前最新的稳定版本是 3.0.5，可以考虑升级。
好的 谢谢 我会试试的
不过性能瓶颈的主因是raft的等待时间么
不确定，需要提供我上面提到的更多信息。
信息有点多哦 主要需要哪些信息哦 你上面提到的，我已经提供了呀
raft store cpu 使用率较高，可能是 region 数量太多引起的，目前每个 tikv 上有多少 region？ 另外看一下 Propose wait duration，这个监控项在 TiKV 监控页面的 Raft Propose 组中。
确认是由于单 tikv 上的 region 过多造成的，可以看到每个 tikv-server 上有 15 万个 region，Propose wait duration 过高（.99 一般低于 100ms），raft store cpu 达到瓶颈（单线程时约 80~85%），可以通过以下手段优化：
- 将集群升级到 3.0 版本
- 扩容 tikv
好的 谢谢
此话题已在最后回复的 1 分钟后被自动关闭。不再允许新回复。