pingcap / pingcap/tiflash

MPPTask failed to be cancel for a simple limit query

Open
#10,347 1 comment 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

affects-6.5 component/compute report/customer type/bug
Dominant language
C++
Stars
1k
Forks
423
Avg merge
1d 15h
Merged PRs (30d)
24

Description

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)
2. What did you expect to see? (Required)
3. What did you see instead (Required)

The query is something like

select t.* from t where id=1234 limit 0, 101;

There are two tiflash, only one tiflash meet this problem.

[2025/08/11 14:25:54.046 +08:00] [INFO] [mpp_gather.go:83] ["Dispatch mpp task"] [timestamp=460034815828164615] [ID=1] [address=10.33.56.172:12256] [plan="Table(efi_voucherdtl_entry2025)->Sel([eq(cast(x.y.z, double BINARY), 1.686365039e+09)])->Limit->Send(-1, )"]
[2025/08/11 14:25:54.046 +08:00] [INFO] [mpp_gather.go:83] ["Dispatch mpp task"] [timestamp=460034815828164615] [ID=2] [address=30.88.0.4:12256] [plan="Table(efi_voucherdtl_entry2025)->Sel([eq(cast(x.y.z, double BINARY), 1.686365039e+09)])->Limit->Send(-1, )"]
[2025/08/11 14:25:55.073 +08:00] [WARN] [mpp.go:396] ["establish mpp connection meet error and cannot retry"] [error="rpc error: code = Canceled desc = context canceled"] [timestamp=460034815828164615] [task=2]
[2025/08/11 14:25:55.379 +08:00] [ERROR] [session.go:2671] ["Authentication failed with reason: 1"] [user=m] [host=30.88.47.245] ["auth user"=m] ["auth host"=%]
[2025/08/11 14:25:54.047 +08:00] [INFO] [FlashService.cpp:235] ["Handling mpp dispatch request, task meta: start_ts: 460034815828164615\ntask_id: 2\naddress: \"30.88.0.4:12256\"\n"] [source=FlashService] [thread_id=25842]
[2025/08/11 14:25:54.050 +08:00] [INFO] [FlashService.cpp:291] ["Handling establish mpp connection request: sender_meta {\n  start_ts: 460034815828164615\n  task_id: 2\n  address: \"30.88.0.4:12256\"\n}\nreceiver_meta {\n  start_ts: 460034815828164615\n  task_id: -1\n}\n"] [source=FlashService] [thread_id=721]
[2025/08/11 14:25:54.079 +08:00] [INFO] [DeltaMergeStore.cpp:1602] ["Segment read tasks build done, cost=0ms sorted_ranges=39 n_tasks_before_split=38 n_tasks_final=38 n_ranges_final=76"] [source="table_id=102865 MPP<query:460034815828164615,task:2> table_id=102865"] [thread_id=775]
[2025/08/11 14:25:54.079 +08:00] [INFO] [DeltaMergeStore.cpp:999] ["Read create segment snapshot done, keep_order=false dt_enable_read_thread=true enable_read_thread=true"] [source="table_id=102865 MPP<query:460034815828164615,task:2> table_id=102865"] [thread_id=775]
[2025/08/11 14:25:54.081 +08:00] [INFO] [DeltaMergeStore.cpp:1052] ["Read create stream done, pool_id=40200105 num_streams=24"] [source="table_id=102865 MPP<query:460034815828164615,task:2> table_id=102865"] [thread_id=775]
[2025/08/11 14:25:54.082 +08:00] [INFO] [DeltaMergeStore.cpp:1602] ["Segment read tasks build done, cost=0ms sorted_ranges=2 n_tasks_before_split=1 n_tasks_final=1 n_ranges_final=1"] [source="table_id=102849 MPP<query:460034815828164615,task:2> table_id=102849"] [thread_id=775]
[2025/08/11 14:25:54.082 +08:00] [INFO] [DeltaMergeStore.cpp:999] ["Read create segment snapshot done, keep_order=false dt_enable_read_thread=true enable_read_thread=true"] [source="table_id=102849 MPP<query:460034815828164615,task:2> table_id=102849"] [thread_id=775]
[2025/08/11 14:25:54.082 +08:00] [INFO] [DeltaMergeStore.cpp:1052] ["Read create stream done, pool_id=40200106 num_streams=1"] [source="table_id=102849 MPP<query:460034815828164615,task:2> table_id=102849"] [thread_id=775]
[2025/08/11 14:25:54.082 +08:00] [INFO] [DeltaMergeStore.cpp:1602] ["Segment read tasks build done, cost=0ms sorted_ranges=2 n_tasks_before_split=1 n_tasks_final=1 n_ranges_final=1"] [source="table_id=16909 MPP<query:460034815828164615,task:2> table_id=16909"] [thread_id=775]
[2025/08/11 14:25:54.082 +08:00] [INFO] [DeltaMergeStore.cpp:999] ["Read create segment snapshot done, keep_order=false dt_enable_read_thread=true enable_read_thread=true"] [source="table_id=16909 MPP<query:460034815828164615,task:2> table_id=16909"] [thread_id=775]
[2025/08/11 14:25:54.082 +08:00] [INFO] [DeltaMergeStore.cpp:1052] ["Read create stream done, pool_id=40200107 num_streams=1"] [source="table_id=16909 MPP<query:460034815828164615,task:2> table_id=16909"] [thread_id=775]
[2025/08/11 14:25:54.082 +08:00] [INFO] [DeltaMergeStore.cpp:1602] ["Segment read tasks build done, cost=0ms sorted_ranges=1 n_tasks_before_split=1 n_tasks_final=1 n_ranges_final=1"] [source="table_id=102833 MPP<query:460034815828164615,task:2> table_id=102833"] [thread_id=775]
[2025/08/11 14:25:54.082 +08:00] [INFO] [DeltaMergeStore.cpp:999] ["Read create segment snapshot done, keep_order=false dt_enable_read_thread=true enable_read_thread=true"] [source="table_id=102833 MPP<query:460034815828164615,task:2> table_id=102833"] [thread_id=775]
[2025/08/11 14:25:54.082 +08:00] [INFO] [DeltaMergeStore.cpp:1052] ["Read create stream done, pool_id=40200108 num_streams=1"] [source="table_id=102833 MPP<query:460034815828164615,task:2> table_id=102833"] [thread_id=775]
[2025/08/11 14:25:54.083 +08:00] [INFO] [DeltaMergeStore.cpp:1602] ["Segment read tasks build done, cost=0ms sorted_ranges=1 n_tasks_before_split=1 n_tasks_final=1 n_ranges_final=1"] [source="table_id=16893 MPP<query:460034815828164615,task:2> table_id=16893"] [thread_id=775]
[2025/08/11 14:25:54.083 +08:00] [INFO] [DeltaMergeStore.cpp:999] ["Read create segment snapshot done, keep_order=false dt_enable_read_thread=true enable_read_thread=true"] [source="table_id=16893 MPP<query:460034815828164615,task:2> table_id=16893"] [thread_id=775]
[2025/08/11 14:25:54.083 +08:00] [INFO] [DeltaMergeStore.cpp:1052] ["Read create stream done, pool_id=40200109 num_streams=1"] [source="table_id=16893 MPP<query:460034815828164615,task:2> table_id=16893"] [thread_id=775]
[2025/08/11 14:25:54.084 +08:00] [INFO] [DeltaMergeStore.cpp:1602] ["Segment read tasks build done, cost=0ms sorted_ranges=149 n_tasks_before_split=103 n_tasks_final=103 n_ranges_final=216"] [source="table_id=16885 MPP<query:460034815828164615,task:2> table_id=16885"] [thread_id=775]
[2025/08/11 14:25:54.084 +08:00] [INFO] [DeltaMergeStore.cpp:999] ["Read create segment snapshot done, keep_order=false dt_enable_read_thread=true enable_read_thread=true"] [source="table_id=16885 MPP<query:460034815828164615,task:2> table_id=16885"] [thread_id=775]
[2025/08/11 14:25:54.086 +08:00] [INFO] [DeltaMergeStore.cpp:1052] ["Read create stream done, pool_id=40200110 num_streams=24"] [source="table_id=16885 MPP<query:460034815828164615,task:2> table_id=16885"] [thread_id=775]
[2025/08/11 14:25:54.161 +08:00] [INFO] [executeQuery.cpp:439] ["Query pipeline:\nUnion: <for mpp>\n ExchangeSender x 24\n  Expression: <final projection>\n   SharedQuery: <restore concurrency>\n    Limit, limit = 101\n     Union: <for partial limit>\n      Limit x 24, limit = 101\n       Expression: <table scan schema projection>\n        Expression: <projection after push down filter>\n         Filter: <push down filter>\n          Multiplex\n           UnorderedInputStream x 52\n"] [source=MPP<query:460034815828164615,task:2>] [thread_id=775]
[2025/08/11 14:25:54.161 +08:00] [INFO] [MinTSOScheduler.cpp:271] ["min_tso query is updated from 18446744073709551615 to 460034815828164615 when directly schedule it, used threads = 0, 0 active and 0 waiting queries."] [thread_id=775]
[2025/08/11 14:25:54.161 +08:00] [INFO] [MPPTask.cpp:374] ["task starts running, time cost in schedule: 0 ms, time cost in preprocess 111 ms"] [source=MPP<query:460034815828164615,task:2>] [thread_id=775]
[2025/08/11 14:25:55.073 +08:00] [INFO] [FlashService.cpp:363] ["cancel mpp task request: meta {\n  start_ts: 460034815828164615\n}\n"] [source=FlashService] [thread_id=25538]
[2025/08/11 14:25:55.073 +08:00] [WARN] [MPPTaskManager.cpp:152] ["Begin to abort query: 460034815828164615, abort type: ONCANCELLATION, reason: Receive cancel request from TiDB"] [thread_id=25538]
[2025/08/11 14:25:55.073 +08:00] [INFO] [MinTSOScheduler.cpp:271] ["min_tso query is updated from 460034815828164615 to 18446744073709551615 when cancelling it, used threads = 50, 0 active and 0 waiting queries."] [thread_id=25538]
[2025/08/11 14:25:55.073 +08:00] [WARN] [MPPTaskManager.cpp:195] ["Remaining task in query 460034815828164615 are: MPP<query:460034815828164615,task:2> "] [thread_id=25538]
[2025/08/11 14:25:55.073 +08:00] [WARN] [MPPTask.cpp:478] ["Begin abort task: MPP<query:460034815828164615,task:2>, abort type: ONCANCELLATION"] [source=MPP<query:460034815828164615,task:2>] [thread_id=25538]
[2025/08/11 14:25:55.073 +08:00] [INFO] [EstablishCall.cpp:215] ["connection for tunnel2+-1 cost 1022 ms, including 0 ms to waiting task."] [source="MPP<query:460034815828164615,task:2> tunnel2+-1"] [thread_id=2010]
[2025/08/11 14:25:55.073 +08:00] [WARN] [MPPTask.cpp:507] ["Finish abort task from running"] [source=MPP<query:460034815828164615,task:2>] [thread_id=25538]
[2025/08/11 14:25:55.073 +08:00] [WARN] [MPPTaskManager.cpp:207] ["Finish abort query: 460034815828164615"] [thread_id=25538]
[2025/08/11 14:25:55.074 +08:00] [INFO] [MPPTask.cpp:388] ["mpp task finish execute, success: false, status: CANCELLED"] [source=MPP<query:460034815828164615,task:2>] [thread_id=775]
[2025/08/11 14:25:55.074 +08:00] [INFO] [MPPTaskStatistics.cpp:126] ["{\"query_tso\":460034815828164615,\"task_id\":2,\"is_root\":true,\"sender_executor_id\":\"ExchangeSender_20\",\"executors\":[{\"id\":\"ExchangeSender_20\",\"type\":\"ExchangeSender\",\"children\":[\"Limit_19\"],\"outbound_rows\":8,\"outbound_blocks\":2,\"outbound_bytes\":14456,\"execution_time_ns\":912010069,\"partition_num\":1,\"sender_target_task_ids\":[-1],\"exchange_type\":\"PassThrough\",\"connection_details\":[{\"tunnel_id\":\"tunnel2+-1\",\"sender_target_task_id\":-1,\"sender_target_host\":\"10.33.58.75:38168\",\"is_local\":false,\"packets\":0,\"bytes\":0}]},{\"id\":\"Limit_19\",\"type\":\"Limit\",\"children\":[\"Selection_18\"],\"outbound_rows\":8,\"outbound_blocks\":2,\"outbound_bytes\":14456,\"execution_time_ns\":783008645},{\"id\":\"Selection_18\",\"type\":\"Selection\",\"children\":[\"TableFullScan_17\"],\"outbound_rows\":8,\"outbound_blocks\":2,\"outbound_bytes\":14456,\"execution_time_ns\":783008645},{\"id\":\"TableFullScan_17\",\"type\":\"TableScan\",\"children\":[],\"outbound_rows\":3145728,\"outbound_blocks\":48,\"outbound_bytes\":5769682933,\"execution_time_ns\":891009837,\"connection_details\":[{\"is_local\":true,\"packets\":0,\"bytes\":5769682933},{\"is_local\":false,\"packets\":0,\"bytes\":0}],\"scan_details\":{\"create_inputstream_time\":\"253ms\",\"create_snapshot_time\":\"0ms\",\"delta_bytes\":489102486,\"delta_rows\":257823,\"dmfile_read_time\":\"19391ms\",\"dmfile_scan_rows\":6281260,\"dmfile_skip_rows\":499712,\"mvcc_input_bytes\":7346526167,\"mvcc_input_rows\":3999231,\"mvcc_output_rows\":3999231,\"num_columns\":177,\"num_read_tasks\":145,\"num_segments\":145}}],\"host\":\"30.88.0.4:12256\",\"task_init_timestamp\":1754893554047884000,\"task_start_timestamp\":1754893554161757000,\"task_end_timestamp\":1754893555074697000,\"compile_start_timestamp\":1754893554049800000,\"compile_end_timestamp\":1754893554161725000,\"read_wait_index_start_timestamp\":1754893554051886000,\"read_wait_index_end_timestamp\":1754893554076808000,\"local_input_bytes\":5769682933,\"remote_input_bytes\":0,\"output_bytes\":14456,\"status\":\"CANCELLED\",\"error_message\":\"Receive cancel request from TiDB\",\"working_time\":0,\"memory_peak\":0}"] [source="mpp_task_tracing MPP<query:460034815828164615,task:2>"] [thread_id=775]
[2025/08/11 14:25:55.074 +08:00] [INFO] [MPPTask.cpp:74] ["finish MPPTask: MPP<query:460034815828164615,task:2>"] [source=MPP<query:460034815828164615,task:2>] [thread_id=775]
[2025/08/11 14:25:55.085 +08:00] [ERROR] [Exception.cpp:93] ["virtual DB::SharedQueryBlockInputStream::~SharedQueryBlockInputStream(): Code: 0, e.displayText() = DB::Exception: Query was cancelled, e.what() = DB::Exception, Stack trace:\n\n\n       0x17620ce\tDB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) [tiflash+24518862]\n                \tdbms/src/Common/Exception.h:46\n       0x1872d7e\tDB::SharedQueryBlockInputStream::waitThread() [tiflash+25636222]\n                \tdbms/src/DataStreams/SharedQueryBlockInputStream.h:183\n       0x18722ea\tDB::SharedQueryBlockInputStream::readSuffix() [tiflash+25633514]\n                \tdbms/src/DataStreams/SharedQueryBlockInputStream.h:86\n       0x18723ac\tDB::SharedQueryBlockInputStream::~SharedQueryBlockInputStream() [tiflash+25633708]\n                \tdbms/src/DataStreams/SharedQueryBlockInputStream.h:54\n       0x1838f1e\tDB::IBlockInputStream::~IBlockInputStream() [tiflash+25399070]\n                \tdbms/src/DataStreams/IBlockInputStream.h:111\n       0x1838f1e\tDB::IBlockInputStream::~IBlockInputStream() [tiflash+25399070]\n                \tdbms/src/DataStreams/IBlockInputStream.h:111\n       0x1838f1e\tDB::IBlockInputStream::~IBlockInputStream() [tiflash+25399070]\n                \tdbms/src/DataStreams/IBlockInputStream.h:111\n       0x6e5c31c\tDB::UnionBlockInputStream<(DB::StreamUnionMode)0, true>::~UnionBlockInputStream() [tiflash+115720988]\n                \tdbms/src/DataStreams/UnionBlockInputStream.h:135\n       0x67b1330\tstd::__1::__shared_ptr_emplace<DB::ProcessListEntry, std::__1::allocator<DB::ProcessListEntry> >::__on_zero_shared() [tiflash+108729136]\n                \t/usr/local/bin/../include/c++/v1/__memory/shared_ptr.h:315\n       0x63d0daa\tDB::DAGContext::~DAGContext() [tiflash+104664490]\n                \tdbms/src/Flash/Coprocessor/DAGContext.h:126\n       0x6e9a6db\tDB::MPPTask::~MPPTask() [tiflash+115975899]\n                \tdbms/src/Flash/Mpp/MPPTask.cpp:75\n       0x6e93d27\tstd::__1::__shared_ptr_pointer<DB::MPPTask*, std::__1::shared_ptr<DB::MPPTask>::__shared_ptr_default_delete<DB::MPPTask, DB::MPPTask>, std::__1::allocator<DB::MPPTask> >::__on_zero_shared() [tiflash+115948839]\n                \t/usr/local/bin/../include/c++/v1/__memory/shared_ptr.h:267\n       0x6ea27c1\tstd::__1::__function::__func<DB::MPPTask::run()::$_13, std::__1::allocator<DB::MPPTask::run()::$_13>, void ()>::destroy() [tiflash+116008897]\n                \t/usr/local/bin/../include/c++/v1/__functional/function.h:327\n       0x1847df4\tDB::ExecutableTask<auto DB::wrapInvocable<std::__1::function<void ()> >(bool, std::__1::function<void ()>&&)::'lambda'()>::~ExecutableTask() [tiflash+25460212]\n                \tdbms/src/Common/ExecutableTask.h:46\n       0x184af48\tDB::DynamicThreadPool::executeTask(std::__1::unique_ptr<DB::IExecutableTask, std::__1::default_delete<DB::IExecutableTask> >&) [tiflash+25472840]\n                \tdbms/src/Common/DynamicThreadPool.cpp:102\n       0x184a590\tDB::DynamicThreadPool::fixedWork(unsigned long) [tiflash+25470352]\n                \tdbms/src/Common/DynamicThreadPool.cpp:115\n       0x184b682\tvoid* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, std::__1::thread DB::ThreadFactory::newThread<void (DB::DynamicThreadPool::*)(unsigned long), DB::DynamicThreadPool*, unsigned long&>(bool, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, void (DB::DynamicThreadPool::*&&)(unsigned long), DB::DynamicThreadPool*&&, unsigned long&)::'lambda'(auto&&...), DB::DynamicThreadPool*, unsigned long> >(void*) [tiflash+25474690]\n                \t/usr/local/bin/../include/c++/v1/thread:291\n  0x7fe86b3d9ea5\tstart_thread [libpthread.so.0+32421]\n  0x7fe86a7de96d\t__clone [libc.so.6+1042797]"] [source="Limit MPP<query:460034815828164615,task:2>"] [thread_id=775]
[2025/08/11 14:36:42.400 +08:00] [WARN] [PageDirectory.cpp:1608] ["Meet a stale snapshot [thread id=775] [tracing id=MPP<query:460034815828164615,task:2> table_id=102865] [seq=2162921] [alive time(s)=648.320648822]"] [source=__global__.meta] [thread_id=24]
[2025/08/11 14:36:42.400 +08:00] [WARN] [PageDirectory.cpp:1608] ["Meet a stale snapshot [thread id=775] [tracing id=MPP<query:460034815828164615,task:2> table_id=102849] [seq=2162921] [alive time(s)=648.317918479]"] [source=__global__.meta] [thread_id=24]
[2025/08/11 14:36:42.400 +08:00] [WARN] [PageDirectory.cpp:1608] ["Meet a stale snapshot [thread id=775] [tracing id=MPP<query:460034815828164615,task:2> table_id=16909] [seq=2162921] [alive time(s)=648.31763543]"] [source=__global__.meta] [thread_id=24]
4. What is your TiFlash version? (Required)

v6.5.7

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start by tracing the cancellation flow through FlashService.cpp, MPPTaskManager.cpp, MPPTask.cpp, EstablishCall.cpp, and the related mpp_gather.go and mpp.go log points. Reproduce the simple LIMIT query with the supplied two-TiFlash setup, then determine why the task is cancelled and verify that cancellation behaves correctly without the reported failure.

Written by the indexing model from the issue text.

Assessment

Tech stack
cpp, sql
Domain
databases, distributed-systems
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
30/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.