【 TiDB 使用环境】生产环境 /测试/ Poc
【 TiDB 版本】6.5
【遇到的问题】tidb集群不知明原因挂掉
【复现路径】无操作
【问题现象及影响】
集群宕机后无法正常拉起，pd单独启动正常，tikv单独启动正常，过一段时间又整体down掉
pd日志：
[2023/06/15 15:24:39.106 +08:00] [WARN] [v3_server.go:830] [“timed out waiting for read index response (local node might have slow network)”] [timeout=11s]
[2023/06/15 15:24:39.149 +08:00] [WARN] [etcd_kv.go:160] [“txn runs too slow”] [response=null] [cost=10.00018136s] [error=“context deadline exceeded”]
[2023/06/15 15:24:39.149 +08:00] [WARN] [allocator_manager.go:629] [“failed to update allocator’s timestamp”] [dc-location=global] [error=“[PD:etcd:ErrEtcdKVPut]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:39.149 +08:00] [INFO] [tso.go:416] [“reset the timestamp in memory”]
[2023/06/15 15:24:39.149 +08:00] [INFO] [lease.go:159] [“stop lease keep alive worker”] [purpose=“pd leader election”]
[2023/06/15 15:24:39.188 +08:00] [INFO] [server.go:1522] [“no longer a leader because lease has expired, pd leader will step down”]
[2023/06/15 15:24:39.606 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:39.707 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=2.00025902s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/topology/tidb/" range_end:"/topology/tidb0" “] [response=] [error=“context canceled”]
[2023/06/15 15:24:39.707 +08:00] [INFO] [trace.go:152] [“trace[553154447] range”] [detail=”{range_begin:/topology/tidb/; range_end:/topology/tidb0; }”] [duration=2.000356001s] [start=2023/06/15 15:24:37.706 +08:00] [end=2023/06/15 15:24:39.707 +08:00] [steps=”["trace[553154447] ‘agreement among raft nodes before linearized reading’ (duration: 2.000274096s)"]”]
[2023/06/15 15:24:40.107 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:40.607 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:40.982 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=5.000155428s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/tidb/store/gcworker/saved_safe_point" “] [response=] [error=“context canceled”]
[2023/06/15 15:24:40.982 +08:00] [INFO] [trace.go:152] [“trace[1517060739] range”] [detail=”{range_begin:/tidb/store/gcworker/saved_safe_point; range_end:; }”] [duration=5.000265051s] [start=2023/06/15 15:24:35.981 +08:00] [end=2023/06/15 15:24:40.982 +08:00] [steps=”["trace[1517060739] ‘agreement among raft nodes before linearized reading’ (duration: 5.000170095s)"]”]
[2023/06/15 15:24:41.108 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:41.609 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:42.110 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:42.611 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:42.711 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=10.000255023s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/scheduler_config/" range_end:"/pd/7204350633511442718/scheduler_config0" limit:1000 “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:42.711 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/scheduler_config/] [cost=10.000457391s] [error=“context deadline exceeded”]
[2023/06/15 15:24:42.711 +08:00] [INFO] [trace.go:152] [“trace[1357921245] range”] [detail=”{range_begin:/pd/7204350633511442718/scheduler_config/; range_end:/pd/7204350633511442718/scheduler_config0; }”] [duration=10.000356053s] [start=2023/06/15 15:24:32.710 +08:00] [end=2023/06/15 15:24:42.711 +08:00] [steps=”["trace[1357921245] ‘agreement among raft nodes before linearized reading’ (duration: 10.000267673s)"]”]
[2023/06/15 15:24:42.711 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/scheduler_config/] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:43.111 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:43.612 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:46.115 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:46.148 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=10.000001343s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=10.000079733s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.00022946s] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [INFO] [trace.go:152] [“trace[1654063221] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=10.000089974s] [start=2023/06/15 15:24:36.148 +08:00] [end=2023/06/15 15:24:46.148 +08:00] [steps=”["trace[1654063221] ‘agreement among raft nodes before linearized reading’ (duration: 10.000008688s)"]”]
[2023/06/15 15:24:46.148 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000311315s] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=”[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=”[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [INFO] [trace.go:152] [“trace[120052108] range”] [detail=“{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=10.00015238s] [start=2023/06/15 15:24:36.148 +08:00] [end=2023/06/15 15:24:46.148 +08:00] [steps=“["trace[120052108] ‘agreement among raft nodes before linearized reading’ (duration: 10.000093416s)"]”]
[2023/06/15 15:24:46.148 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000032107s] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000096773s] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.999966894s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context canceled”]
[2023/06/15 15:24:46.148 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000055744s] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [INFO] [trace.go:152] [“trace[1371381750] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=9.999999936s] [start=2023/06/15 15:24:36.148 +08:00] [end=2023/06/15 15:24:46.148 +08:00] [steps=”["trace[1371381750] ‘agreement among raft nodes before linearized reading’ (duration: 9.999972719s)"]”]
[2023/06/15 15:24:46.148 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:46.148 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.999983087s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context canceled”]
[2023/06/15 15:24:46.148 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.999982091s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context canceled”]
[2023/06/15 15:24:46.148 +08:00] [INFO] [trace.go:152] [“trace[706522399] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=10.000011961s] [start=2023/06/15 15:24:36.148 +08:00] [end=2023/06/15 15:24:46.148 +08:00] [steps=”["trace[706522399] ‘agreement among raft nodes before linearized reading’ (duration: 9.999989085s)"]”]
[2023/06/15 15:24:46.148 +08:00] [INFO] [trace.go:152] [“trace[567413646] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=10.000082512s] [start=2023/06/15 15:24:36.148 +08:00] [end=2023/06/15 15:24:46.148 +08:00] [steps=”["trace[567413646] ‘agreement among raft nodes before linearized reading’ (duration: 9.99999037s)"]”]
[2023/06/15 15:24:46.149 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000056983s] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.149 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:46.149 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.999967982s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context canceled”]
[2023/06/15 15:24:46.149 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000108241s] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.149 +08:00] [INFO] [trace.go:152] [“trace[1217563820] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=10.000006522s] [start=2023/06/15 15:24:36.149 +08:00] [end=2023/06/15 15:24:46.149 +08:00] [steps=”["trace[1217563820] ‘agreement among raft nodes before linearized reading’ (duration: 9.999975239s)"]”]
[2023/06/15 15:24:46.149 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.999984831s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context canceled”]
[2023/06/15 15:24:46.149 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=”[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:46.149 +08:00] [INFO] [trace.go:152] [“trace[476717548] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=10.000027198s] [start=2023/06/15 15:24:36.149 +08:00] [end=2023/06/15 15:24:46.149 +08:00] [steps=“["trace[476717548] ‘agreement among raft nodes before linearized reading’ (duration: 9.999989603s)"]”]
[2023/06/15 15:24:46.150 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=10.000690761s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.150 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000956417s] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.150 +08:00] [INFO] [trace.go:152] [“trace[336632226] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=10.000719941s] [start=2023/06/15 15:24:36.149 +08:00] [end=2023/06/15 15:24:46.150 +08:00] [steps=”["trace[336632226] ‘agreement among raft nodes before linearized reading’ (duration: 10.000699627s)"]”]
[2023/06/15 15:24:46.150 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=10.000813366s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.150 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=”[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:46.150 +08:00] [INFO] [trace.go:152] [“trace[1342164580] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=10.000839452s] [start=2023/06/15 15:24:36.149 +08:00] [end=2023/06/15 15:24:46.150 +08:00] [steps=“["trace[1342164580] ‘agreement among raft nodes before linearized reading’ (duration: 10.00081812s)"]”]
[2023/06/15 15:24:46.150 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=10.000741859s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.150 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=10.000870302s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.150 +08:00] [INFO] [trace.go:152] [“trace[1505674019] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=10.00076422s] [start=2023/06/15 15:24:36.149 +08:00] [end=2023/06/15 15:24:46.150 +08:00] [steps=”["trace[1505674019] ‘agreement among raft nodes before linearized reading’ (duration: 10.000740936s)"]”]
[2023/06/15 15:24:46.150 +08:00] [INFO] [trace.go:152] [“trace[2074130296] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=10.000888702s] [start=2023/06/15 15:24:36.149 +08:00] [end=2023/06/15 15:24:46.150 +08:00] [steps=”["trace[2074130296] ‘agreement among raft nodes before linearized reading’ (duration: 10.000878315s)"]”]
[2023/06/15 15:24:46.150 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000880418s] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.150 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.001018118s] [error=“context deadline exceeded”]
[2023/06/15 15:24:46.150 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000926763s] [error=“rpc error: code = Unknown desc = context deadline exceeded”]
[2023/06/15 15:24:46.150 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:46.150 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:46.150 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]rpc error: code = Unknown desc = context deadline exceeded: rpc error: code = Unknown desc = context deadline exceeded”]
[2023/06/15 15:24:46.616 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:47.117 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025282] [retry-timeout=500ms]
[2023/06/15 15:24:47.482 +08:00] [WARN] [wal.go:808] [“slow fdatasync”] [took=19.910723848s] [expected-duration=1s]
[2023/06/15 15:24:47.482 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.332789504s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“etcdserver: leader changed”]
[2023/06/15 15:24:47.482 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.333479682s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“etcdserver: leader changed”]
[2023/06/15 15:24:47.482 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.333151403s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“etcdserver: leader changed”]
[2023/06/15 15:24:47.482 +08:00] [INFO] [trace.go:152] [“trace[1150520820] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=9.332861249s] [start=2023/06/15 15:24:38.149 +08:00] [end=2023/06/15 15:24:47.482 +08:00] [steps=”["trace[1150520820] ‘agreement among raft nodes before linearized reading’ (duration: 9.332794698s)"]”]
[2023/06/15 15:24:47.482 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.332614393s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“etcdserver: leader changed”]
[2023/06/15 15:24:47.482 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.332505014s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“etcdserver: leader changed”]
[2023/06/15 15:24:47.482 +08:00] [INFO] [trace.go:152] [“trace[705463792] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=9.332738259s] [start=2023/06/15 15:24:38.150 +08:00] [end=2023/06/15 15:24:47.482 +08:00] [steps=”["trace[705463792] ‘agreement among raft nodes before linearized reading’ (duration: 9.332619041s)"]”]
[2023/06/15 15:24:47.482 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.332491214s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“etcdserver: leader changed”]
[2023/06/15 15:24:47.482 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.332580469s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“etcdserver: leader changed”]
[2023/06/15 15:24:47.482 +08:00] [INFO] [trace.go:152] [“trace[1478541918] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=9.332713967s] [start=2023/06/15 15:24:38.150 +08:00] [end=2023/06/15 15:24:47.482 +08:00] [steps=”["trace[1478541918] ‘agreement among raft nodes before linearized reading’ (duration: 9.332588629s)"]”]
…
[2023/06/15 15:24:47.482 +08:00] [INFO] [trace.go:152] [“trace[1408123276] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=9.333207102s] [start=2023/06/15 15:24:38.149 +08:00] [end=2023/06/15 15:24:47.482 +08:00] [steps=”["trace[1408123276] ‘agreement among raft nodes before linearized reading’ (duration: 9.333158772s)"]”]
[2023/06/15 15:24:47.483 +08:00] [INFO] [trace.go:152] [“trace[1274984949] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=9.334298081s] [start=2023/06/15 15:24:38.148 +08:00] [end=2023/06/15 15:24:47.483 +08:00] [steps=”["trace[1274984949] ‘agreement among raft nodes before linearized reading’ (duration: 9.334029535s)"]”]
[2023/06/15 15:24:47.483 +08:00] [INFO] [trace.go:152] [“trace[1911885162] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=9.333533098s] [start=2023/06/15 15:24:38.149 +08:00] [end=2023/06/15 15:24:47.483 +08:00] [steps=”["trace[1911885162] ‘agreement among raft nodes before linearized reading’ (duration: 9.333239032s)"]”]
[2023/06/15 15:24:47.575 +08:00] [WARN] [etcd_kv.go:160] [“txn runs too slow”] [response=null] [cost=10.000837723s] [error=“context deadline exceeded”]
[2023/06/15 15:24:47.575 +08:00] [ERROR] [etcd_kv.go:97] [“save to etcd meet error”] [key=/pd/7204350633511442718/raft/s/00000000000000000002] [value=”\u0008\u0002\u0012\u000ctidb01:20161"\n\n\u0004zone\u0012\u0002z1"\n\n\u0004rack\u0012\u0002r1"\u000e\n\u0004host\u0012\u0006tidb01"\u0008\n\u0002dc\u0012\u0002d1*\u00056.5.02\u000ctidb01:20161:\u000ctidb01:20181B(47b81680f75adc4b7200480cea5dbe46ae07c4b5H䭪\ufffd\u0006R$/u01/tidb/tidb-deploy/tikv-20161/binX\ufffd\ufffd\ufffd\ufffd戱\ufffd\u0017h\u0001”] [error=”[PD:etcd:ErrEtcdKVPut]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:47.982 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025287] [retry-timeout=500ms]
[2023/06/15 15:24:48.149 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=640.995578ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.149 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000561262s] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.149 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=638.318933ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.149 +08:00] [INFO] [trace.go:152] [“trace[1514218598] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=641.083825ms] [start=2023/06/15 15:24:47.508 +08:00] [end=2023/06/15 15:24:48.149 +08:00] [steps=”["trace[1514218598] ‘agreement among raft nodes before linearized reading’ (duration: 641.000705ms)"]”]
[2023/06/15 15:24:48.149 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.001167201s] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.149 +08:00] [INFO] [trace.go:152] [“trace[1697245881] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=638.360495ms] [start=2023/06/15 15:24:47.511 +08:00] [end=2023/06/15 15:24:48.149 +08:00] [steps=”["trace[1697245881] ‘agreement among raft nodes before linearized reading’ (duration: 638.316626ms)"]”]
[2023/06/15 15:24:48.149 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:48.149 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000371184s] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.149 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:48.149 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=642.140459ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.149 +08:00] [INFO] [trace.go:152] [“trace[688509788] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=642.434808ms] [start=2023/06/15 15:24:47.507 +08:00] [end=2023/06/15 15:24:48.149 +08:00] [steps=”["trace[688509788] ‘agreement among raft nodes before linearized reading’ (duration: 642.149705ms)"]”]
[2023/06/15 15:24:48.149 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=639.446706ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.149 +08:00] [INFO] [trace.go:152] [“trace[446894989] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=639.743033ms] [start=2023/06/15 15:24:47.510 +08:00] [end=2023/06/15 15:24:48.149 +08:00] [steps=”["trace[446894989] ‘agreement among raft nodes before linearized reading’ (duration: 639.4578ms)"]”]
[2023/06/15 15:24:48.149 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:48.149 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000271695s] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.149 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=642.52216ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000048627s] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [INFO] [trace.go:152] [“trace[165146757] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=642.57019ms] [start=2023/06/15 15:24:47.507 +08:00] [end=2023/06/15 15:24:48.150 +08:00] [steps=”["trace[165146757] ‘agreement among raft nodes before linearized reading’ (duration: 642.533629ms)"]”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000213749s] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000021909s] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=641.372279ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context canceled”]
[2023/06/15 15:24:48.150 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=”[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000052644s] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [INFO] [trace.go:152] [“trace[1444027040] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=641.416365ms] [start=2023/06/15 15:24:47.508 +08:00] [end=2023/06/15 15:24:48.150 +08:00] [steps=“["trace[1444027040] ‘agreement among raft nodes before linearized reading’ (duration: 641.384192ms)"]”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=644.292024ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context canceled”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=639.930022ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context canceled”]
[2023/06/15 15:24:48.150 +08:00] [INFO] [trace.go:152] [“trace[23718976] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=644.357014ms] [start=2023/06/15 15:24:47.505 +08:00] [end=2023/06/15 15:24:48.150 +08:00] [steps=”["trace[23718976] ‘agreement among raft nodes before linearized reading’ (duration: 644.31623ms)"]”]
[2023/06/15 15:24:48.150 +08:00] [INFO] [trace.go:152] [“trace[2073527866] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=639.955641ms] [start=2023/06/15 15:24:47.510 +08:00] [end=2023/06/15 15:24:48.150 +08:00] [steps=”["trace[2073527866] ‘agreement among raft nodes before linearized reading’ (duration: 639.938928ms)"]”]
[2023/06/15 15:24:48.150 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000053627s] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=640.049567ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [INFO] [trace.go:152] [“trace[623046662] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=640.077193ms] [start=2023/06/15 15:24:47.510 +08:00] [end=2023/06/15 15:24:48.150 +08:00] [steps=”["trace[623046662] ‘agreement among raft nodes before linearized reading’ (duration: 640.055802ms)"]”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000072542s] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=641.555751ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context canceled”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/gc/safe_point] [cost=10.000061048s] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=641.591616ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/gc/safe_point" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [INFO] [trace.go:152] [“trace[1246120792] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=641.597357ms] [start=2023/06/15 15:24:47.508 +08:00] [end=2023/06/15 15:24:48.150 +08:00] [steps=”["trace[1246120792] ‘agreement among raft nodes before linearized reading’ (duration: 641.568299ms)"]”]
[2023/06/15 15:24:48.150 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/gc/safe_point] [error=”[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:48.150 +08:00] [INFO] [trace.go:152] [“trace[9366884] range”] [detail=”{range_begin:/pd/7204350633511442718/gc/safe_point; range_end:; }”] [duration=641.616243ms] [start=2023/06/15 15:24:47.508 +08:00] [end=2023/06/15 15:24:48.150 +08:00] [steps=“["trace[9366884] ‘agreement among raft nodes before linearized reading’ (duration: 641.602537ms)"]”]
[2023/06/15 15:24:48.483 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025287] [retry-timeout=500ms]
[2023/06/15 15:24:48.984 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025287] [retry-timeout=500ms]
[2023/06/15 15:24:49.429 +08:00] [INFO] [raft.go:850] [“3383c2841e1cbd55 [logterm: 205, index: 148334949, vote: 0] ignored MsgPreVote from 2430cbde1e343d8e [logterm: 205, index: 148335834] at term 205: lease is not expired (remaining ticks: 1)”]
[2023/06/15 15:24:49.484 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025287] [retry-timeout=500ms]
[2023/06/15 15:24:49.849 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/config] [cost=10.000142284s] [error=“context deadline exceeded”]
[2023/06/15 15:24:49.849 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=9.999920911s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/config" “] [response=] [error=“context deadline exceeded”]
[2023/06/15 15:24:49.849 +08:00] [INFO] [trace.go:152] [“trace[1443434619] range”] [detail=”{range_begin:/pd/7204350633511442718/config; range_end:; }”] [duration=10.000048273s] [start=2023/06/15 15:24:39.849 +08:00] [end=2023/06/15 15:24:49.849 +08:00] [steps=”["trace[1443434619] ‘agreement among raft nodes before linearized reading’ (duration: 9.999917207s)"]”]
[2023/06/15 15:24:49.849 +08:00] [ERROR] [etcdutil.go:126] [“load from etcd meet error”] [key=/pd/7204350633511442718/config] [error=“[PD:etcd:ErrEtcdKVGet]context deadline exceeded: context deadline exceeded”]
[2023/06/15 15:24:49.849 +08:00] [WARN] [manager.go:101] [“failed to reload persist options”]
[2023/06/15 15:24:49.903 +08:00] [INFO] [v3_server.go:802] [“first commit in current term: resending ReadIndex request”]
[2023/06/15 15:24:49.904 +08:00] [WARN] [v3_server.go:783] [“ignored out-of-date read index response; local node read indexes queueing up and waiting to be in sync with leader”] [sent-request-id=13642960994652025287] [received-request-id=13642960994652024940]
[2023/06/15 15:24:49.972 +08:00] [INFO] [trace.go:152] [“trace[1666331653] linearizableReadLoop”] [detail=“{readStateIndex:148335834; appliedIndex:148334973; }”] [duration=2.489892924s] [start=2023/06/15 15:24:47.482 +08:00] [end=2023/06/15 15:24:49.972 +08:00] [steps=“["trace[1666331653] ‘read index received’ (duration: 2.422505022s)","trace[1666331653] ‘applied index is now lower than readState.Index’ (duration: 67.386078ms)"]”]
[2023/06/15 15:24:49.972 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=3.809156642s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/tidb/store/gcworker/saved_safe_point" “] [response=“range_response_count:1 size:81”] []
[2023/06/15 15:24:49.972 +08:00] [INFO] [trace.go:152] [“trace[1340252589] range”] [detail=”{range_begin:/tidb/store/gcworker/saved_safe_point; range_end:; response_count:1; response_revision:147612360; }”] [duration=3.809226071s] [start=2023/06/15 15:24:46.163 +08:00] [end=2023/06/15 15:24:49.972 +08:00] [steps=”["trace[1340252589] ‘agreement among raft nodes before linearized reading’ (duration: 3.809086645s)"]”]
[2023/06/15 15:24:49.972 +08:00] [WARN] [v3_server.go:783] [“ignored out-of-date read index response; local node read indexes queueing up and waiting to be in sync with leader”] [sent-request-id=13642960994652025289] [received-request-id=13642960994652025287]
[2023/06/15 15:24:49.972 +08:00] [WARN] [util.go:121] [“failed to apply request”] [took=40.384µs] [request=“header:<ID:13642960994652025283 > lease_revoke:id:3d5588bdbabe7032”] [response=size:31] [error=“lease not found”]
[2023/06/15 15:24:49.972 +08:00] [WARN] [util.go:121] [“failed to apply request”] [took=32.893µs] [request=“header:<ID:13642960994652025284 > lease_revoke:id:3d5588bdbabe7032”] [response=size:31] [error=“lease not found”]
[2023/06/15 15:24:49.972 +08:00] [WARN] [util.go:121] [“failed to apply request”] [took=32.294µs] [request=“header:<ID:13642960994652025285 > lease_revoke:id:3d5588bdbabe7032”] [response=size:31] [error=“lease not found”]
[2023/06/15 15:24:49.972 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=3.81034331s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/tidb/store/gcworker/saved_safe_point" “] [response=“range_response_count:1 size:81”] []
[2023/06/15 15:24:49.972 +08:00] [INFO] [trace.go:152] [“trace[327637538] range”] [detail=”{range_begin:/tidb/store/gcworker/saved_safe_point; range_end:; response_count:1; response_revision:147612361; }”] [duration=3.810402008s] [start=2023/06/15 15:24:46.162 +08:00] [end=2023/06/15 15:24:49.972 +08:00] [steps=”["trace[327637538] ‘agreement among raft nodes before linearized reading’ (duration: 3.810117745s)"]”]
[2023/06/15 15:24:49.973 +08:00] [WARN] [server.go:1115] [“failed to revoke lease”] [lease-id=3d5588bdbabe7032] [error=“lease not found”]
[2023/06/15 15:24:49.973 +08:00] [WARN] [etcd_kv.go:160] [“txn runs too slow”] [response=“{"header":{"cluster_id":10695899325034778091,"member_id":3712024390580092245,"revision":147612363,"raft_term":205},"succeeded":true,"responses":[{"Response":{"ResponsePut":{"header":{"revision":147612363}}}}]}”] [cost=2.397669391s] []
[2023/06/15 15:24:49.984 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=134.680574ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/config" “] [response=“range_response_count:1 size:4265”] []
[2023/06/15 15:24:49.984 +08:00] [INFO] [trace.go:152] [“trace[683187435] range”] [detail=”{range_begin:/pd/7204350633511442718/config; range_end:; response_count:1; response_revision:147612405; }”] [duration=134.772191ms] [start=2023/06/15 15:24:49.850 +08:00] [end=2023/06/15 15:24:49.984 +08:00] [steps=”["trace[683187435] ‘agreement among raft nodes before linearized reading’ (duration: 134.622169ms)"]”]
[2023/06/15 15:24:51.140 +08:00] [INFO] [trace.go:152] [“trace[1393234113] linearizableReadLoop”] [detail=“{readStateIndex:148335942; appliedIndex:148335942; }”] [duration=291.384188ms] [start=2023/06/15 15:24:50.849 +08:00] [end=2023/06/15 15:24:51.140 +08:00] [steps=“["trace[1393234113] ‘read index received’ (duration: 291.379296ms)","trace[1393234113] ‘applied index is now lower than readState.Index’ (duration: 3.89µs)"]”]
[2023/06/15 15:24:51.140 +08:00] [WARN] [etcd_kv.go:160] [“txn runs too slow”] [response=“{"header":{"cluster_id":10695899325034778091,"member_id":3712024390580092245,"revision":147612463,"raft_term":205},"succeeded":true,"responses":[{"Response":{"ResponsePut":{"header":{"revision":147612463}}}}]}”] [cost=1.039105923s] []
[2023/06/15 15:24:51.140 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=291.545487ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/config" “] [response=“range_response_count:1 size:4265”] []
[2023/06/15 15:24:51.140 +08:00] [INFO] [trace.go:152] [“trace[1598893527] range”] [detail=”{range_begin:/pd/7204350633511442718/config; range_end:; response_count:1; response_revision:147612463; }”] [duration=291.646896ms] [start=2023/06/15 15:24:50.849 +08:00] [end=2023/06/15 15:24:51.140 +08:00] [steps=”["trace[1598893527] ‘agreement among raft nodes before linearized reading’ (duration: 291.507059ms)"]”]
[2023/06/15 15:24:52.330 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=13] [error=“rpc error: code = Canceled desc = context canceled”]
[2023/06/15 15:24:52.330 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=12] [error=EOF]
[2023/06/15 15:24:52.331 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=14] [error=“rpc error: code = Canceled desc = context canceled”]
[2023/06/15 15:24:52.331 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=1] [error=EOF]
[2023/06/15 15:24:52.331 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=10] [error=“rpc error: code = Canceled desc = context canceled”]
[2023/06/15 15:24:52.331 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=15] [error=“rpc error: code = Canceled desc = context canceled”]
[2023/06/15 15:24:52.331 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=106658738] [error=“rpc error: code = Canceled desc = context canceled”]
[2023/06/15 15:24:52.331 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=106658737] [error=“rpc error: code = Canceled desc = context canceled”]
[2023/06/15 15:24:52.331 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=11] [error=EOF]
[2023/06/15 15:24:52.331 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=3] [error=EOF]
[2023/06/15 15:24:52.331 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=2] [error=EOF]
[2023/06/15 15:24:52.331 +08:00] [WARN] [heartbeat_streams.go:143] [“send keepalive message fail, store maybe disconnected”] [target-store-id=106658739] [error=EOF]
[2023/06/15 15:24:52.349 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025313] [retry-timeout=500ms]
[2023/06/15 15:24:52.850 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025313] [retry-timeout=500ms]
[2023/06/15 15:24:53.351 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025313] [retry-timeout=500ms]
[2023/06/15 15:24:53.428 +08:00] [WARN] [wal.go:808] [“slow fdatasync”] [took=1.112099444s] [expected-duration=1s]
[2023/06/15 15:24:54.797 +08:00] [WARN] [etcd_kv.go:160] [“txn runs too slow”] [response=“{"header":{"cluster_id":10695899325034778091,"member_id":3712024390580092245,"revision":147612817,"raft_term":205},"succeeded":true,"responses":[{"Response":{"ResponsePut":{"header":{"revision":147612817}}}}]}”] [cost=3.200203093s] []
[2023/06/15 15:24:54.800 +08:00] [INFO] [trace.go:152] [“trace[368761499] linearizableReadLoop”] [detail=“{readStateIndex:148336294; appliedIndex:148336078; }”] [duration=2.950959115s] [start=2023/06/15 15:24:51.849 +08:00] [end=2023/06/15 15:24:54.800 +08:00] [steps=“["trace[368761499] ‘read index received’ (duration: 1.956686344s)","trace[368761499] ‘applied index is now lower than readState.Index’ (duration: 994.271035ms)"]”]
[2023/06/15 15:24:54.800 +08:00] [WARN] [v3_server.go:783] [“ignored out-of-date read index response; local node read indexes queueing up and waiting to be in sync with leader”] [sent-request-id=13642960994652025321] [received-request-id=13642960994652025313]
[2023/06/15 15:24:54.800 +08:00] [INFO] [trace.go:152] [“trace[1411667172] put”] [detail=“{key:/topology/ng-monitoring/monitor:12020/ttl; req_size:74; response_revision:147612889; }”] [duration=1.753748812s] [start=2023/06/15 15:24:53.046 +08:00] [end=2023/06/15 15:24:54.800 +08:00] [steps=“["trace[1411667172] ‘process raft request’ (duration: 1.753677525s)"]”]
[2023/06/15 15:24:54.800 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=2.951113219s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/config" “] [response=“range_response_count:1 size:4265”] []
[2023/06/15 15:24:54.800 +08:00] [INFO] [trace.go:152] [“trace[1801619809] range”] [detail=”{range_begin:/pd/7204350633511442718/config; range_end:; response_count:1; response_revision:147612889; }”] [duration=2.951187824s] [start=2023/06/15 15:24:51.849 +08:00] [end=2023/06/15 15:24:54.800 +08:00] [steps=”["trace[1801619809] ‘agreement among raft nodes before linearized reading’ (duration: 2.951054081s)"]”]
[2023/06/15 15:24:54.800 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/config] [cost=2.951445953s] []
[2023/06/15 15:24:55.059 +08:00] [INFO] [trace.go:152] [“trace[698830815] linearizableReadLoop”] [detail=“{readStateIndex:148336374; appliedIndex:148336374; }”] [duration=258.924164ms] [start=2023/06/15 15:24:54.800 +08:00] [end=2023/06/15 15:24:55.059 +08:00] [steps=“["trace[698830815] ‘read index received’ (duration: 258.912922ms)","trace[698830815] ‘applied index is now lower than readState.Index’ (duration: 9.617µs)"]”]
[2023/06/15 15:24:55.059 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=2.972737335s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/tidb/store/gcworker/saved_safe_point" “] [response=“range_response_count:1 size:81”] []
[2023/06/15 15:24:55.059 +08:00] [INFO] [trace.go:152] [“trace[1179323797] range”] [detail=”{range_begin:/tidb/store/gcworker/saved_safe_point; range_end:; response_count:1; response_revision:147612895; }”] [duration=2.972828202s] [start=2023/06/15 15:24:52.086 +08:00] [end=2023/06/15 15:24:55.059 +08:00] [steps=”["trace[1179323797] ‘agreement among raft nodes before linearized reading’ (duration: 2.9726627s)"]”]
[2023/06/15 15:24:55.062 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=261.541143ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/config" “] [response=“range_response_count:1 size:4265”] []
[2023/06/15 15:24:55.062 +08:00] [INFO] [trace.go:152] [“trace[1869340592] range”] [detail=”{range_begin:/pd/7204350633511442718/config; range_end:; response_count:1; response_revision:147612939; }”] [duration=261.671019ms] [start=2023/06/15 15:24:54.801 +08:00] [end=2023/06/15 15:24:55.062 +08:00] [steps=”["trace[1869340592] ‘agreement among raft nodes before linearized reading’ (duration: 261.461257ms)"]”]
[2023/06/15 15:24:56.349 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025326] [retry-timeout=500ms]
[2023/06/15 15:24:56.673 +08:00] [INFO] [trace.go:152] [“trace[756515706] linearizableReadLoop”] [detail=“{readStateIndex:148336763; appliedIndex:148336765; }”] [duration=824.105743ms] [start=2023/06/15 15:24:55.849 +08:00] [end=2023/06/15 15:24:56.673 +08:00] [steps=“["trace[756515706] ‘read index received’ (duration: 824.09961ms)","trace[756515706] ‘applied index is now lower than readState.Index’ (duration: 5.081µs)"]”]
[2023/06/15 15:24:56.673 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=824.267236ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/config" “] [response=“range_response_count:1 size:4265”] []
[2023/06/15 15:24:56.673 +08:00] [INFO] [trace.go:152] [“trace[1911224217] range”] [detail=”{range_begin:/pd/7204350633511442718/config; range_end:; response_count:1; response_revision:147613286; }”] [duration=824.350866ms] [start=2023/06/15 15:24:55.849 +08:00] [end=2023/06/15 15:24:56.673 +08:00] [steps=”["trace[1911224217] ‘agreement among raft nodes before linearized reading’ (duration: 824.204117ms)"]”]
[2023/06/15 15:24:56.721 +08:00] [WARN] [v3_server.go:783] [“ignored out-of-date read index response; local node read indexes queueing up and waiting to be in sync with leader”] [sent-request-id=13642960994652025413] [received-request-id=13642960994652025326]
[2023/06/15 15:24:56.809 +08:00] [INFO] [trace.go:152] [“trace[923767685] linearizableReadLoop”] [detail=“{readStateIndex:148336766; appliedIndex:148336767; }”] [duration=136.640922ms] [start=2023/06/15 15:24:56.673 +08:00] [end=2023/06/15 15:24:56.809 +08:00] [steps=“["trace[923767685] ‘read index received’ (duration: 136.633836ms)","trace[923767685] ‘applied index is now lower than readState.Index’ (duration: 4.517µs)"]”]
[2023/06/15 15:24:56.809 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=350.650348ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/tidb/store/gcworker/saved_safe_point" “] [response=“range_response_count:1 size:81”] []
[2023/06/15 15:24:56.810 +08:00] [INFO] [trace.go:152] [“trace[415434536] range”] [detail=”{range_begin:/tidb/store/gcworker/saved_safe_point; range_end:; response_count:1; response_revision:147613288; }”] [duration=350.722661ms] [start=2023/06/15 15:24:56.459 +08:00] [end=2023/06/15 15:24:56.810 +08:00] [steps=”["trace[415434536] ‘agreement among raft nodes before linearized reading’ (duration: 350.582611ms)"]”]
[2023/06/15 15:24:56.810 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=361.979793ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/tidb/store/gcworker/saved_safe_point" “] [response=“range_response_count:1 size:81”] []
[2023/06/15 15:24:56.810 +08:00] [INFO] [trace.go:152] [“trace[941111339] range”] [detail=”{range_begin:/tidb/store/gcworker/saved_safe_point; range_end:; response_count:1; response_revision:147613288; }”] [duration=362.035538ms] [start=2023/06/15 15:24:56.448 +08:00] [end=2023/06/15 15:24:56.810 +08:00] [steps=”["trace[941111339] ‘agreement among raft nodes before linearized reading’ (duration: 361.930093ms)"]”]
[2023/06/15 15:24:57.145 +08:00] [INFO] [trace.go:152] [“trace[167777991] linearizableReadLoop”] [detail=“{readStateIndex:148336770; appliedIndex:148336770; }”] [duration=295.496535ms] [start=2023/06/15 15:24:56.849 +08:00] [end=2023/06/15 15:24:57.145 +08:00] [steps=“["trace[167777991] ‘read index received’ (duration: 295.491601ms)","trace[167777991] ‘applied index is now lower than readState.Index’ (duration: 3.859µs)"]”]
[2023/06/15 15:24:57.145 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=295.662636ms] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/config" “] [response=“range_response_count:1 size:4265”] []
[2023/06/15 15:24:57.145 +08:00] [INFO] [trace.go:152] [“trace[1442524431] range”] [detail=”{range_begin:/pd/7204350633511442718/config; range_end:; response_count:1; response_revision:147613291; }”] [duration=295.723969ms] [start=2023/06/15 15:24:56.849 +08:00] [end=2023/06/15 15:24:57.145 +08:00] [steps=”["trace[1442524431] ‘agreement among raft nodes before linearized reading’ (duration: 295.597043ms)"]”]
[2023/06/15 15:24:58.350 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025417] [retry-timeout=500ms]
[2023/06/15 15:24:59.851 +08:00] [WARN] [v3_server.go:814] [“waiting for ReadIndex response took too long, retrying”] [sent-request-id=13642960994652025417] [retry-timeout=500ms]
[2023/06/15 15:25:00.210 +08:00] [WARN] [etcd_kv.go:160] [“txn runs too slow”] [response=“{"header":{"cluster_id":10695899325034778091,"member_id":3712024390580092245,"revision":147613297,"raft_term":205},"succeeded":true,"responses":[{"Response":{"ResponsePut":{"header":{"revision":147613297}}}}]}”] [cost=3.010586421s] []
[2023/06/15 15:25:00.223 +08:00] [INFO] [trace.go:152] [“trace[241575964] linearizableReadLoop”] [detail=“{readStateIndex:148336776; appliedIndex:148336776; }”] [duration=2.373579005s] [start=2023/06/15 15:24:57.849 +08:00] [end=2023/06/15 15:25:00.223 +08:00] [steps=“["trace[241575964] ‘read index received’ (duration: 2.373575273s)","trace[241575964] ‘applied index is now lower than readState.Index’ (duration: 3.043µs)"]”]
[2023/06/15 15:25:00.223 +08:00] [WARN] [util.go:163] [“apply request took too long”] [took=2.373961484s] [expected-duration=100ms] [prefix=“read-only range “] [request=“key:"/pd/7204350633511442718/config" “] [response=“range_response_count:1 size:4265”] []
[2023/06/15 15:25:00.223 +08:00] [INFO] [trace.go:152] [“trace[1024599343] range”] [detail=”{range_begin:/pd/7204350633511442718/config; range_end:; response_count:1; response_revision:147613297; }”] [duration=2.374077685s] [start=2023/06/15 15:24:57.849 +08:00] [end=2023/06/15 15:25:00.223 +08:00] [steps=”["trace[1024599343] ‘agreement among raft nodes before linearized reading’ (duration: 2.37388206s)"]”]
[2023/06/15 15:25:00.224 +08:00] [WARN] [etcdutil.go:121] [“kv gets too slow”] [request-key=/pd/7204350633511442718/config] [cost=2.374380679s] []
