Tikv_gc_last_run_time、tikv_gc_safe_point出现异常

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

  • 系统版本 & 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失败的情况呢?

  • 关键词

GC,region

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

  • 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\n\t/home/jenkins/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb
/privilege/privileges/privileges.go:111\ngithub.com/pingcap/tidb/session.(*session).Auth\n\t/home/jenkins/workspace/release_tidb_3.0/go/src/github.co
m/pingcap/tidb/session/session.go:1342\ngithub.com/pingcap/tidb/server.(*TiDBContext).Auth\n\t/home/jenkins/workspace/release_tidb_3.0/go/src/github.
com/pingcap/tidb/server/driver_tidb.go:285\ngithub.com/pingcap/tidb/server.(*clientConn).openSessionAndDoAuth\n\t/home/jenkins/workspace/release_tidb
_3.0/go/src/github.com/pingcap/tidb/server/conn.go:555\ngithub.com/pingcap/tidb/server.(*clientConn).readOptionalSSLRequestAndHandshakeResponse\n\t/h
ome/jenkins/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb/server/conn.go:532\ngithub.com/pingcap/tidb/server.(*clientConn).handshake\n\t/home/jenkins/workspace/release_tidb_3.0/go/src/github.com/pingcap/tidb/server/conn.go:170\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/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"]

您好: 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. 能否尝试降低这两个参数的值,不建议配置的值过大,多谢。

  • 172.17.9.20 上关于GC的日志

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

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

  • 在tikv节点上的日志

这几天的日志文件非常大

最后一次GC的日志

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

  • 参数调整

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

  • 整体我看了下,最优一个 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 是否使用率都很高。

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

在上周五的时候我们增加了两个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%上下波动的。

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

这是筛选的日志内容

gc_error.log.gz (1.5 MB)

  • 重启下 tidb gc leader 的 tidb-server
  • select * from mysql.tidb where VARIABLE_NAME=‘tikv_gc_leader_desc’; 这个可以确认 gc leader
  • 看了下错误日志,初步判断原因是 gc 的时候拿 region cache,但是这个 cache 有问题,卡住了 gc。
  • 可以重启 tidb gc leader 尝试修复。具体原因排查我们可能需要知道,store id 为 733265 733266 76572 这三台tikv 在问题刚发生那段时间前后的日志。如果可以,辛苦发下

我们接下来会重启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)

  • OK,有消息及时同步。

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

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

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

  2. 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
}

  1. pd leader的日志

pd_172.17.9.20.log.gz (3.7 MB)

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

更早之前的日志

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

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

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

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

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

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

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