`endless-htap-consistency-chaos` failed

[solotzg]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

https://tcms.pingcap.net/dashboard/executions/plan/7916800

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

result inconsistent tso 462501132822118401, difference: row number: 1, row1: 60509113, row2: 60509112, tikv: [60509113], tiflash: [60509112]

[2025/11/28 11:50:21.640 +08:00] [ERROR] [consistency_test.go:685] ["check consistence error"] ["db name"=db0] [sql="select count(*) from dwm_yl_rt_ssmx_bill_detail"] [realSql="select /*+ use_index(dwm_yl_rt_ssmx_bill_detail,PRIMARY) */  count(*) from dwm_yl_rt_ssmx_bill_detail"] ["prev succ"=493] [error="result inconsistent tso 462501132822118401, difference: row number: 1, row1: 60509113, row2: 60509112, tikv: [60509113], tiflash: [60509112]"] [stack="github.com/pingcap/endless/testcase/tiflash/consistency_test.checkConsistency.func1\n\t/home/jenkins/agent/workspace/endless-master-build/testcase/tiflash/consistency/consistency_test.go:685\ngithub.com/pingcap/endless/testcase/tiflash/consistency_test.checkConsistency.WithGinkgoRecover.func2\n\t/go/pkg/mod/github.com/pingcap/endless@v0.0.0-20251016101934-b4857b163a2c/pkg/util/fastfail.go:18\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/go/pkg/mod/golang.org/x/sync@v0.12.0/errgroup/errgroup.go:78"]

3. What did you see instead (Required)

4. What is your TiFlash version? (Required)

d0b28bd

[JaySon-Huang]

No obvious root cause spot. Many meet lock error happen with the tso=462501132822118401

