pingcap / pingcap/tidb

session panic due to Out Of Memory Quota

Open
#32,624 0 comments 0 reactions 0 assignees View on GitHub
severity/moderate sig/execution type/bug
Dominant language
Go
Stars
40.5k
Forks
6.2k
PR merge metrics
PR metrics pending

Description

## Bug Report

Please answer these questions before submitting your issue. Thanks!

### 1. Minimal reproduce step (Required)

run tipocket case:ledger -run-time=6h -tikv-replicas=4 -nemesis=random_kill,kill_tikv_1node_5min,shuffle-leader-scheduler,shuffle-region-scheduler,random-merge-scheduler,subcritical_skews

case log:
http://172.16.4.180:31714/archived-workflows/test-store/2f2dcac2-1f9a-4770-8e62-2cbf4d51ff09
http://172.16.4.180:31714/archived-workflows/test-store/32d60380-2d4f-4f81-b284-55f5865ae154

### 2. What did you expect to see? (Required)

case run success.

### 3. What did you see instead (Required)

case failed,connection panic,tidb log as follow:
[2022/02/23 01:54:42.912 +00:00] [ERROR] [client.go:893] ["[pd] update connection contexts failed"] [dc=global] [error="rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.233.87.251:2379: connect: connection refused\""]
[2022/02/23 01:54:43.913 +00:00] [INFO] [client.go:774] ["[pd] tso stream is not ready"] [dc=global]
[2022/02/23 01:54:44.704 +00:00] [INFO] [ddl_tiflash_api.go:204] ["updateTiFlashStores finished"] ["TiFlash store count"=0]
[2022/02/23 01:54:45.078 +00:00] [INFO] [coprocessor.go:849] ["[TIME_COP_PROCESS] resp_time:4m27.367767273s txnStartTS:431379053687865411 region_id:27041 store_addr:tipocket-ledger1-tikv-1.tipocket-ledger1-tikv-peer.tipocket-ledger1-1645560000.svc:20160 backoff_ms:987 backoff_types:[regionMiss,tikvRPC,tikvRPC,tikvRPC,tikvRPC] kv_process_ms:25803 kv_wait_ms:209 kv_read_ms:0 processed_versions:641307 total_versions:642243 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:642242 rocksdb_cache_hit_count:796 rocksdb_read_count:0 rocksdb_read_byte:0"]
[2022/02/23 01:54:46.315 +00:00] [INFO] [coprocessor.go:849] ["[TIME_COP_PROCESS] resp_time:4m13.831623778s txnStartTS:431379187040256001 region_id:2 store_addr:tipocket-ledger1-tikv-1.tipocket-ledger1-tikv-peer.tipocket-ledger1-1645560000.svc:20160 backoff_ms:1160 backoff_types:[tikvRPC,tikvRPC,tikvRPC,tikvRPC] kv_process_ms:12347 kv_wait_ms:62 kv_read_ms:5152 processed_versions:837542 total_versions:1303229 rocksdb_delete_skipped_count:24026 rocksdb_key_skipped_count:1350651 rocksdb_cache_hit_count:1146 rocksdb_read_count:2 rocksdb_read_byte:30947"] [conn=921]
[2022/02/23 01:54:48.857 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1375386592] [quota=1073741824] ["total token count"=15] ["remaining token count"=14]
[2022/02/23 01:54:48.896 +00:00] [INFO] [coprocessor.go:849] ["[TIME_COP_PROCESS] resp_time:3.815095391s txnStartTS:431379053687865411 region_id:31461 store_addr:tipocket-ledger1-tikv-0.tipocket-ledger1-tikv-peer.tipocket-ledger1-1645560000.svc:20160 kv_process_ms:3806 kv_wait_ms:1 kv_read_ms:0 processed_versions:647688 total_versions:648698 rocksdb_delete_skipped_count:565 rocksdb_key_skipped_count:1296480 rocksdb_cache_hit_count:1604 rocksdb_read_count:1 rocksdb_read_byte:65492"]
[2022/02/23 01:54:48.909 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1363089240] [quota=1073741824] ["total token count"=15] ["remaining token count"=13]
[2022/02/23 01:54:48.929 +00:00] [ERROR] [client.go:893] ["[pd] update connection contexts failed"] [dc=global] [error="rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.233.87.251:2379: connect: connection refused\""]
[2022/02/23 01:54:49.005 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1342027826] [quota=1073741824] ["total token count"=15] ["remaining token count"=12]
[2022/02/23 01:54:49.100 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1320700184] [quota=1073741824] ["total token count"=15] ["remaining token count"=11]
[2022/02/23 01:54:49.204 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1299678345] [quota=1073741824] ["total token count"=15] ["remaining token count"=10]
[2022/02/23 01:54:49.296 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1278673214] [quota=1073741824] ["total token count"=15] ["remaining token count"=9]
[2022/02/23 01:54:49.411 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1234864943] [quota=1073741824] ["total token count"=15] ["remaining token count"=8]
[2022/02/23 01:54:49.524 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1234864726] [quota=1073741824] ["total token count"=15] ["remaining token count"=7]
[2022/02/23 01:54:49.684 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1212345309] [quota=1073741824] ["total token count"=15] ["remaining token count"=6]
[2022/02/23 01:54:49.865 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1189857436] [quota=1073741824] ["total token count"=15] ["remaining token count"=5]
[2022/02/23 01:54:49.932 +00:00] [INFO] [client.go:774] ["[pd] tso stream is not ready"] [dc=global]
[2022/02/23 01:54:49.978 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1168977049] [quota=1073741824] ["total token count"=15] ["remaining token count"=4]
[2022/02/23 01:54:50.099 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1145725215] [quota=1073741824] ["total token count"=15] ["remaining token count"=3]
[2022/02/23 01:54:50.223 +00:00] [INFO] [coprocessor.go:1250] ["memory exceeds quota, destroy one token now."] [consumed=1123580874] [quota=1073741824] ["total token count"=15] ["remaining token count"=2]
[2022/02/23 01:54:50.321 +00:00] [INFO] [coprocessor.go:1236] ["memory exceeds quota, rateLimitAction delegate to fallback action"] ["total token count"=15]
[2022/02/23 01:54:50.321 +00:00] [INFO] [row_container.go:367] ["memory exceeds quota, spill to disk now."] [consumed=1102463887] [quota=1073741824]
[2022/02/23 01:54:51.553 +00:00] [INFO] [coprocessor.go:849] ["[TIME_COP_PROCESS] resp_time:2.654399468s txnStartTS:431379053687865411 region_id:31645 store_addr:tipocket-ledger1-tikv-2.tipocket-ledger1-tikv-peer.tipocket-ledger1-1645560000.svc:20160 kv_process_ms:2647 kv_wait_ms:0 kv_read_ms:0 processed_versions:704037 total_versions:704539 rocksdb_delete_skipped_count:0 rocksdb_key_skipped_count:704538 rocksdb_cache_hit_count:872 rocksdb_read_count:0 rocksdb_read_byte:0"]
[2022/02/23 01:54:52.268 +00:00] [INFO] [coprocessor.go:849] ["[TIME_COP_PROCESS] resp_time:1.477154799s txnStartTS:431379187040256001 region_id:103699 store_addr:tipocket-ledger1-tikv-3.tipocket-ledger1-tikv-peer.tipocket-ledger1-1645560000.svc:20160 kv_process_ms:1407 kv_wait_ms:1 kv_read_ms:1212 processed_versions:697528 total_versions:1005389 rocksdb_delete_skipped_count:10408 rocksdb_key_skipped_count:1012074 rocksdb_cache_hit_count:1044 rocksdb_read_count:3 rocksdb_read_byte:196474"] [conn=921]
[2022/02/23 01:54:52.268 +00:00] [WARN] [expensivequery.go:179] [expensive_query] [cost_time=287.004073116s] [cop_time=287.249614309s] [process_time=873.534s] [wait_time=1.616s] [backoff_time=4.504s] [request_count=32] [total_keys=22482336] [process_keys=20989066] [num_cop_tasks=32] [process_avg_time=27.2979375s] [process_p90_time=46.997s] [process_max_time=52.092s] [process_max_addr=tipocket-ledger1-tikv-1.tipocket-ledger1-tikv-peer.tipocket-ledger1-1645560000.svc:20160] [wait_avg_time=0.0505s] [wait_p90_time=0.084s] [wait_max_time=0.495s] [wait_max_addr=tipocket-ledger1-tikv-1.tipocket-ledger1-tikv-peer.tipocket-ledger1-1645560000.svc:20160] [stats=ledger_accounts:431379177944121382] [conn_id=921] [user=root] [database=test] [table_ids="[65,65]"] [txn_start_ts=431379187040256001] [mem_max="1385689313 Bytes (1.29 GB)"] [sql="select sum(balance) total from\n (select account_id, max(causality_id) max_causality_id from ledger_accounts group by account_id) last\n join ledger_accounts\n on last.account_id = ledger_accounts.account_id and last.max_causality_id = ledger_accounts.causality_id"]
[2022/02/23 01:54:52.268 +00:00] [ERROR] [coprocessor.go:660] ["copIteratorWork meet panic"] [r="\"Out Of Memory Quota![conn_id=921]\""] ["stack trace"="github.com/pingcap/tidb/store/copr.(*copIteratorWorker).handleTask.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:662\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:965\ngithub.com/pingcap/tidb/util/memory.(*PanicOnExceed).Action\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/memory/action.go:129\ngithub.com/pingcap/tidb/util/chunk.(*SpillDiskAction).Action\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/chunk/row_container.go:393\ngithub.com/pingcap/tidb/store/copr.(*rateLimitAction).Action\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:1227\ngithub.com/pingcap/tidb/store/copr.(*rateLimitAction).Action\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:1227\ngithub.com/pingcap/tidb/util/memory.(*Tracker).Consume.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/memory/tracker.go:336\ngithub.com/pingcap/tidb/util/memory.(*Tracker).Consume\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/memory/tracker.go:344\ngithub.com/pingcap/tidb/store/copr.(*copIteratorWorker).sendToRespCh\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:550\ngithub.com/pingcap/tidb/store/copr.(*copIteratorWorker).handleCopResponse\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:1016\ngithub.com/pingcap/tidb/store/copr.(*copIteratorWorker).handleTaskOnce\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:789\ngithub.com/pingcap/tidb/store/copr.(*copIteratorWorker).handleTask\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:673\ngithub.com/pingcap/tidb/store/copr.(*copIteratorWorker).run\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:414"]
[2022/02/23 01:54:52.284 +00:00] [INFO] [conn.go:1119] ["command dispatched failed"] [conn=921] [connInfo="id:921, addr:10.233.123.197:49820 status:11, collation:utf8mb4_general_ci, user:root"] [command=Query] [status="inTxn:1, autocommit:1"] [sql="\nselect sum(balance) total from\n (select account_id, max(causality_id) max_causality_id from ledger_accounts group by account_id) last\n join ledger_accounts\n on last.account_id = ledger_accounts.account_id and last.max_causality_id = ledger_accounts.causality_id"] [txn_mode=PESSIMISTIC] [timestamp=431379187040256001] [err="Out Of Memory Quota![conn_id=921]\ngithub.com/pingcap/tidb/store/copr.(*copIteratorWorker).handleTask.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:663\nruntime.gopanic\n\t/usr/local/go/src/runtime/panic.go:965\ngithub.com/pingcap/tidb/util/memory.(*PanicOnExceed).Action\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/memory/action.go:129\ngithub.com/pingcap/tidb/util/chunk.(*SpillDiskAction).Action\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/chunk/row_container.go:393\ngithub.com/pingcap/tidb/store/copr.(*rateLimitAction).Action\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:1227\ngithub.com/pingcap/tidb/store/copr.(*rateLimitAction).Action\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:1227\ngithub.com/pingcap/tidb/util/memory.(*Tracker).Consume.func1\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/memory/tracker.go:336\ngithub.com/pingcap/tidb/util/memory.(*Tracker).Consume\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/util/memory/tracker.go:344\ngithub.com/pingcap/tidb/store/copr.(*copIteratorWorker).sendToRespCh\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:550\ngithub.com/pingcap/tidb/store/copr.(*copIteratorWorker).handleCopResponse\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:1016\ngithub.com/pingcap/tidb/store/copr.(*copIteratorWorker).handleTaskOnce\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:789\ngithub.com/pingcap/tidb/store/copr.(*copIteratorWorker).handleTask\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:673\ngithub.com/pingcap/tidb/store/copr.(*copIteratorWorker).run\n\t/home/jenkins/agent/workspace/build-common/go/src/github.com/pingcap/tidb/store/copr/coprocessor.go:414\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1371"]
[2022/02/23 01:54:54.708 +00:00] [INFO] [ddl_tiflash_api.go:204] ["updateTiFlashStores finished"] ["TiFlash store count"=0]
[2022/02/23 01:54:54.935 +00:00] [ERROR] [client.go:893] ["[pd] update connection contexts failed"] [dc=global] [error="rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing dial tcp 10.233.87.251:2379: connect: connection refused\""]
[2022/02/23 01:54:54.935 +00:00] [ERROR] [client.go:778] ["[pd] create tso stream error"] [dc-location=global] [error="[PD:client:ErrClientCreateTSOStream]create TSO stream failed, retry timeout"]

### 4. What is your TiDB version? (Required)

[2022/02/22 20:01:31.011 +00:00] [INFO] [printer.go:34] ["Welcome to TiDB."] ["Release Version"=v5.5.0-nightly] [Edition=Community] ["Git Commit Hash"=5bbd7099143e840636486ea6940c576086942409] ["Git Branch"=heads/refs/tags/v5.5.0-nightly] ["UTC Build Time"="2022-02-22 18:12:56"] [GoVersion=go1.16.4] ["Race Enabled"=false] ["Check Table Before Drop"=false] ["TiKV Min Version"=v3.0.0-60965b006877ca7234adaced7890d7b029ed1306]

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.