Too many “EventFeed retry rate limited” logs

[overvenus]

What did you do?

TiKV was OOM, and then TiCDC prints many "EventFeed retry rate limited" log.

[2021/12/17 16:46:23.117 +08:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=4037] [regionID=370191] [startKey=7480000000000019ff595f720000000000fa] [endKey=7480000000000019ff595f730000000000fa] [checkpointTs=429845584546889806]
[2021/12/17 16:46:23.122 +08:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=1195] [regionID=370191] [startKey=748000000000000dff0b5f720000000000fa] [endKey=748000000000000dff0b5f730000000000fa] [checkpointTs=429845584546889806]
[2021/12/17 16:46:23.123 +08:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=4539] [regionID=370191] [startKey=748000000000002cff0d5f720000000000fa] [endKey=748000000000002cff0d5f730000000000fa] [checkpointTs=429845584546889806]
[2021/12/17 16:46:23.123 +08:00] [INFO] [region_cache.go:875] ["switch region peer to next due to send request fail"] [current="region ID: 370191, meta: id:370191 start_key:\"t\\200\\000\\000\\000\\000\\000\\001\\377\\311_r\\200\\000\\000\\000\\000\\377\\006h\\020\\000\\0
00\\000\\000\\000\\372\" end_key:\"t\\200\\000\\000\\000\\000\\000o\\377+_i\\200\\000\\000\\000\\000\\377\\000\\000\\001\\0011073\\3779\\000\\000\\000\\374\\003\\200\\000\\377\\000\\000\\000~\\346\\037\\000\\000\\375\" region_epoch:<conf_ver:41 version:44273 > peers:<id:3
70193 store_id:9 > peers:<id:2700356 store_id:526219 > peers:<id:2739915 store_id:526220 > , peer: id:2700356 store_id:526219 , addr: 172.16.6.46:22161, idx: 1, reqStoreType: TiKvOnly, runStoreType: tikv"] [needReload=false] [error="[CDC:ErrEventFeedAborted]single event f
eed aborted"]
[2021/12/17 16:46:23.123 +08:00] [INFO] [region_range_lock.go:218] ["range locked"] [lockID=1195] [regionID=370191] [startKey=748000000000000dff0b5f720000000000fa] [endKey=748000000000000dff0b5f730000000000fa] [checkpointTs=429845584546889806]
[2021/12/17 16:46:23.123 +08:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=153] [regionID=370191] [startKey=7480000000000038ff2f5f720000000000fa] [endKey=7480000000000038ff2f5f730000000000fa] [checkpointTs=429845584546889806]
[2021/12/17 16:46:23.123 +08:00] [INFO] [client.go:692] ["creating new stream to store to send request"] [regionID=370191] [requestID=14725] [storeID=526220] [addr=172.16.6.47:22161]
[2021/12/17 16:46:23.123 +08:00] [INFO] [client.go:976] ["EventFeed retry rate limited"] [regionID=370191]
[2021/12/17 16:46:23.125 +08:00] [INFO] [region_range_lock.go:370] ["unlocked range"] [lockID=3723] [regionID=370191] [startKey=7480000000000058ff675f720000000000fa] [endKey=7480000000000058ff675f730000000000fa] [checkpointTs=429845584546889806]
[2021/12/17 16:46:23.125 +08:00] [INFO] [client.go:976] ["EventFeed retry rate limited"] [regionID=370191]
[2021/12/17 16:46:23.118 +08:00] [INFO] [region_cache.go:875] ["switch region peer to next due to send request fail"] [current="region ID: 370191, meta: id:370191 start_key:\"t\\200\\000\\000\\000\\000\\000\\001\\377\\311_r\\200\\000\\000\\000\\000\\377\\006h\\020\\000\\000\\000\\000\\000\\372\" end_key:\"t\\200\\000\\000\\000\\000\\000o\\377+_i\\200\\000\\000\\000\\000\\377\\000\\000\\001\\0011073\\3779\\000\\000\\000\\374\\003\\200\\000\\377\\000\\000\\000~\\346\\037\\000\\000\\375\" region_epoch:<conf_ver:41 version:44273 > peers:<id:370193 store_id:9 > peers:<id:2700356 store_id:526219 > peers:<id:2739915 store_id:526220 > , peer: id:2700356 store_id:526219 , addr: 172.16.6.46:22161, idx: 1, reqStoreType: TiKvOnly, runStoreType: tikv"] [needReload=false] [error="[CDC:ErrEventFeedAborted]single event feed aborted"]
[2021/12/17 16:46:23.117 +08:00] [WARN] [client.go:1127] ["failed to receive from stream"] [addr=172.16.6.46:22161] [storeID=526219] [error="rpc error: code = Unavailable desc = transport is closing"]
...
[2021/12/20 18:04:25.041 +08:00] [INFO] [client.go:976] ["EventFeed retry rate limited"] [regionID=370191]
[2021/12/20 18:04:25.041 +08:00] [INFO] [client.go:976] ["EventFeed retry rate limited"] [regionID=370191]
...
[2021/12/20 18:06:45.066 +08:00] [INFO] [client.go:976] ["EventFeed retry rate limited"] [regionID=370191]
[2021/12/20 18:06:45.116 +08:00] [INFO] [client.go:976] ["EventFeed retry rate limited"] [regionID=370191]

[root@baseline03 ~]# grep 'EventFeed retry rate limited' /cdc-8400/log/cdc.log | wc -l
1927643
[root@baseline03 ~]# grep 'EventFeed retry rate limited' /cdc-8400/log/cdc.log | grep '370191' | wc -l
1927387

What did you expect to see?

No more than 100 repeated logs.

What did you see instead?

See above.

Versions of the cluster

Upstream TiDB cluster version (execute SELECT tidb_version(); in a MySQL client):

master

TiCDC version (execute cdc version):

9ef831fdbb92e7795d20445c50a12238b4e15291

tiflow/cdc/kv/client.go

Line 976 in 9ef831f

log.Info("EventFeed retry rate limited", zap.Uint64("regionID", regionID))