tiflash-0
# meet lock, read_index region_id=4661;
# meet lock, wait_index region_id=1279,8925,4661,4262,2312,2689,6628,1498; 8 in total
[2025/11/28 11:50:06.756 +08:00] [INFO] [FlashService.cpp:502] ["Handling mpp dispatch request, task: MPP<gather_id:1, query_ts:1764301806737642124, local_query_id:535, server_id:259, start_ts:462501132822118401,task_id:1>, resource_group: default, conn_id: 543171014, conn_alias: "] [source=FlashService] [thread_id=450]
[2025/11/28 11:50:07.148 +08:00] [INFO] [LearnerReadWorker.cpp:436] ["[Learner Read] Batch read index, num_regions=399 num_requests=399 num_stale_read=0 num_cached_index=0 n_unavailable=1 read_cost=390ms start_ts=462501132822118401 unavailable_regions={ids=[{region_id:4661,s:MEET_LOCK,msg:}] locks=[4661(primary_lock: \"..."\nlock_version: 462501132796166160\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\001|\\245\\300\"\nlock_ttl: 3001\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132796166161\n)]}"] [source="MPP<gather_id:1, query_ts:1764301806737642124, local_query_id:535, server_id:259, start_ts:462501132822118401,task_id:1>"] [thread_id=325]
[2025/11/28 11:50:07.149 +08:00] [INFO] [LearnerReadWorker.cpp:538] ["[Learner Read] Finish wait index and resolve locks, wait_cost=0ms n_regions=399 n_unavailable=8 start_ts=462501132822118401 unavailable_regions={ids=[{region_id:6628,s:MEET_LOCK,msg:}|{region_id:1498,s:MEET_LOCK,msg:}|{region_id:2312,s:MEET_LOCK,msg:}|{region_id:2689,s:MEET_LOCK,msg:}|{region_id:4262,s:MEET_LOCK,msg:}] locks=[4661(primary_lock: \"..."\nlock_version: 462501132796166160\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\001|\\245\\300\"\nlock_ttl: 3001\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132796166161\n)|1279(primary_lock: \"..."\nlock_version: 462501132782796801\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\003\\232Y\\017\"\nlock_ttl: 3000\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132782796802\n)|8925(primary_lock: \"..."\nlock_version: 462501132730368020\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\003_l\\376\"\nlock_ttl: 3235\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132796166147\n)|4262(primary_lock: \"..."\nlock_version: 462501132769689604\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\001M\\177l\"\nlock_ttl: 3074\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132796166153\n)|2312(primary_lock: \"..."\nlock_version: 462501131891507207\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\000q%\\252\"\nlock_ttl: 6170\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132691046402\n)|2689(primary_lock: \"..."\nlock_version: 462501132730368017\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\000\\233s5\"\nlock_ttl: 3132\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132756582409\n)|6628(primary_lock: \"..."\nlock_version: 462501132769689602\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\002[v\\346\"\nlock_ttl: 3001\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132769689603\n)|1498(primary_lock: \"..."\nlock_version: 462501132796166153\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\000\\025\\344\\362\"\nlock_ttl: 3003\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132796166154\n)]}"] [source="MPP<gather_id:1, query_ts:1764301806737642124, local_query_id:535, server_id:259, start_ts:462501132822118401,task_id:1>"] [thread_id=325]
[2025/11/28 11:50:07.156 +08:00] [INFO] [RemoteRequest.cpp:35] ["Start to build remote request for 8 regions (1279,8925,4661,4262,2312,2689,6628,1498) for table 116"] [source="MPP<gather_id:1, query_ts:1764301806737642124, local_query_id:535, server_id:259, start_ts:462501132822118401,task_id:1>"] [thread_id=325]

# tiflash-1
# meet lock, read_index region_id=8971;
# meet lock, wait_index region_id=3859,4826,8971; 3 in total
[2025/11/28 11:50:07.634 +08:00] [INFO] [LearnerReadWorker.cpp:436] ["[Learner Read] Batch read index, num_regions=387 num_requests=387 num_stale_read=0 num_cached_index=0 n_unavailable=1 read_cost=877ms start_ts=462501132822118401 unavailable_regions={ids=[{region_id:8971,s:MEET_LOCK,msg:}] locks=[8971(primary_lock: \"..."\nlock_version: 462501132756582401\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\003dd\\254\"\nlock_ttl: 3178\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132796166160\n)]}"] [source="MPP<gather_id:1, query_ts:1764301806737642124, local_query_id:535, server_id:259, start_ts:462501132822118401,task_id:2>"] [thread_id=286]
[2025/11/28 11:50:07.637 +08:00] [INFO] [LearnerReadWorker.cpp:538] ["[Learner Read] Finish wait index and resolve locks, wait_cost=2ms n_regions=387 n_unavailable=3 start_ts=462501132822118401 unavailable_regions={ids=[{region_id:3859,s:MEET_LOCK,msg:}|{region_id:4826,s:MEET_LOCK,msg:}|{region_id:8971,s:MEET_LOCK,msg:}] locks=[8971(primary_lock: \"..."\nlock_version: 462501132756582401\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\003dd\\254\"\nlock_ttl: 3178\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132796166160\n)|4826(primary_lock: \"..."\nlock_version: 462501131891507201\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\001\\216.\\222\"\nlock_ttl: 6176\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132730368024\n)|3859(primary_lock: \"..."\nlock_version: 462501132730368010\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\001\\037\\254l\"\nlock_ttl: 3003\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132730368017\n)]}"] [source="MPP<gather_id:1, query_ts:1764301806737642124, local_query_id:535, server_id:259, start_ts:462501132822118401,task_id:2>"] [thread_id=286]
[2025/11/28 11:50:08.379 +08:00] [INFO] [RemoteRequest.cpp:35] ["Start to build remote request for 3 regions (8971,4826,3859) for table 116"] [source="MPP<gather_id:1, query_ts:1764301806737642124, local_query_id:535, server_id:259, start_ts:462501132822118401,task_id:2>"] [thread_id=286]

# tiflash-2
# meet lock, read_index region_id=7546;
# meet lock, wait_index region_id=7546,4957,3637,4411,4390,2533,9235,8787,5341,1947; 10 in total
[2025/11/28 11:50:06.892 +08:00] [INFO] [LearnerReadWorker.cpp:436] ["[Learner Read] Batch read index, num_regions=380 num_requests=380 num_stale_read=0 num_cached_index=0 n_unavailable=1 read_cost=12ms start_ts=462501132822118401 unavailable_regions={ids=[{region_id:7546,s:MEET_LOCK,msg:}] locks=[7546(primary_lock: \"..."\nlock_version: 462501132782796802\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\002\\30268\"\nlock_ttl: 3001\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132782796805\n)]}"] [source="MPP<gather_id:1, query_ts:1764301806737642124, local_query_id:535, server_id:259, start_ts:462501132822118401,task_id:3>"] [thread_id=367]
[2025/11/28 11:50:06.907 +08:00] [INFO] [LearnerReadWorker.cpp:538] ["[Learner Read] Finish wait index and resolve locks, wait_cost=14ms n_regions=380 n_unavailable=10 start_ts=462501132822118401 unavailable_regions={ids=[{region_id:8787,s:MEET_LOCK,msg:}|{region_id:5341,s:MEET_LOCK,msg:}|{region_id:9235,s:MEET_LOCK,msg:}|{region_id:2533,s:MEET_LOCK,msg:}|{region_id:4390,s:MEET_LOCK,msg:}] locks=[7546(primary_lock: \"..."\nlock_version: 462501132782796802\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\002\\30268\"\nlock_ttl: 3001\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132782796805\n)|4957(primary_lock: \"..."\nlock_version: 462501132756582407\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\001\\234k\\306\"\nlock_ttl: 3001\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132756582408\n)|3637(primary_lock: \"..."\nlock_version: 462501132730368011\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\001\\006\\332\\205\"\nlock_ttl: 3245\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132782796802\n)|4411(primary_lock: \"..."\nlock_version: 462501131891507202\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\001^\\351=\"\nlock_ttl: 3005\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501131891507203\n)|4390(primary_lock: \"..."\nlock_version: 462501132796166150\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\001\\\\@\\341\"\nlock_ttl: 3001\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132796166161\n)|2533(primary_lock: \"..."\nlock_version: 462501131590041613\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\000\\212V\\215\"\nlock_ttl: 3003\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501131873943554\n)|9235(primary_lock: \"..."\nlock_version: 462501132730368006\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\003\\202\\214)\"\nlock_ttl: 3005\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132730368017\n)|8787(primary_lock: \"..."\nlock_version: 462501131603148803\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\003Mi\\213\"\nlock_ttl: 7275\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501132782796805\n)|5341(primary_lock: \"..."\nlock_version: 462501131786649625\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\001\\307\\272m\"\nlock_ttl: 3295\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501131943936009\n)|1947(primary_lock: \"..."\nlock_version: 462501131891507209\nkey: \"t\\200\\000\\000\\000\\000\\000\\000t_r\\200\\000\\000\\000\\000Ho\\031\"\nlock_ttl: 3001\ntxn_size: 1\nuse_async_commit: true\nmin_commit_ts: 462501131943936009\n)]}"] [source="MPP<gather_id:1, query_ts:1764301806737642124, local_query_id:535, server_id:259, start_ts:462501132822118401,task_id:3>"] [thread_id=367]
[2025/11/28 11:50:06.916 +08:00] [INFO] [RemoteRequest.cpp:35] ["Start to build remote request for 10 regions (7546,4957,3637,4411,4390,2533,9235,8787,5341,1947) for table 116"] [source="MPP<gather_id:1, query_ts:1764301806737642124, local_query_id:535, server_id:259, start_ts:462501132822118401,task_id:3>"] [thread_id=367]

