两地三中心的性能问题

TiDB → KV Request Duration 99 by store 表示依据 tikv store 分类统计 99% 的 KV 请求执行时间小于该值(就是 tidb 发消息给 tikv 得到反馈的时间,按 message type 分类)
TiKV-Details → 99% gRPC message duration 表示 99% 的 gRPC 请求的执行时间小于该值(就是 tikv 接收到信息处理完成到返回的给 tidb 的时间消耗,按 message type 分类)
二者差值,可以看出在 网络上浪费的多少时间。


另外,blackbox_exporter 可以看网络延时情况;

可以反馈下以上信息

2 个赞

test

另外我们发现有一定的概率 一些非常简单的sql 要执行很长时间 例如20多S,重新执行 无法复现这个时长

看你禁用了异地的raft leader,剩下的同城两中心leader分布怎么样,我觉得有可能是同城两中心之间的网络存在延迟。
再就是同一个SQL不稳定,这个SQL是否执行计划发生了改变。。。个人想法

还是网络问题
tidb duration 999线平均30秒了,tidb发送的Kv请求处理时间要几秒-几十秒,而tikv处理rpc请求时间在毫秒级,说明时间主要是发生在tidb和tikv间的网络上,store-5782656比其他4个tikv要更严重些。可以试试1、从tidb server 用大包长ping 另一机房的tikv。 2. 把store-5782656 scale-in缩容后(注意要等到tombstone状态后prune),看看整体延迟是否有所降低。



kv request 99 by store 不是说明 tikv自己慢吗?

另外 排名前三的 store都是异地机房的,另外最好把图片的IP 模糊下

kv request 99 by store,是从tidb侧看的,从tudb发出请求到处理完成返回,中间有网络和tikv处理时间

99%grpc 时间是 tikv的内部时间?

还有就是那个,执行计划并没有改变, 很简单的sql 偶发 慢的情况

image
时间在锁上

  1. 秒级 和 毫秒 级的 Max 99 线对比,可以证明网络问题导致。


  2. 加锁过程中,4 次 rpc 交互总时间 26.9s(这个 rpc 是并发的,与 query time 不是全包含关系),该指标异常,极可能同样受网络影响

这种读的sql 也是 99% 很快 就有一定概率 超时 20多秒

同城裸光纤这个网络延迟有点高,50km 以内 ping 一般在 1ms 左右。另外看 reject-leader 的配置是 shunyi 顺义机房吗?应该 reject 沈阳机房的 leader吧。下面是某银行两地三中心的实践经验,供参考。

tikv 配置:
server:
grpc-raft-conn-num: 16
grpc-compression-type: gzip
grpc-keepalive-time: 120s
grpc-keepalive-timeout: 120s
concurrent-send-snap-limit: 64
concurrent-recv-snap-limit: 64

pd 配置:
member leader_priority pd1 2(北京)
member leader_priority pd2 2(北京)
member leader_priority pd3 1(沈阳)
config set label-property reject-leader dc shenyang
config set tolerant-size-ratio 50.0

沈阳 tikv 需要增加额外配置,禁止发起选举:
raftstore:
raft-min-election-timeout-ticks: 1000 (异地 TiKV 附加配置)
raft-max-election-timeout-ticks: 1020 (异地 TiKV 附加配置)

感谢,我们对比下 ,是将 reject-leader配置的沈阳。 我们ping值在2-3ms

同时这个黑河监控有毛刺 ping值的 这种是否很严重?

针对这条 SQL 的执行计划可以 copy 上来了?方便看

