Memory usage surges during redo apply recently

[fubinzh]

What did you do?

During recent testing we found that cdc consumes more memory during redo apply and results in OOM issue.

What did you expect to see?

redo apply memory usage should be stable.

What did you see instead?

4/11 memory usage:

[root@upstream-ticdc-0 /]# /cdc  redo  apply "--sink-uri=mysql://root:@downstream-tidb.cdc-testbed-tps-7566087-1-319:4000" "--storage=s3://tmp/test-infra-redolog/redo-apply-multiple-workload-node-restart-sync-90c0bc8f-323c-41f6-b662-706b847c6d4e?access-key=xxx&secret-access-key=xxx&endpoint=http://minio-peer:9000&force-path-style=true" "--tmp-dir=/tmp/1"
[2024/04/10 11:04:13.471 +00:00] [INFO] [helper.go:54] ["init log"] [file=] [level=info]
[2024/04/10 11:04:13.475 +00:00] [INFO] [s3.go:407] ["succeed to get bucket region from s3"] ["bucket region"=us-east-1]
[2024/04/10 11:04:13.737 +00:00] [INFO] [mem_quota.go:82] ["New memory quota"] [namespace=default] [changefeed=redo-applier] [total=1073741824]
[2024/04/10 11:04:13.737 +00:00] [INFO] [redo.go:163] ["apply redo log starts"] [checkpointTs=448985877505376323] [resolvedTs=448986017647558699]
[2024/04/10 11:04:13.738 +00:00] [INFO] [s3.go:407] ["succeed to get bucket region from s3"] ["bucket region"=us-east-1]
[2024/04/10 11:04:13.738 +00:00] [INFO] [tz.go:35] ["Use the timezone of the TiCDC server machine"] [timezoneName=System] [timezone=UTC]
[2024/04/10 11:04:13.738 +00:00] [WARN] [config.go:381] ["Because time-zone is not specified, the timezone of the TiCDC server will be used. We recommend that you specify the time-zone explicitly. Please make sure that the timezone of the TiCDC server, sink-uri and the downstream datab
ase are consistent. If the downstream database does not load the timezone information, you can refer to https://dev.mysql.com/doc/refman/8.0/en/mysql-tzinfo-to-sql.html."] [timezone=UTC]
[2024/04/10 11:04:13.739 +00:00] [INFO] [s3.go:407] ["succeed to get bucket region from s3"] ["bucket region"=us-east-1]
[2024/04/10 11:04:13.745 +00:00] [INFO] [db_helper.go:173] ["sink uri is configured"] [dsn="root:******@tcp(downstream-tidb.cdc-testbed-tps-7566087-1-319:4000)/?interpolateParams=true&multiStatements=true&allow_auto_random_explicit_insert=1&charset=utf8mb4&foreign_key_checks=0&maxAllow
edPacket=0&readTimeout=2m&sql_mode=%22ALLOW_INVALID_DATES%2CNO_ENGINE_SUBSTITUTION%2CONLY_FULL_GROUP_BY%2CIGNORE_SPACE%2CNO_AUTO_VALUE_ON_ZERO%22&tidb_enable_external_ts_read=%22OFF%22&tidb_placement_mode=%22ignore%22&tidb_txn_mode=optimistic&time_zone=%22UTC%22&timeout=2m&transaction_
isolation=%22READ-COMMITTED%22&writeTimeout=2m"]
[2024/04/10 11:04:13.749 +00:00] [INFO] [mysql.go:197] ["MySQL backends is created"] [changefeed=.] [workerCount=16] [forceReplicate=false]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=0]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=1]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=3]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=2]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=5]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=4]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=8]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=6]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=7]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=9]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=10]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=11]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=13]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=12]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=14]
[2024/04/10 11:04:13.749 +00:00] [INFO] [worker.go:105] ["Transaction dmlSink worker starts"] [changefeedID=.] [workerID=15]
[2024/04/10 11:04:13.750 +00:00] [INFO] [tz.go:35] ["Use the timezone of the TiCDC server machine"] [timezoneName=System] [timezone=UTC]
[2024/04/10 11:04:13.750 +00:00] [WARN] [config.go:381] ["Because time-zone is not specified, the timezone of the TiCDC server will be used. We recommend that you specify the time-zone explicitly. Please make sure that the timezone of the TiCDC server, sink-uri and the downstream datab
ase are consistent. If the downstream database does not load the timezone information, you can refer to https://dev.mysql.com/doc/refman/8.0/en/mysql-tzinfo-to-sql.html."] [timezone=UTC]
[2024/04/10 11:04:13.755 +00:00] [INFO] [db_helper.go:173] ["sink uri is configured"] [dsn="root:******@tcp(downstream-tidb.cdc-testbed-tps-7566087-1-319:4000)/?interpolateParams=true&multiStatements=true&allow_auto_random_explicit_insert=1&charset=utf8mb4&foreign_key_checks=0&maxAllow
edPacket=0&readTimeout=2m&sql_mode=%22NO_ENGINE_SUBSTITUTION%2CONLY_FULL_GROUP_BY%2CIGNORE_SPACE%2CNO_AUTO_VALUE_ON_ZERO%2CALLOW_INVALID_DATES%22&tidb_enable_external_ts_read=%22OFF%22&tidb_placement_mode=%22ignore%22&tidb_txn_mode=optimistic&time_zone=%22UTC%22&timeout=2m&transaction_
isolation=%22READ-COMMITTED%22&writeTimeout=2m"]
[2024/04/10 11:04:13.758 +00:00] [INFO] [mysql_ddl_sink.go:105] ["MySQL DDL sink is created"] [namespace=] [changefeed=]
[2024/04/10 11:04:14.135 +00:00] [INFO] [file.go:114] ["succeed to download and sort redo logs"] [type=ddl] [duration=397.463695ms]
^B%[2024/04/10 11:04:41.134 +00:00] [INFO] [file.go:114] ["succeed to download and sort redo logs"] [type=row] [duration=27.396073836s]

Killed

4/3 memory usage:

Versions of the cluster

Release Version: v8.1.0-alpha
Git Commit Hash: 8a3b776
Git Branch: heads/refs/tags/v8.1.0-alpha
UTC Build Time: 2024-04-09 11:36:29
Go Version: go version go1.21.6 linux/amd64
Failpoint Build: false

[fubinzh]

/severity major

[fubinzh]

/label affects-8.1

[CharlesCheung96]

The root cause of the OOM problem is the inappropriate gc policy, which can be addressed when the GOMEMLIMIT is limited to 8GiB.

In addition, we found some operations that may allocate too much memory, and we will fix them later: