Tikv_gc_last_run_time、tikv_gc_safe_point出现异常

pangcm · 2019 年11 月 8 日 10:00

为提高效率，提问时请尽量提供详细背景信息，问题描述清晰可优先响应。以下信息点请尽量提供：

【系统版本 & kernel 版本】

CentOS7.4，3.10.0-693.2.2.el7.x86_64

【TiDB 版本】

3.0.2

【磁盘型号】

SSD

【集群节点分布】

TIDB：2个节点

PD:3个节点

TiKV:8个节点（原来是6个，今天新增2个）

【数据量 & region 数量 & 副本数】

【问题描述（我做了什么）】

如题所示，我们的TiDB集群近期遇到存储空间告警的问题。于是我们尝试去清除一些数据，并且也在今天增加了两个节点。我们清除数据后，发现数据量并没有下降。排查后发现GC有异常，上次GC成功的时间是11月4号。

在社区里面我看到有人遇到过类似的问题，给出的答复是region的数量过多引起的。

但是我这里有个疑问，我看grafana上的历史数据，在4号之前的GC都是很正常的，大概10分钟到半小时就能跑一次GC。另外，由于我们已经开启了merge，最近的region数量相对之前是下降了，为什么之前没有出现GC失败的情况呢？

4号之后就没有gc了

image1753×320 25.9 KB
3号的时候gc运行正常

image1729×296 54.2 KB
最近几天region数量的变化

image915×317 18.3 KB
最近几天数据库使用磁盘的大小

image910×314 16.4 KB

【关键词】

GC,region

yilong · 2019 年11 月 8 日 10:33

您好：请帮忙反馈下tikv和tidb的日志，多谢。在11月4号有进行什么操作吗？

pangcm · 2019 年11 月 8 日 10:52

11月4日的操作

我们在4号上午调整了下几个任务的并发数量，分别是

region-schedule-limit 由8调整为16 merge-schedule-limit 由8调整为16

TiDB日志

不大清楚你想要哪一个时间段的日志，这里给出最后一次 gc之后的日志。