id                         	task     	estRows	operator info                                                                                                                                                                                                                          	actRows	execution info                                                                                                                                                                                                                                                                                                                             	memory   	disk
StreamAgg_15               	root     	1      	funcs:count(1)->Column#52                                                                                                                                                                                                              	1      	time:24.3s, loops:2                                                                                                                                                                                                                                                                                                                        	8 Bytes  	N/A
└─IndexJoin_61             	root     	1.77   	inner join, inner:TableReader_57, outer key:lenovo_sc_db_org.tbl_auth_roleuser.roleid, inner key:lenovo_sc_db_org.tbl_auth_role.id, equal cond:eq(lenovo_sc_db_org.tbl_auth_roleuser.roleid, lenovo_sc_db_org.tbl_auth_role.id)        	0      	time:24.3s, loops:1, inner:{total:1.51ms, concurrency:5, task:1, construct:18.7µs, fetch:1.49ms, build:87ns}, probe:4.31µs                                                                                                                                                                                                               	750 Bytes	N/A
  ├─IndexHashJoin_35       	root     	1.77   	inner join, inner:IndexLookUp_32, outer key:lenovo_sc_db_org.tbl_auth_user.userid, inner key:lenovo_sc_db_org.tbl_auth_roleuser.userid, equal cond:eq(lenovo_sc_db_org.tbl_auth_user.userid, lenovo_sc_db_org.tbl_auth_roleuser.userid)	11     	time:24.3s, loops:3, inner:{total:24.3s, concurrency:5, task:1, construct:14.7µs, fetch:24.3s, build:3.17µs, join:13.2µs}                                                                                                                                                                                                               	49.3 KB  	N/A
  │ ├─Point_Get_45         	root     	1      	table:tbl_auth_user, index:unique_userCode(userCode)                                                                                                                                                                                   	1      	time:16.9ms, loops:3, Get:{num_rpc:2, total_time:16.8ms}, scan_detail: {total_process_keys: 2, total_keys: 2, rocksdb: {delete_skipped_count: 0, key_skipped_count: 0, block: {cache_hit_count: 10, read_count: 0, read_byte: 0 Bytes}}}                                                                                                   	N/A      	N/A
  │ └─IndexLookUp_32       	root     	1.77   	                                                                                                                                                                                                                                       	11     	time:24.3s, loops:2, index_task: {total_time: 15.9s, fetch_handle: 15.9s, build: 5.73µs, wait: 2.1µs}, table_task: {total_time: 1m28s, num: 1, concurrency: 5}                                                                                                                                                                           	9.26 KB  	N/A
  │   ├─IndexRangeScan_29  	cop[tikv]	3.37   	table:t0, index:index_userID_roleId(userId, roleId), range: decided by [eq(lenovo_sc_db_org.tbl_auth_roleuser.userid, lenovo_sc_db_org.tbl_auth_user.userid)], keep order:false                                                        	11     	time:15.9s, loops:3, cop_task: {num: 1, max: 15.9s, proc_keys: 11, rpc_num: 1, rpc_time: 15.9s, copr_cache_hit_ratio: 0.00}, tikv_task:{time:0s, loops:1}, scan_detail: {total_process_keys: 11, total_keys: 12, rocksdb: {delete_skipped_count: 0, key_skipped_count: 11, block: {cache_hit_count: 6, read_count: 0, read_byte: 0 Bytes}}}	N/A      	N/A
  │   └─Selection_31       	cop[tikv]	1.77   	eq(1, lenovo_sc_db_org.tbl_auth_roleuser.roleuserstatus)                                                                                                                                                                               	11     	time:8.31s, loops:2, cop_task: {num: 1, max: 8.31s, proc_keys: 11, rpc_num: 1, rpc_time: 8.31s, copr_cache_hit_ratio: 0.00}, tikv_task:{time:0s, loops:1}, scan_detail: {total_process_keys: 11, total_keys: 12, rocksdb: {delete_skipped_count: 0, key_skipped_count: 3, block: {cache_hit_count: 45, read_count: 0, read_byte: 0 Bytes}}}	N/A      	N/A
  │     └─TableRowIDScan_30	cop[tikv]	3.37   	table:t0, keep order:false                                                                                                                                                                                                             	11     	tikv_task:{time:0s, loops:1}                                                                                                                                                                                                                                                                                                               	N/A      	N/A
  └─TableReader_57         	root     	0.01   	data:Selection_56                                                                                                                                                                                                                      	0      	time:1.42ms, loops:1, cop_task: {num: 1, max: 1.29ms, proc_keys: 11, tot_proc: 1ms, rpc_num: 1, rpc_time: 1.27ms, copr_cache_hit_ratio: 0.00}                                                                                                                                                                                              	N/A      	N/A
    └─Selection_56         	cop[tikv]	0.01   	eq(lenovo_sc_db_org.tbl_auth_role.roletype, 1), eq(lenovo_sc_db_org.tbl_auth_role.status, 1)                                                                                                                                           	0      	tikv_task:{time:1ms, loops:1}, scan_detail: {total_process_keys: 11, total_keys: 12, rocksdb: {delete_skipped_count: 0, key_skipped_count: 2, block: {cache_hit_count: 39, read_count: 0, read_byte: 0 Bytes}}}                                                                                                                            	N/A      	N/A
      └─TableRangeScan_55  	cop[tikv]	1      	table:t1, range: decided by [lenovo_sc_db_org.tbl_auth_roleuser.roleid], keep order:false                                                                                                                                              	11     	tikv_task:{time:1ms, loops:1}                                                                                                                                                                                                                                                                                                              	N/A      	N/A