tiflash version

[2025/11/28 02:15:59.002 +08:00] [INFO] [BaseDaemon.cpp:1158] ["TiFlash build info: TiFlash\nRelease Version: v9.0.0-beta.2.pre-89-gd0b28bd1c\nEdition:         Community\nGit Commit Hash: d0b28bd1c47167725f1a6e4111ece4b41a5e3230\nGit Branch:      HEAD\nUTC Build Time:  2025-11-27 10:15:00\nEnable Features: jemalloc sm4(GmSSL) mem-profiling avx2 avx512 unwind thinlto hnsw.l2=skylake hnsw.cosine=skylake vec.l2=skylake vec.cos=skylake\nProfile:         RELWITHDEBINFO\nCompiler:        clang++ 17.0.6\n"] [thread_id=1]

tidb version

[2025/11/28 02:16:33.856 +08:00] [INFO] [printer.go:54] ["Welcome to TiDB."] ["Release Version"=v9.0.0-beta.2.pre-830-ga3de287] [Edition=Community] ["Git Commit Hash"=a3de2875ae27fdfcb88de0f16a74feef37818f9c] ["Git Branch"=HEAD] ["UTC Build Time"="2025-11-27 15:09:50"] [GoVersion=go1.23.12] ["Race Enabled"=false] ["Check Table Before Drop"=false] ["Kernel Type"=Classic]

