drainer运行异常终止

zhengyunpeng · 2020 年3 月 19 日 06:10

为提高效率，提问时请提供以下信息，问题描述清晰可优先响应。

【TiDB 版本】：3.0.5
【问题描述】： drainer启动后正常运行，一会就异常终止了报错日志：

2020/03/19 13:27:49 Connected to 192.168.10.202:2181
2020/03/19 13:27:49 Authenticated: id=144216523007983622, timeout=40000
2020/03/19 13:27:49 Re-submitting `0` credentials after reconnect
2020/03/19 13:27:49 Recv loop terminated: err=EOF
2020/03/19 13:27:49 Send loop terminated: err=<nil>

不懂就问 · 2020 年3 月 19 日 07:20

辛苦贴一份完整的 drainer 异常时段的日志信息。

yilong · 2020 年3 月 19 日 14:35

您好：请问这是报错前后的所有日志信息吗？如果还有其他信息，麻烦多上传一些，如果没有，帮忙确认下，多谢

zhengyunpeng · 2020 年3 月 22 日 13:42

抱歉，之前在忙然后忘记了。。

error日志：


2020/03/22 19:36:10 Connected to 192.168.10.204:2181
2020/03/22 19:36:10 Authenticated: id=288331799617994792, timeout=40000
2020/03/22 19:36:10 Re-submitting `0` credentials after reconnect
2020/03/22 19:36:10 Recv loop terminated: err=EOF
2020/03/22 19:36:10 Send loop terminated: err=<nil>

drainer日志：

192.168.10.202:9092\
"]
[2020/03/22 19:36:51.031 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:36:51.031 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9923 attempts remaining)\
"]
[2020/03/22 19:36:51.531 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:36:51.531 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:36:51.531 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9922 attempts remaining)\
"]
[2020/03/22 19:36:52.032 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:36:52.032 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:36:52.032 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9921 attempts remaining)\
"]
[2020/03/22 19:36:52.532 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:36:52.533 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:36:52.533 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9920 attempts remaining)\
"]
[2020/03/22 19:36:53.033 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:36:53.033 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:36:53.033 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9919 attempts remaining)\
"]
[2020/03/22 19:36:53.397 +08:00] [INFO] [server.go:406] ["begin to close drainer server"]
[2020/03/22 19:36:53.397 +08:00] [ERROR] [util.go:59] ["Recovered from panic"] [err="\"Waiting too long for `Syncer.run` to quit.\""] [stack="github.com/pingcap/tidb-binlog/drainer.(*taskGroup).start.func1.1\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb-binlog/drainer/util.go:61\
runtime.gopanic\
\t/usr/local/go/src/runtime/panic.go:522\
github.com/pingcap/tidb-binlog/drainer.(*Syncer).run\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:422\
github.com/pingcap/tidb-binlog/drainer.(*Syncer).Start\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:123\
github.com/pingcap/tidb-binlog/drainer.(*Server).Start.func4\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb-binlog/drainer/server.go:269\
github.com/pingcap/tidb-binlog/drainer.(*taskGroup).start.func1\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb-binlog/drainer/util.go:69"] [name=syncer]
[2020/03/22 19:36:53.397 +08:00] [INFO] [util.go:66] [Exit] [name=syncer]
[2020/03/22 19:36:53.400 +08:00] [INFO] [server.go:371] ["has already update status"] [id=tidb1:8249]
[2020/03/22 19:36:53.401 +08:00] [INFO] [server.go:410] ["commit status done"]
[2020/03/22 19:36:53.401 +08:00] [INFO] [collector.go:130] ["publishBinlogs quit"]
[2020/03/22 19:36:53.401 +08:00] [INFO] [util.go:66] [Exit] [name=heartbeat]
[2020/03/22 19:36:53.401 +08:00] [INFO] [pump.go:72] ["pump is closing"] [id=tidb2:8250]
[2020/03/22 19:36:53.401 +08:00] [INFO] [pump.go:72] ["pump is closing"] [id=tidb3:8250]
[2020/03/22 19:36:53.401 +08:00] [INFO] [pump.go:72] ["pump is closing"] [id=tidb4:8250]
[2020/03/22 19:36:53.401 +08:00] [WARN] [merge.go:284] ["can't read binlog from pump"] ["source id"=tidb4:8250]
[2020/03/22 19:36:53.401 +08:00] [INFO] [util.go:66] [Exit] [name=collect]
[2020/03/22 19:36:53.533 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:36:53.534 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:36:53.534 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9918 attempts remaining)\
"]
[2020/03/22 19:36:54.034 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:36:54.035 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:36:54.035 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9917 attempts remaining)\
"]
[2020/03/22 19:36:54.401 +08:00] [INFO] [merge.go:245] ["Merger is closed successfully"]
[2020/03/22 19:36:54.535 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:36:54.535 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:36:54.535 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9916 attempts remaining)\
"]
[2020/03/22 19:36:55.035 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]