非常简单一个sql 数据量也不大,走了索引 我根本无法复现出 20多S的情况

算子虽然推到 tikv 执行了,但是在 RPC 上就花费了 15.9s 返回查出来的 row id 结果给 TiDB;
又花了 8.31s tidb 发送消息给 tikv 通过 row id 查具体数据。

又因为 RPC 再对应算子上只发生了 1 次,所以这里的时间刚好表示这次 RPC 的时间(忽略并发的影响);

总结还是网络抖导致,而不是真正的某一块处理有问题(tikv_task 很快)。

感谢感谢 我先按照上面的gzip 修改下参数 优化下看看 另外这个SQL的执行计划您也帮忙分析下

id                     	task     	estRows	operator info                                                                                                                            	actRows	execution info                                                                                                                                                                                                                                                                                                                                                   	memory 	disk
StreamAgg_10           	root     	1      	funcs:count(1)->Column#21                                                                                                                	0      	time:30.1s, loops:1                                                                                                                                                                                                                                                                                                                                              	1.35 KB	N/A
└─IndexLookUp_37       	root     	3.72   	                                                                                                                                         	0      	time:30.1s, loops:1, index_task: {total_time: 2.54ms, fetch_handle: 2.54ms, build: 1.08µs, wait: 1.84µs}, table_task: {total_time: 30.1s, num: 1, concurrency: 5}                                                                                                                                                                                              	8 KB   	N/A
  ├─IndexRangeScan_34  	cop[tikv]	249.65 	table:q, index:INX_QueueMainInfo_StationCode(StationCode), range:["35003805","35003805"], keep order:false                               	275    	time:2.52ms, loops:3, cop_task: {num: 1, max: 2.44ms, proc_keys: 275, rpc_num: 1, rpc_time: 2.43ms, copr_cache_hit_ratio: 0.00}, tikv_task:{time:0s, loops:4}, scan_detail: {total_process_keys: 275, total_keys: 276, rocksdb: {delete_skipped_count: 0, key_skipped_count: 275, block: {cache_hit_count: 9, read_count: 0, read_byte: 0 Bytes}}}               	N/A    	N/A
  └─Selection_36       	cop[tikv]	3.72   	eq(cast(lenovo_sc_db_esd.queuemaininfo.queuestatus, var_string(11)), "30"), ge(lenovo_sc_db_esd.queuemaininfo.queuestarttime, 2022-04-26)	0      	time:30.1s, loops:1, cop_task: {num: 1, max: 5.48ms, proc_keys: 187, tot_proc: 2ms, rpc_num: 1, rpc_time: 5.46ms, copr_cache_hit_ratio: 0.00}, tikv_task:{time:2ms, loops:3}, scan_detail: {total_process_keys: 187, total_keys: 187, rocksdb: {delete_skipped_count: 0, key_skipped_count: 0, block: {cache_hit_count: 924, read_count: 0, read_byte: 0 Bytes}}}	N/A    	N/A
    └─TableRowIDScan_35	cop[tikv]	249.65 	table:q, keep order:false                                                                                                                	187    	tikv_task:{time:2ms, loops:3}                                                                                                                                                                                                                                                                                                                                    	N/A    	N/A

看上去前两条是同城主机之间 ping,如果这种 4-5s 的抖动很频繁的话,说明网络质量有比严重的问题,从我们客户报告的问题来看,这种抖动在一个集群里面一年见到一次算是比较多的了。

1 个赞

感谢各位,目前看确实是网络的可能的问题,我们去排查下

同时这个参数我们没设置

grpc-raft-conn-num: 16
grpc-compression-type: gzip

会考虑设置下。 完成后给大家反馈结果

1 个赞


这个时间点的 coprocessor cpu 消耗怎么样?