[2025/11/28 11:13:09.231 +08:00] [INFO] [chaos.go:83] ["begin to select tiflash to shutdown instance"] [selector=endless-htap-consistency-chaos-tps-7916800-1-296/tc-tiflash-1]
[2025/11/28 11:13:09.283 +08:00] [INFO] [chaos.go:149] ["ns=endless-htap-consistency-chaos-tps-7916800-1-296,kind=schedules,name=pod-failure-uluhvqhc,spec=&k8s.ChaosIdentifier{Namespace:\"endless-htap-consistency-chaos-tps-7916800-1-296\", Name:\"pod-failure-uluhvqhc\", Spec:FailureExperimentSpec{Duration: \"5m\", Scheduler: ExperimentScheduler{Cron: \"@every 15m\"}}}"]
....
[2025/11/28 11:28:09.283 +08:00] [INFO] [chaos.go:156] ["delete chaos"] ["chaos info"="ns=endless-htap-consistency-chaos-tps-7916800-1-296,kind=schedules,name=pod-failure-uluhvqhc,spec=&k8s.ChaosIdentifier{Namespace:\"endless-htap-consistency-chaos-tps-7916800-1-296\", Name:\"pod-failure-uluhvqhc\", Spec:FailureExperimentSpec{Duration: \"5m\", Scheduler: ExperimentScheduler{Cron: \"@every 15m\"}}}"]
....
[2025/11/28 11:50:21.640 +08:00] [ERROR] [consistency_test.go:685] ["check consistence error"] ["db name"=db0] [sql="select count(*) from dwm_yl_rt_ssmx_bill_detail"] [realSql="select /*+ use_index(dwm_yl_rt_ssmx_bill_detail,PRIMARY) */  count(*) from dwm_yl_rt_ssmx_bill_detail"] ["prev succ"=493] [error="result inconsistent tso 462501132822118401, difference: row number: 1, row1: 60509113, row2: 60509112, tikv: [60509113], tiflash: [60509112]"] [stack="github.com/pingcap/endless/testcase/tiflash/consistency_test.checkConsistency.func1\n\t/home/jenkins/agent/workspace/endless-master-build/testcase/tiflash/consistency/consistency_test.go:685\ngithub.com/pingcap/endless/testcase/tiflash/consistency_test.checkConsistency.WithGinkgoRecover.func2\n\t/go/pkg/mod/github.com/pingcap/endless@v0.0.0-20251016101934-b4857b163a2c/pkg/util/fastfail.go:18\ngolang.org/x/sync/errgroup.(*Group).Go.func1\n\t/go/pkg/mod/golang.org/x/sync@v0.12.0/errgroup/errgroup.go:78"]
....
[2025/11/28 11:50:21.641 +08:00] [INFO] [chaos.go:156] ["delete chaos"] ["chaos info"="ns=endless-htap-consistency-chaos-tps-7916800-1-296,kind=schedules,name=pod-failure-uluhvqhc,spec=&k8s.ChaosIdentifier{Namespace:\"endless-htap-consistency-chaos-tps-7916800-1-296\", Name:\"pod-failure-uluhvqhc\", Spec:FailureExperimentSpec{Duration: \"5m\", Scheduler: ExperimentScheduler{Cron: \"@every 15m\"}}}"]