...

[2020/03/22 19:36:52.032 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9921 attempts remaining)\
"]
[2020/03/22 19:36:52.532 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:36:52.533 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:36:52.533 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9920 attempts remaining)\
"]
[2020/03/22 19:36:53.033 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:36:53.033 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:36:53.033 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9919 attempts remaining)\
"]
[2020/03/22 19:36:53.397 +08:00] [INFO] [server.go:406] ["begin to close drainer server"]
[2020/03/22 19:36:53.397 +08:00] [ERROR] [util.go:59] ["Recovered from panic"] [err="\"Waiting too long for `Syncer.run` to quit.\""] [stack="github.com/pingcap/tidb-binlog/drainer.(*taskGroup).start.func1.1\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb-binlog/drainer/util.go:61\
runtime.gopanic\
\t/usr/local/go/src/runtime/panic.go:522\
github.com/pingcap/tidb-binlog/drainer.(*Syncer).run\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:422\
github.com/pingcap/tidb-binlog/drainer.(*Syncer).Start\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb-binlog/drainer/syncer.go:123\
github.com/pingcap/tidb-binlog/drainer.(*Server).Start.func4\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb-binlog/drainer/server.go:269\
github.com/pingcap/tidb-binlog/drainer.(*taskGroup).start.func1\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb-binlog/drainer/util.go:69"] [name=syncer]
[2020/03/22 19:36:53.397 +08:00] [INFO] [util.go:66] [Exit] [name=syncer]
[2020/03/22 19:36:53.400 +08:00] [INFO] [server.go:371] ["has already update status"] [id=tidb1:8249]
[2020/03/22 19:36:53.401 +08:00] [INFO] [server.go:410] ["commit status done"]
[2020/03/22 19:36:53.401 +08:00] [INFO] [collector.go:130] ["publishBinlogs quit"]
[2020/03/22 19:36:53.401 +08:00] [INFO] [util.go:66] [Exit] [name=heartbeat]
[2020/03/22 19:36:53.401 +08:00] [INFO] [pump.go:72] ["pump is closing"] [id=tidb2:8250]
[2020/03/22 19:36:53.401 +08:00] [INFO] [pump.go:72] ["pump is closing"] [id=tidb3:8250]
[2020/03/22 19:36:53.401 +08:00] [INFO] [pump.go:72] ["pump is closing"] [id=tidb4:8250]
[2020/03/22 19:36:53.401 +08:00] [WARN] [merge.go:284] ["can't read binlog from pump"] ["source id"=tidb4:825

...

2020/03/22 19:54:18.726 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:54:18.726 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (7844 attempts remaining)\
"]
[2020/03/22 19:54:18.726 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:54:18.727 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9040 attempts remaining)\
"]
[2020/03/22 19:54:19.358 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:54:19.358 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:54:19.400 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\t/usr/local/go/src/runtime/asm_amd64.s:1337"]
[2020/03/22 19:54:19.400 +08:00] [ERROR] [pd.go:129] ["updateTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\t/usr/local/go/src/runtime/asm_amd64.s:1337\
github.com/pingcap/pd/client.(*tsoRequest).Wait\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:561\
github.com/pingcap/pd/client.(*client).GetTS\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:577\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).getTimestamp\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20191018094050-67d8fbf23eee/store/tikv/oracle/oracles/pd.go:103\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).updateTS\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20191018094050-67d8fbf23eee/store/tikv/oracle/oracles/pd.go:127\
runtime.goexit\
\t/usr/local/go/src/runtime/asm_amd64.s:1337\
github.com/pingcap/errors.AddStack\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/errors@v0.11.4/errors.go:174\
github.com/pingcap/errors.Trace\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/errors@v0.11.4/juju_adaptor.go:15\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).getTimestamp\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20191018094050-67d8fbf23eee/store/tikv/oracle/oracles/pd.go:105\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).updateTS\
\t/home/jenkins/agent/workspace/release_tidb_3.0/go/pkg/mod/github.com/pingcap/tidb@v1.1.0-beta.0.20191018094050-67d8fbf23eee/store/tikv/oracle/oracles/pd.go:127\
runtime.goexit\
\t/usr/local/go/src/runtime/asm_amd64.s:1337"]
[2020/03/22 19:54:19.489 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:54:19.489 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (7843 attempts remaining)\
"]
[2020/03/22 19:54:19.795 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:54:19.795 +08:00] [INFO] [client.go:759] ["[sarama] client/metadata retrying after 500ms... (9039 attempts remaining)\
"]
[2020/03/22 19:54:19.989 +08:00] [INFO] [client.go:772] ["[sarama] client/metadata fetching metadata for [kafka_binlog] from broker 192.168.10.202:9092\
"]
[2020/03/22 19:54:19.989 +08:00] [INFO] [client.go:791] ["[sarama] client/metadata found some partitions to be leaderless"]
[2020/03/22 19:54:19.989 +08:00] [INFO] [client.go:759] ["[saram

飞与非-PingCAP · 2020 年3 月 23 日 03:00

从报错信息来看，是 pump 已经停止了，请提供以下信息，如下：

请检查所有的 pump 状态是否正常，若不正常请提供相关的日志
请提供 TiDB 相关的错误信息，最好是日志

zhengyunpeng · 2020 年3 月 23 日 03:48

pump正常：

MySQL [(none)]> show pump status;
+------------+---------------------+--------+--------------------+---------------------+
| NodeID     | Address             | State  | Max_Commit_Ts      | Update_Time         |
+------------+---------------------+--------+--------------------+---------------------+
| tidb4:8250 | 192.168.10.204:8250 | online | 415481286635814916 | 2020-03-23 11:48:47 |
| tidb2:8250 | 192.168.10.202:8250 | online | 415481286635814917 | 2020-03-23 11:48:47 |
| tidb3:8250 | 192.168.10.203:8250 | online | 415481286622707722 | 2020-03-23 11:48:48 |
+------------+---------------------+--------+--------------------+---------------------+
3 rows in set (0.01 sec)

MySQL [(none)]> show drainer status;
+------------+---------------------+--------+--------------------+---------------------+
| NodeID     | Address             | State  | Max_Commit_Ts      | Update_Time         |
+------------+---------------------+--------+--------------------+---------------------+
| tidb1:8249 | 192.168.10.201:8249 | paused | 415419198228398081 | 2020-03-22 19:36:53 |
+------------+---------------------+--------+--------------------+---------------------+
1 row in set (0.05 sec)

zhengyunpeng · 2020 年3 月 23 日 03:54

tidb_error没有错误，对应事件的tidb.log中日志：

2020/03/22 19:30:24.213 +08:00] [WARN] [server.go:262] ["secure connection is not enabled"]
[2020/03/22 19:30:24.213 +08:00] [INFO] [server.go:217] ["server is running MySQL protocol"] [addr=0.0.0.0:4000]
[2020/03/22 19:30:24.217 +08:00] [INFO] [http_status.go:253] ["for status and metrics report"] ["listening on addr"=0.0.0.0:10080]
[2020/03/22 19:30:24.893 +08:00] [INFO] [domain.go:929] ["init stats info time"] ["take time"=720.896429ms]
[2020/03/22 19:30:27.179 +08:00] [INFO] [region_cache.go:540] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=72] [currIdx=2] [leaderStoreID=4]
[2020/03/22 19:30:34.150 +08:00] [INFO] [server.go:413] ["new connection"] [conn=2] [remoteAddr=192.168.10.100:50542]
[2020/03/22 19:30:34.169 +08:00] [INFO] [set.go:192] ["set session var"] [conn=2] [name=character_set_results] [val=NULL]
[2020/03/22 19:30:34.175 +08:00] [INFO] [server.go:413] ["new connection"] [conn=3] [remoteAddr=192.168.10.100:50544]
[2020/03/22 19:30:34.191 +08:00] [INFO] [set.go:192] ["set session var"] [conn=3] [name=character_set_results] [val=NULL]
[2020/03/22 19:30:54.860 +08:00] [INFO] [manager.go:316] ["get owner"] ["owner info"="[stats] /tidb/stats/owner ownerManager bb07d1a4-9ac2-4053-b4f8-e74e7b99e165"] [ownerID=bb07d1a4-9ac2-4053-b4f8-e74e7b99e165]
[2020/03/22 19:36:05.264 +08:00] [INFO] [server.go:413] ["new connection"] [conn=15] [remoteAddr=192.168.10.101:59546]
[2020/03/22 19:36:05.274 +08:00] [INFO] [server.go:413] ["new connection"] [conn=16] [remoteAddr=192.168.10.101:59548]
[2020/03/22 19:36:05.292 +08:00] [INFO] [server.go:413] ["new connection"] [conn=17] [remoteAddr=192.168.10.101:59550]
[2020/03/22 19:36:05.315 +08:00] [INFO] [server.go:413] ["new connection"] [conn=19] [remoteAddr=192.168.10.101:59552]
[2020/03/22 19:36:05.315 +08:00] [INFO] [server.go:413] ["new connection"] [conn=18] [remoteAddr=192.168.10.101:59554]
[2020/03/22 19:36:10.875 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=3]
[2020/03/22 19:36:23.568 +08:00] [INFO] [server.go:413] ["new connection"] [conn=21] [remoteAddr=127.0.0.1:57552]
[2020/03/22 19:40:24.183 +08:00] [INFO] [region_cache.go:540] ["switch region leader to specific leader due to kv return NotLeader"] [regionID=64] [currIdx=1] [leaderStoreID=4]
[2020/03/22 19:40:24.248 +08:00] [INFO] [gc_worker.go:277] ["[gc worker] starts the whole job"] [uuid=5c4080864740007] [safePoint=415465897776119808] [concurrency=3]
[2020/03/22 19:40:24.248 +08:00] [INFO] [gc_worker.go:773] ["[gc worker] start resolve locks"] [uuid=5c4080864740007] [safePoint=415465897776119808] [concurrency=3]
[2020/03/22 19:40:24.248 +08:00] [INFO] [range_task.go:90] ["range task started"] [name=resolve-locks-runner] [startKey=] [endKey=] [concurrency=3]
[2020/03/22 19:40:25.219 +08:00] [INFO] [range_task.go:199] ["range task finished"] [name=resolve-locks-runner] [startKey=] [endKey=] ["cost time"=971.197334ms] ["completed regions"=2903]
[2020/03/22 19:40:25.219 +08:00] [INFO] [gc_worker.go:794] ["[gc worker] finish resolve locks"] [uuid=5c4080864740007] [safePoint=415465897776119808] [regions=2903]
[2020/03/22 19:41:24.232 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5c4080864740007]
[2020/03/22 19:42:05.228 +08:00] [INFO] [gc_worker.go:582] ["[gc worker] start delete"] [uuid=5c4080864740007] [ranges=2]
[2020/03/22 19:42:05.240 +08:00] [INFO] [range_task.go:90] ["range task started"] [name=delete-range-notify] [startKey=dIAAAAAAAB3q] [endKey=dIAAAAAAAB3r] [concurrency=3]
[2020/03/22 19:42:05.243 +08:00] [INFO] [range_task.go:199] ["range task finished"] [name=delete-range-notify] [startKey=dIAAAAAAAB3q] [endKey=dIAAAAAAAB3r] ["cost time"=2.685688ms] ["completed regions"=1]
[2020/03/22 19:42:05.271 +08:00] [INFO] [range_task.go:90] ["range task started"] [name=delete-range-notify] [startKey=dIAAAAAAAB2Z] [endKey=dIAAAAAAAB2a] [concurrency=3]
[2020/03/22 19:42:05.274 +08:00] [INFO] [range_task.go:199] ["range task finished"] [name=delete-range-notify] [startKey=dIAAAAAAAB2Z] [endKey=dIAAAAAAAB2a] ["cost time"=2.618645ms] ["completed regions"=1]
[2020/03/22 19:42:05.288 +08:00] [INFO] [gc_worker.go:601] ["[gc worker] finish delete ranges"] [uuid=5c4080864740007] ["num of ranges"=2] ["cost time"=60.027909ms]
[2020/03/22 19:42:05.308 +08:00] [INFO] [gc_worker.go:624] ["[gc worker] start redo-delete ranges"] [uuid=5c4080864740007] ["num of ranges"=0]
[2020/03/22 19:42:05.308 +08:00] [INFO] [gc_worker.go:643] ["[gc worker] finish redo-delete ranges"] [uuid=5c4080864740007] ["num of ranges"=0] ["cost time"=792ns]
[2020/03/22 19:42:05.315 +08:00] [INFO] [gc_worker.go:921] ["[gc worker] sent safe point to PD"] [uuid=5c4080864740007] ["safe point"=415465897776119808]
[2020/03/22 19:50:24.242 +08:00] [INFO] [gc_worker.go:277] ["[gc worker] starts the whole job"] [uuid=5c4080864740007] [safePoint=415466055062519808] [concurrency=3]
[2020/03/22 19:50:24.243 +08:00] [INFO] [gc_worker.go:773] ["[gc worker] start resolve locks"] [uuid=5c4080864740007] [safePoint=415466055062519808] [concurrency=3]
[2020/03/22 19:50:24.243 +08:00] [INFO] [range_task.go:90] ["range task started"] [name=resolve-locks-runner] [startKey=] [endKey=] [concurrency=3]
[2020/03/22 19:50:24.968 +08:00] [INFO] [range_task.go:199] ["range task finished"] [name=resolve-locks-runner] [startKey=] [endKey=] ["cost time"=725.693483ms] ["completed regions"=2903]
[2020/03/22 19:50:24.968 +08:00] [INFO] [gc_worker.go:794] ["[gc worker] finish resolve locks"] [uuid=5c4080864740007] [safePoint=415466055062519808] [regions=2903]
[2020/03/22 19:51:24.227 +08:00] [INFO] [gc_worker.go:246] ["[gc worker] there's already a gc job running, skipped"] ["leaderTick on"=5c4080864740007]
[2020/03/22 19:52:04.977 +08:00] [INFO] [gc_worker.go:582] ["[gc worker] start delete"] [uuid=5c4080864740007] [ranges=0]
[2020/03/22 19:52:04.977 +08:00] [INFO] [gc_worker.go:601] ["[gc worker] finish delete ranges"] [uuid=5c4080864740007] ["num of ranges"=0] ["cost time"=678ns]
[2020/03/22 19:52:04.980 +08:00] [INFO] [gc_worker.go:624] ["[gc worker] start redo-delete ranges"] [uuid=5c4080864740007] ["num of ranges"=0]
[2020/03/22 19:52:04.980 +08:00] [INFO] [gc_worker.go:643] ["[gc worker] finish redo-delete ranges"] [uuid=5c4080864740007] ["num of ranges"=0] ["cost time"=848ns]
[2020/03/22 19:52:04.985 +08:00] [INFO] [gc_worker.go:921] ["[gc worker] sent safe point to PD"] [uuid=5c4080864740007] ["safe point"=415466055062519808]
[2020/03/22 19:54:09.802 +08:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=67.856794ms]
[2020/03/22 19:54:12.293 +08:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=467.03577ms]
[2020/03/22 19:54:12.294 +08:00] [WARN] [pd.go:109] ["get timestamp too slow"] ["cost time"=467.629426ms]
[2020/03/22 19:54:17.869 +08:00] [INFO] [client_batch.go:291] ["batchRecvLoop fails when receiving, needs to reconnect"] [target=192.168.10.202:20160] [error="rpc error: code = Unavailable desc = transport is closing"]
[2020/03/22 19:54:17.870 +08:00] [INFO] [client_batch.go:291] ["batchRecvLoop fails when receiving, needs to reconnect"] [target=192.168.10.204:20160] [error="rpc error: code = Unavailable desc = transport is closing"]
[2020/03/22 19:54:17.870 +08:00] [INFO] [client_batch.go:291] ["batchRecvLoop fails when receiving, needs to reconnect"] [target=192.168.10.204:20160] [error="rpc error: code = Unavailable desc = transport is closing"]
[2020/03/22 19:54:17.870 +08:00] [ERROR] [client.go:323] ["tso request is canceled due to timeout"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsCancelLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:323"]
[2020/03/22 19:54:17.870 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Canceled desc = context canceled"] [errorVerbose="rpc error: code = Canceled desc = context canceled\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:17.870 +08:00] [ERROR] [pd.go:129] ["updateTS error"] [error="rpc error: code = Canceled desc = context canceled"] [errorVerbose="rpc error: code = Canceled desc = context canceled\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357\
github.com/pingcap/pd/client.(*tsoRequest).Wait\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:561\
github.com/pingcap/pd/client.(*client).GetTS\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:577\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).getTimestamp\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:103\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).updateTS\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:127\
runtime.goexit\
\truntime/asm_amd64.s:1357\
github.com/pingcap/errors.AddStack\
\tgithub.com/pingcap/errors@v0.11.4/errors.go:174\
github.com/pingcap/errors.Trace\
\tgithub.com/pingcap/errors@v0.11.4/juju_adaptor.go:15\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).getTimestamp\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:105\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).updateTS\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:127\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).updateTS\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:129"]
[2020/03/22 19:54:17.871 +08:00] [INFO] [client_batch.go:291] ["batchRecvLoop fails when receiving, needs to reconnect"] [target=192.168.10.204:20160] [error="rpc error: code = Unavailable desc = transport is closing"]
[2020/03/22 19:54:17.872 +08:00] [INFO] [client_batch.go:257] ["batchRecvLoop re-create streaming success"] [target=192.168.10.204:20160]
[2020/03/22 19:54:17.872 +08:00] [INFO] [client_batch.go:257] ["batchRecvLoop re-create streaming success"] [target=192.168.10.204:20160]
[2020/03/22 19:54:17.873 +08:00] [INFO] [client_batch.go:257] ["batchRecvLoop re-create streaming success"] [target=192.168.10.204:20160]
[2020/03/22 19:54:18.173 +08:00] [INFO] [client_batch.go:257] ["batchRecvLoop re-create streaming success"] [target=192.168.10.202:20160]
[2020/03/22 19:54:18.721 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:547.105201ms txnStartTS:415466270990532768 region_id:40 store_addr:192.168.10.203:20160"]
[2020/03/22 19:54:18.721 +08:00] [INFO] [coprocessor.go:743] ["[TIME_COP_PROCESS] resp_time:546.964018ms txnStartTS:415466270990532769 region_id:28 store_addr:192.168.10.203:20160"]
[2020/03/22 19:54:18.722 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:18.722 +08:00] [ERROR] [pd.go:129] ["updateTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357\
github.com/pingcap/pd/client.(*tsoRequest).Wait\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:561\
github.com/pingcap/pd/client.(*client).GetTS\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:577\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).getTimestamp\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:103\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).updateTS\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:127\
runtime.goexit\
\truntime/asm_amd64.s:1357\
github.com/pingcap/errors.AddStack\
\tgithub.com/pingcap/errors@v0.11.4/errors.go:174\
github.com/pingcap/errors.Trace\
\tgithub.com/pingcap/errors@v0.11.4/juju_adaptor.go:15\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).getTimestamp\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:105\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).updateTS\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:127\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).updateTS\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:129"]
[2020/03/22 19:54:19.488 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:19.795 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:19.796 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:19.796 +08:00] [ERROR] [pd.go:129] ["updateTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357\
github.com/pingcap/pd/client.(*tsoRequest).Wait\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:561\
github.com/pingcap/pd/client.(*client).GetTS\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:577\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).getTimestamp\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:103\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).updateTS\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:127\
runtime.goexit\
\truntime/asm_amd64.s:1357\
github.com/pingcap/errors.AddStack\
\tgithub.com/pingcap/errors@v0.11.4/errors.go:174\
github.com/pingcap/errors.Trace\
\tgithub.com/pingcap/errors@v0.11.4/juju_adaptor.go:15\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).getTimestamp\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:105\
github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).updateTS\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:127\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/tidb/store/tikv/oracle/oracles.(*pdOracle).updateTS\
\tgithub.com/pingcap/tidb@/store/tikv/oracle/oracles/pd.go:129"]
[2020/03/22 19:54:19.800 +08:00] [ERROR] [kv.go:246] ["fail to load safepoint from pd"] [error="context deadline exceeded"] [errorVerbose="context deadline exceeded\
github.com/pingcap/errors.AddStack\
\tgithub.com/pingcap/errors@v0.11.4/errors.go:174\
github.com/pingcap/errors.Trace\
\tgithub.com/pingcap/errors@v0.11.4/juju_adaptor.go:15\
github.com/pingcap/tidb/store/tikv.(*EtcdSafePointKV).Get\
\tgithub.com/pingcap/tidb@/store/tikv/safepoint.go:108\
github.com/pingcap/tidb/store/tikv.loadSafePoint\
\tgithub.com/pingcap/tidb@/store/tikv/safepoint.go:127\
github.com/pingcap/tidb/store/tikv.(*tikvStore).runSafePointChecker\
\tgithub.com/pingcap/tidb@/store/tikv/kv.go:239\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/tidb/store/tikv.(*tikvStore).runSafePointChecker\
\tgithub.com/pingcap/tidb@/store/tikv/kv.go:246"]
[2020/03/22 19:54:19.807 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:19.807 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:20.067 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:20.106 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:20.120 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:20.140 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:20.376 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:20.490 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:20.522 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:21.735 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] 
[2020/03/22 19:54:30.930 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:30.941 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:31.113 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:31.162 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 19:54:31.343 +08:00] [ERROR] [client.go:408] ["[pd] getTS error"] [error="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader"] [errorVerbose="rpc error: code = Unknown desc = rpc error: code = Unavailable desc = not leader\
github.com/pingcap/pd/client.(*client).processTSORequests\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:444\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:393\
runtime.goexit\
\truntime/asm_amd64.s:1357"] [stack="github.com/pingcap/log.Error\
\tgithub.com/pingcap/log@v0.0.0-20190715063458-479153f07ebd/global.go:42\
github.com/pingcap/pd/client.(*client).tsLoop\
\tgithub.com/pingcap/pd@v1.1.0-beta.0.20190912093418-dc03c839debd/client/client.go:408"]
[2020/03/22 20:01:25.952 +08:00] [INFO] [ddl_worker.go:306] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:7669, Type:create table, State:synced, SchemaState:public, SchemaID:90, TableID:7668, RowCount:0, ArgLen:0, start time: 2020-03-22 20:01:25.648 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/03/22 20:01:25.960 +08:00] [INFO] [ddl.go:619] ["[ddl] DDL job is finished"] [jobID=7669]
[2020/03/22 20:01:25.960 +08:00] [INFO] [ddl_worker.go:486] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:7671, Type:create table, State:none, SchemaState:none, SchemaID:90, TableID:7670, RowCount:0, ArgLen:0, start time: 2020-03-22 20:01:25.848 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/03/22 20:01:25.961 +08:00] [INFO] [domain.go:566] ["performing DDL change, must reload"]
[2020/03/22 20:01:25.961 +08:00] [INFO] [split_region.go:58] ["split batch regions request"] ["split key count"=1] ["batch count"=1] ["first batch, region ID"=2] ["first split key"=dIAAAAAAAB30]
[2020/03/22 20:01:25.985 +08:00] [INFO] [split_region.go:153] ["batch split regions complete"] ["batch region ID"=2] ["first at"=dIAAAAAAAB30] ["first new region left"="id:18001 start_key:\"t\\200\\000\\000\\000\\000\\000\\035\\377\\360\\000\\000\\000\\000\\000\\000\\000\\370\" end_key:\"t\\200\\000\\000\\000\\000\\000\\035\\377\\364\\000\\000\\000\\000\\000\\000\\000\\370\" region_epoch:<conf_ver:8 version:2824 > peers:<id:18002 store_id:4 > peers:<id:18003 store_id:6 > peers:<id:18004 store_id:1 > "] ["new region count"=1]
[2020/03/22 20:01:25.985 +08:00] [INFO] [split_region.go:200] ["split regions complete"] ["region count"=1] ["region IDs"="[18001]"]
[2020/03/22 20:01:25.993 +08:00] [INFO] [domain.go:123] ["diff load InfoSchema success"] [usedSchemaVersion=7001] [neededSchemaVersion=7002] ["start time"=1.610282ms] [tblIDs="[7670]"]
[2020/03/22 20:01:26.043 +08:00] [INFO] [ddl_worker.go:657] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=7002] ["take time"=63.600976ms] [job="ID:7671, Type:create table, State:done, SchemaState:public, SchemaID:90, TableID:7670, RowCount:0, ArgLen:1, start time: 2020-03-22 20:01:25.848 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/03/22 20:01:26.046 +08:00] [INFO] [ddl_worker.go:306] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:7671, Type:create table, State:synced, SchemaState:public, SchemaID:90, TableID:7670, RowCount:0, ArgLen:0, start time: 2020-03-22 20:01:25.848 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/03/22 20:01:26.056 +08:00] [INFO] [ddl.go:619] ["[ddl] DDL job is finished"] [jobID=7671]
[2020/03/22 20:01:26.057 +08:00] [INFO] [domain.go:566] ["performing DDL change, must reload"]
[2020/03/22 20:01:26.057 +08:00] [INFO] [split_region.go:58] ["split batch regions request"] ["split key count"=1] ["batch count"=1] ["first batch, region ID"=2] ["first split key"=dIAAAAAAAB32]
[2020/03/22 20:01:26.066 +08:00] [INFO] [split_region.go:153] ["batch split regions complete"] ["batch region ID"=2] ["first at"=dIAAAAAAAB32] ["first new region left"="id:18005 start_key:\"t\\200\\000\\000\\000\\000\\000\\035\\377\\364\\000\\000\\000\\000\\000\\000\\000\\370\" end_key:\"t\\200\\000\\000\\000\\000\\000\\035\\377\\366\\000\\000\\000\\000\\000\\000\\000\\370\" region_epoch:<conf_ver:8 version:2825 > peers:<id:18006 store_id:4 > peers:<id:18007 store_id:6 > peers:<id:18008 store_id:1 > "] ["new region count"=1]
[2020/03/22 20:01:26.066 +08:00] [INFO] [split_region.go:200] ["split regions complete"] ["region count"=1] ["region IDs"="[18005]"]
[2020/03/22 20:01:31.394 +08:00] [INFO] [server.go:413] ["new connection"] [conn=74] [remoteAddr=192.168.10.204:51918]
[2020/03/22 20:01:31.440 +08:00] [INFO] [set.go:192] ["set session var"] [conn=74] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:32.236 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=74]
[2020/03/22 20:01:32.290 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=73]
[2020/03/22 20:01:32.297 +08:00] [INFO] [server.go:413] ["new connection"] [conn=75] [remoteAddr=192.168.10.201:45712]
[2020/03/22 20:01:32.312 +08:00] [INFO] [set.go:192] ["set session var"] [conn=75] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:32.318 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=75]
[2020/03/22 20:01:37.932 +08:00] [INFO] [server.go:413] ["new connection"] [conn=76] [remoteAddr=192.168.10.204:51922]
[2020/03/22 20:01:37.952 +08:00] [INFO] [set.go:192] ["set session var"] [conn=76] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:37.953 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=76]
[2020/03/22 20:01:37.971 +08:00] [INFO] [server.go:413] ["new connection"] [conn=77] [remoteAddr=192.168.10.204:51924]
[2020/03/22 20:01:37.983 +08:00] [INFO] [set.go:192] ["set session var"] [conn=77] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:37.987 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=77]
[2020/03/22 20:01:38.005 +08:00] [INFO] [server.go:413] ["new connection"] [conn=78] [remoteAddr=192.168.10.204:51926]
[2020/03/22 20:01:38.024 +08:00] [INFO] [set.go:192] ["set session var"] [conn=78] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:38.030 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=78]
[2020/03/22 20:01:38.045 +08:00] [INFO] [server.go:413] ["new connection"] [conn=79] [remoteAddr=192.168.10.204:51928]
[2020/03/22 20:01:38.053 +08:00] [INFO] [set.go:192] ["set session var"] [conn=79] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:38.054 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=79]
[2020/03/22 20:01:38.069 +08:00] [INFO] [server.go:413] ["new connection"] [conn=80] [remoteAddr=192.168.10.204:51930]
[2020/03/22 20:01:38.079 +08:00] [INFO] [set.go:192] ["set session var"] [conn=80] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:38.081 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=80]
[2020/03/22 20:01:38.102 +08:00] [INFO] [server.go:413] ["new connection"] [conn=81] [remoteAddr=192.168.10.204:51932]
[2020/03/22 20:01:38.114 +08:00] [INFO] [set.go:192] ["set session var"] [conn=81] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:38.118 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=81]
[2020/03/22 20:01:38.135 +08:00] [INFO] [server.go:413] ["new connection"] [conn=82] [remoteAddr=192.168.10.204:51934]
[2020/03/22 20:01:38.143 +08:00] [INFO] [set.go:192] ["set session var"] [conn=82] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:38.144 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=82]
[2020/03/22 20:01:38.160 +08:00] [INFO] [server.go:413] ["new connection"] [conn=83] [remoteAddr=192.168.10.204:51936]
[2020/03/22 20:01:38.167 +08:00] [INFO] [set.go:192] ["set session var"] [conn=83] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:38.168 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=83]
[2020/03/22 20:01:38.183 +08:00] [INFO] [server.go:413] ["new connection"] [conn=84] [remoteAddr=192.168.10.204:51938]
[2020/03/22 20:01:38.202 +08:00] [INFO] [set.go:192] ["set session var"] [conn=84] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:38.205 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=84]
[2020/03/22 20:01:38.221 +08:00] [INFO] [server.go:413] ["new connection"] [conn=85] [remoteAddr=192.168.10.204:51940]
[2020/03/22 20:01:38.241 +08:00] [INFO] [set.go:192] ["set session var"] [conn=85] [name=character_set_results] [val=NULL]
[2020/03/22 20:01:38.246 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=85]
[2020/03/22 20:01:38.261 +08:00] [INFO] [server.

zhengyunpeng · 2020 年3 月 23 日 03:55

tidb日志错误很多，超过4000了，删了好多

飞与非-PingCAP · 2020 年3 月 23 日 06:09

请检查 drainer 报错误时间段， Pump 的状态

yilong · 2020 年3 月 23 日 13:44

您好：

     1. 从drainer日志看，应该是kafka那里有报错，接着drainer被关闭

     2. 之后tidb也出现获取pd tso慢

     3. 建议可以检查一下kafka是否在问题发生时正常，多谢。

zhengyunpeng · 2020 年3 月 24 日 06:42

您好，今天排查问题，发现是kafka的问题，有一个kafka关掉了。谢谢

来了老弟 · 2020 年3 月 25 日 03:12

，感谢回复，如果问题已解决，请选择一个解决方案吧~

如有新的问题，请另开新帖提问哦~

system · 2022 年10 月 31 日 19:05

此话题已在最后回复的 1 分钟后被自动关闭。不再允许新回复。