[2019/11/04 02:02:28.484 +08:00] [INFO] [server.go:416] ["connection closed"] [conn=111300]
[2019/11/04 02:02:30.344 +08:00] [ERROR] [privileges.go:111] ["get user privilege record fail"] [user=xlopAdmin] [host=127.0.0.1] [stack="github.com/
pingcap/tidb/privilege/privileges.(*UserPrivileges).ConnectionVerification
	/home/jenkins/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb
/privilege/privileges/privileges.go:111
github.com/pingcap/tidb/session.(*session).Auth
	/home/jenkins/workspace/release_tidb_3.0/go/src/github.co
m/pingcap/tidb/session/session.go:1342
github.com/pingcap/tidb/server.(*TiDBContext).Auth
	/home/jenkins/workspace/release_tidb_3.0/go/src/github.
com/pingcap/tidb/server/driver_tidb.go:285
github.com/pingcap/tidb/server.(*clientConn).openSessionAndDoAuth
	/home/jenkins/workspace/release_tidb
_3.0/go/src/github.com/pingcap/tidb/server/conn.go:555
github.com/pingcap/tidb/server.(*clientConn).readOptionalSSLRequestAndHandshakeResponse
	/h
ome/jenkins/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb/server/conn.go:532
github.com/pingcap/tidb/server.(*clientConn).handshake
	/home/jenkins/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb/server/conn.go:170
github.com/pingcap/tidb/server.(*Server).onConn
	/home/jenkins/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb/server/server.go:404"]
[2019/11/04 02:02:30.347 +08:00] [INFO] [server.go:413] ["new connection"] [conn=111572] [remoteAddr=127.0.0.1:12417]
[2019/11/04 02:02:30.366 +08:00] [INFO] [set.go:190] ["set session var"] [conn=111572] [name=character_set_results] [val=NULL]
[2019/11/04 02:02:30.368 +08:00] [INFO] [set.go:190] ["set session var"] [conn=111572] [name=autocommit] [val=1]
[2019/11/04 02:02:30.370 +08:00] [INFO] [set.go:190] ["set session var"] [conn=111572] [name=tx_read_only] [val=0]
[2019/11/04 02:02:30.370 +08:00] [INFO] [set.go:190] ["set session var"] [conn=111572] [name=transaction_read_only] [val=0]
[2019/11/04 02:02:30.372 +08:00] [INFO] [set.go:190] ["set session var"] [conn=111572] [name=autocommit] [val=1]
[2019/11/04 02:02:30.484 +08:00] [INFO] [coprocessor.go:726] ["[TIME_COP_PROCESS] resp_time:477.376236ms txnStartTS:412301171098648583 region_id:429189 store_addr:172.17.9.31:20160 kv_process_ms:469 scan_total_write:796372 scan_processed_write:546166 scan_total_data:0 scan_processed_data:0 scan_total_lock:1 scan_processed_lock:0"]
[2019/11/04 02:02:35.391 +08:00] [INFO] [coprocessor.go:726] ["[TIME_COP_PROCESS] resp_time:385.254932ms txnStartTS:412301172409368582 region_id:2140084 store_addr:172.17.9.31:20160 kv_process_ms:377 scan_total_write:679904 scan_processed_write:679903 scan_total_data:0 scan_processed_data:0 scan_total_lock:1 scan_processed_lock:0"]
[2019/11/04 02:02:35.407 +08:00] [INFO] [coprocessor.go:726] ["[TIME_COP_PROCESS] resp_time:401.723137ms txnStartTS:412301172409368582 region_id:2176193 store_addr:172.17.9.35:20160 kv_process_ms:360 scan_total_write:383366 scan_processed_write:383365 scan_total_data:0 scan_processed_data:0 scan_total_lock:1 scan_processed_lock:0"]
[2019/11/04 02:02:35.410 +08:00] [INFO] [coprocessor.go:726] ["[TIME_COP_PROCESS] resp_time:403.802941ms txnStartTS:412301172409368582 region_id:2103697 store_addr:172.17.9.35:20160 kv_process_ms:371 scan_total_write:639894 scan_processed_write:639893 scan_total_data:0 scan_processed_data:0 scan_total_lock:1 scan_processed_lock:0"]
[2019/11/04 02:02:35.463 +08:00] [INFO] [coprocessor.go:726] ["[TIME_COP_PROCESS] resp_time:456.963642ms txnStartTS:412301172409368582 region_id:2154229 store_addr:172.17.9.30:20160 kv_process_ms:440 scan_total_write:637026 scan_processed_write:637025 scan_total_data:0 scan_processed_data:0 scan_total_lock:1 scan_processed_lock:0"]
[2019/11/04 02:02:35.874 +08:00] [INFO] [coprocessor.go:726] ["[TIME_COP_PROCESS] resp_time:326.90633ms txnStartTS:412301172540440708 region_id:2121600 store_addr:172.17.9.33:20160 kv_process_ms:316 scan_total_write:559191 scan_processed_write:559190 scan_total_data:0 scan_processed_data:0 scan_total_lock:1 scan_processed_lock:0"]
[2019/11/04 02:02:36.088 +08:00] [INFO] [coprocessor.go:726] ["[TIME_COP_PROCESS] resp_time:541.209688ms txnStartTS:412301172540440708 region_id:2194328 store_addr:172.17.9.33:20160 kv_process_ms:530 scan_total_write:612809 scan_processed_write:612808 scan_total_data:0 scan_processed_data:0 scan_total_lock:1 scan_processed_lock:0"]
[2019/11/04 02:02:41.284 +08:00] [INFO] [coprocessor.go:726] ["[TIME_COP_WAIT] resp_time:342.468066ms txnStartTS:18446744073709551615 region_id:2154722 store_addr:172.17.9.34:20160 kv_wait_ms:341"]
[2019/11/04 02:02:44.875 +08:00] [INFO] [server.go:413] ["new connection"] [conn=111573] [remoteAddr=127.0.0.1:12469]
[2019/11/04 02:02:44.888 +08:00] [INFO] [set.go:190] ["set session var"] [conn=111573] [name=character_set_results] [val=NULL]
[2019/11/04 02:02:44.890 +08:00] [INFO] [set.go:190] ["set session var"] [conn=111573] [name=autocommit] [val=1]
[2019/11/04 02:02:44.892 +08:00] [INFO] [set.go:190] ["set session var"] [conn=111573] [name=tx_read_only] [val=0]
[2019/11/04 02:02:44.892 +08:00] [INFO] [set.go:190] ["set session var"] [conn=111573] [name=transaction_read_only] [val=0]

-TiKV日志

同样，TiKV也截取这段时间的其中一个节点的日志

[2019/11/04 00:02:27.973 +08:00] [INFO] [peer.rs:724] ["failed to schedule peer tick"] [err="sending on a disconnected channel"] [tick=CHECK_PEER_STA
LE_STATE] [peer_id=2214134] [region_id=2214132]
[2019/11/04 00:02:28.995 +08:00] [INFO] [peer.rs:724] ["failed to schedule peer tick"] [err="sending on a disconnected channel"] [tick=PD_HEARTBEAT] [peer_id=1736045] [region_id=963505]
[2019/11/04 00:02:30.902 +08:00] [INFO] [keys.rs:149] ["approximate keys over threshold, need to do split check"] [threshold=1440000] [keys=1444604] [region_id=1351694]
[2019/11/04 00:02:31.596 +08:00] [INFO] [peer.rs:320] ["on split"] [split_keys="key 748000000000000FFF8A5F698000000000FF0000010380000000FF0151B96C03850A00FF001D039EB2000000FCFA495574EB87FFAF"] [peer_id=1351695] [region_id=1351694]
[2019/11/04 00:02:31.596 +08:00] [INFO] [pd.rs:277] ["try to batch split region"] [region="id: 1351694 start_key: 748000000000000FFF8A5F698000000000FF0000010380000000FF0151444303830600FF00198DC080000000FC end_key: 748000000000000FFF8A5F698000000000FF0000010380000000FF0151EE6503810200FF001BAD3281000000FC region_epoch { conf_ver: 80 version: 2094 } peers { id: 1351695 store_id: 76572 } peers { id: 1504697 store_id: 733266 } peers { id: 1591175 store_id: 93545 }"] [new_region_ids="[new_region_id: 2221078 new_peer_ids: 2221079 new_peer_ids: 2221080 new_peer_ids: 2221081]"] [region_id=1351694]
[2019/11/04 00:02:31.669 +08:00] [INFO] [apply.rs:1043] ["execute admin command"] [command="cmd_type: BatchSplit splits { requests { split_key: 748000000000000FFF8A5F698000000000FF0000010380000000FF0151B96C03850A00FF001D039EB2000000FC new_region_id: 2221078 new_peer_ids: 2221079 new_peer_ids: 2221080 new_peer_ids: 2221081 } right_derive: true }"] [index=987284] [term=6] [peer_id=1351695] [region_id=1351694]
[2019/11/04 00:02:31.669 +08:00] [INFO] [apply.rs:1613] ["split region"] [keys="key 748000000000000FFF8A5F698000000000FF0000010380000000FF0151B96C03850A00FF001D039EB2000000FC"] [region="id: 1351694 start_key: 748000000000000FFF8A5F698000000000FF0000010380000000FF0151444303830600FF00198DC080000000FC end_key: 748000000000000FFF8A5F698000000000FF0000010380000000FF0151EE6503810200FF001BAD3281000000FC region_epoch { conf_ver: 80 version: 2094 } peers { id: 1351695 store_id: 76572 } peers { id: 1504697 store_id: 733266 } peers { id: 1591175 store_id: 93545 }"] [peer_id=1351695] [region_id=1351694]
[2019/11/04 00:02:31.720 +08:00] [INFO] [peer.rs:1526] ["notify pd with split"] [split_count=2] [peer_id=1351695] [region_id=1351694]
[2019/11/04 00:02:31.720 +08:00] [INFO] [peer.rs:1568] ["insert new region"] [region="id: 2221078 start_key: 748000000000000FFF8A5F698000000000FF0000010380000000FF0151444303830600FF00198DC080000000FC end_key: 748000000000000FFF8A5F698000000000FF0000010380000000FF0151B96C03850A00FF001D039EB2000000FC region_epoch { conf_ver: 80 version: 2095 } peers { id: 2221079 store_id: 76572 } peers { id: 2221080 store_id: 733266 } peers { id: 2221081 store_id: 93545 }"] [region_id=2221078]
[2019/11/04 00:02:31.721 +08:00] [INFO] [peer.rs:142] ["create peer"] [peer_id=2221079] [region_id=2221078]
[2019/11/04 00:02:31.721 +08:00] [INFO] [raft.rs:723] ["[region 2221078] 2221079 became follower at term 5"]
[2019/11/04 00:02:31.721 +08:00] [INFO] [raft.rs:295] ["[region 2221078] 2221079 newRaft [peers: [2221079, 2221080, 2221081], term: 5, commit: 5, applied: 5, last_index: 5, last_term: 5]"]
[2019/11/04 00:02:31.721 +08:00] [INFO] [raft.rs:1094] ["[region 2221078] 2221079 is starting a new election at term 5"]
[2019/11/04 00:02:31.721 +08:00] [INFO] [raft.rs:765] ["[region 2221078] 2221079 became pre-candidate at term 5"]
[2019/11/04 00:02:31.721 +08:00] [INFO] [raft.rs:858] ["[region 2221078] 2221079 received MsgRequestPreVoteResponse from 2221079 at term 5"]
[2019/11/04 00:02:31.721 +08:00] [INFO] [raft.rs:832] ["[region 2221078] 2221079 [logterm: 5, index: 5] sent MsgRequestPreVote request to 2221080 at term 5"]
[2019/11/04 00:02:31.721 +08:00] [INFO] [raft.rs:832] ["[region 2221078] 2221079 [logterm: 5, index: 5] sent MsgRequestPreVote request to 2221081 at term 5"]
[2019/11/04 00:02:31.811 +08:00] [INFO] [raft.rs:858] ["[region 2221078] 2221079 received MsgRequestPreVoteResponse from 2221080 at term 5"]
[2019/11/04 00:02:31.811 +08:00] [INFO] [raft.rs:1587] ["[region 2221078] 2221079 [quorum:2] has received 2 MsgRequestPreVoteResponse votes and 0 vote rejections"]
[2019/11/04 00:02:31.811 +08:00] [INFO] [raft.rs:743] ["[region 2221078] 2221079 became candidate at term 6"]
[2019/11/04 00:02:31.811 +08:00] [INFO] [raft.rs:858] ["[region 2221078] 2221079 received MsgRequestVoteResponse from 2221079 at term 6"]
[2019/11/04 00:02:31.811 +08:00] [INFO] [raft.rs:832] ["[region 2221078] 2221079 [logterm: 5, index: 5] sent MsgRequestVote request to 2221080 at term 6"]
[2019/11/04 00:02:31.811 +08:00] [INFO] [raft.rs:832] ["[region 2221078] 2221079 [logterm: 5, index: 5] sent MsgRequestVote request to 2221081 at term 6"]

yilong · 2019 年11 月 8 日 12:41

您好： 1. 在host:172-17-9-20上查看tidb的日志，11月4号最后一次gc时间后的信息，是否还有gc日志 grep gc_worker tidb.log | more 2.在tikv节点上，查看tikv日志的gc信息 grep gc_worker tikv.log | more 3. 能否尝试降低这两个参数的值，不建议配置的值过大，多谢。

pangcm · 2019 年11 月 9 日 01:52

172.17.9.20 上关于GC的日志

这是11月4号最后一次GC后的信息

直到今天，日志主要还是那些比较凌乱的日志

在tikv节点上的日志

这几天的日志文件非常大

最后一次GC的日志

最后一次GC后的日志没有找到这个关键词

参数调整

已经把这两个参数调整为默认值了。

WalterWj · 2019 年11 月 11 日 03:28

整体我看了下，最优一个 error failed gc，err=Engine(Timeout(10s)),这个报错一般是指 TIKV 过忙，取 snapshot 超时。不过一般 gc 的时候个别 region 失败没什么影响。
能否匹配下 tidb.log 中 gc_worker 和 error 关键字(gc_work 是 tidb owner 执行的)，看一下是否有其他类型报错
还有就是可以看下 TIKV 的网络、CPU(TIKV 监控 Thread CPU里面的内容，可以截图下)，IO 是否使用率都很高。

还有就是我们调整参数回去之后，是否变正常呢？

pangcm · 2019 年11 月 11 日 03:56

在上周五的时候我们增加了两个TiKV节点，并且在11月11日凌晨balance region结束。所以现在的raft cpu比之前的要低点，IO的话与之前差不多。增加节点之前的IO使用率也大概在50%—60%之间。

调整了参数之后并没有恢复正常，GC的状态依然没有什么变化。

1.tidb.log的日志

过去几天的错误日志基本都是这个 region epoch is ahead of tikv，日志非常多。

2.TiKV的监控截图（过去6小时）

raft cpu的占用在增加TiKV节点之前大概为130%，目前基本在110%以内。
IO使用率一直都在60%上下波动的。

WalterWj · 2019 年11 月 11 日 05:17

可以 grep gc_worker tidb.log |grep error > gc_error.log ，我这边需要看下 gc 相关报错。

pangcm · 2019 年11 月 11 日 06:07

这是筛选的日志内容

gc_error.log.gz (1.5 MB)

WalterWj · 2019 年11 月 11 日 08:07

重启下 tidb gc leader 的 tidb-server
select * from mysql.tidb where VARIABLE_NAME=‘tikv_gc_leader_desc’; 这个可以确认 gc leader

WalterWj · 2019 年11 月 11 日 08:17

看了下错误日志，初步判断原因是 gc 的时候拿 region cache，但是这个 cache 有问题，卡住了 gc。
可以重启 tidb gc leader 尝试修复。具体原因排查我们可能需要知道，store id 为 733265 733266 76572 这三台tikv 在问题刚发生那段时间前后的日志。如果可以，辛苦发下

pangcm · 2019 年11 月 11 日 08:49

我们接下来会重启gc leader 的tidb节点看下怎样，并且会把并发数调整为8.

下面是这三个tikv节点的日志，截取了事件前后一共20万行。

tikv_76572.log.gz (2.5 MB) tikv_733265.log.gz (2.1 MB) tikv_733266.log.gz (2.6 MB)

WalterWj · 2019 年11 月 11 日 08:53

OK，有消息及时同步。

Zj-PingCAP · 2019 年11 月 11 日 11:00

请问 172.17.9.30:20160 是哪台 TiKV？根据日志，这台 TiKV 在出问题的时间点附近曾经有一段时间无法连接。是手动操作导致的吗？如果不是，希望也可以提供一下这台机器在那段时间的日志。

Zj-PingCAP · 2019 年11 月 11 日 11:11

另外麻烦提供一下 pd-ctl 执行命令 region 2216497 的输出，以及在出问题的那段时间以及更早之前一两个小时内的 pd leader 的日志

pangcm · 2019 年11 月 11 日 11:37

172.17.9.30:20160就是ID为76572的TiKV。那个时间点我们没有做任何的手动操作。
region 2216497 的输出

{
  "id": 2216497,
  "start_key": "748000000000000FFF8C5F698000000000FF0000020003800000FF010C36035C000000FC",
  "end_key": "748000000000000FFF8C5F698000000000FF0000020003800000FF010C5DC559000000FC",
  "epoch": {
    "conf_ver": 4244,
    "version": 3202
  },
  "peers": [
    {
      "id": 2216498,
      "store_id": 733265
    },
    {
      "id": 2216499,
      "store_id": 733266
    },
    {
      "id": 2216500,
      "store_id": 76572
    }
  ],
  "leader": {
    "id": 2216499,
    "store_id": 733266
  },
  "written_bytes": 481,
  "approximate_size": 1,
  "approximate_keys": 724157
}

pd leader的日志

pd_172.17.9.20.log.gz (3.7 MB)

Zj-PingCAP · 2019 年11 月 11 日 11:59

刚刚说的3个tikv，可以的话麻烦提供一下更早一个小时的日志

pangcm · 2019 年11 月 12 日 02:16

更早之前的日志

tikv_76572_1104.log.gz (4.6 MB) tikv_733265_1104.log.gz (4.5 MB) tikv_733266_1104.log.gz (4.4 MB)

pangcm · 2019 年11 月 12 日 03:22

TiKV节点出问题的可能性很大，这几天 IP为 172.17.9.30 ，id为 76572 的TiKV节点的日志非常大（一天9G），监控上也显示了大量的 raftstore error。

此外，在系统日志上看到在11月4号2点21分的时候，这个节点自动重启了。所以就出现了前面你们说到的连接不到该节点的情况。

这种情况下，我们是不是可以尝试重启这个KV节点去处理呢？还有就是哪里能看到这个节点的健康状况呢？

Zj-PingCAP · 2019 年11 月 12 日 03:29

重启的问题我们刚刚在 tikv 的日志里也看到了，是由于一个 merge 的 bug 导致的。关于这个问题，建议升级到 3.0.5。

前面 GC 卡住的问题也与此有关，这边需要继续查。

上面图里的大量的 epoch not match 则是 GC 卡住的问题导致的。昨天我们建议重启 gc leader，重启过了吗？如果重启 gc leader 后 GC 恢复正常，那么这个错误应当也消失了。