[2022/03/09 14:00:49.555 +08:00] [DEBUG] [MPPTask.cpp:239] ["MPPTask:<query:431700219966259312,task:20> begin to register the tunnel tunnel20+26"] [thread_id=47081]
[2022/03/09 14:00:49.598 +08:00] [DEBUG] [MPPTask.cpp:239] ["MPPTask:<query:431700219966259312,task:20> begin to register the tunnel tunnel20+27"] [thread_id=47081]
[2022/03/09 14:00:49.723 +08:00] [DEBUG] [MPPTask.cpp:239] ["MPPTask:<query:431700219966259312,task:20> begin to register the tunnel tunnel20+28"] [thread_id=47081]
[2022/03/09 14:00:49.768 +08:00] [DEBUG] [MPPTask.cpp:250] ["MPPTask:<query:431700219966259312,task:20> begin to register the task <query:431700219966259312,task:20>"] [thread_id=47081]
[2022/03/09 14:00:51.976 +08:00] [INFO] [MPPTaskStatistics.cpp:113] ["mpp_task_tracing:<query:431700219966259312,task:20> {\"query_tso\":431700219966259312,\"task_id\":20,\"is_root\":false,\"sender_executor_id\":\"ExchangeSender_218\",\"executors\":[{\"id\":\"ExchangeSender_218\",\"type\":\"ExchangeSender\",\"children\":[\"TableFullScan_217\"],\"outbound_rows\":0,\"outbound_blocks\":0,\"outbound_bytes\":0,\"execution_time_ns\":0,\"partition_num\":3,\"sender_target_task_ids\":[26,27,28],\"exchange_type\":\"Hash\",\"connection_details\":[{\"tunnel_id\":\"tunnel20+26\",\"sender_target_task_id\":26,\"sender_target_host\":\"172.16.4.39:41337\",\"is_local\":true,\"packets\":0,\"bytes\":0},{\"tunnel_id\":\"tunnel20+27\",\"sender_target_task_id\":27,\"sender_target_host\":\"172.16.4.42:41437\",\"is_local\":false,\"packets\":0,\"bytes\":0},{\"tunnel_id\":\"tunnel20+28\",\"sender_target_task_id\":28,\"sender_target_host\":\"172.16.4.79:41337\",\"is_local\":false,\"packets\":0,\"bytes\":0}]},{\"id\":\"TableFullScan_217\",\"type\":\"TableScan\",\"children\":[],\"outbound_rows\":0,\"outbound_blocks\":0,\"outbound_bytes\":0,\"execution_time_ns\":0,\"connection_details\":[{\"is_local\":true,\"packets\":0,\"bytes\":0},{\"is_local\":false,\"packets\":0,\"bytes\":0}]}],\"host\":\"172.16.4.39:41337\",\"task_init_timestamp\":1646805649485433530,\"task_start_timestamp\":0,\"task_end_timestamp\":0,\"compile_start_timestamp\":0,\"compile_end_timestamp\":0,\"read_wait_index_start_timestamp\":0,\"read_wait_index_end_timestamp\":0,\"local_input_bytes\":0,\"remote_input_bytes\":0,\"output_bytes\":0,\"status\":\"INITIALIZING\",\"error_message\":\"\",\"working_time\":0,\"memory_peak\":0}"] [thread_id=47081]
[2022/03/09 14:00:52.044 +08:00] [INFO] [<unknown>] ["MPPTask:<query:431700219966259312,task:20> task starts preprocessing"] [thread_id=51765]
[2022/03/09 14:00:52.288 +08:00] [DEBUG] [executeQuery.cpp:83] ["MPPTask:<query:431700219966259312,task:20> (from 172.16.5.85:39866, query_id: 15be2b77-7d53-40cc-82ca-8cfba3e102c4) time_zone_offset: 28800 flags: 226 output_offsets: 0 encode_type: TypeCHBlock time_zone_name: \"Asia/Shanghai\" collect_execution_summaries: true chunk_memory_layout {   endian: LittleEndian } root_executor {   tp: TypeExchangeSender   executor_id: \"ExchangeSender_218\"   exchange_sender {     tp: Hash     encoded_task_meta: \"\\010\\360\\200\\260\\244\\201\\242\\355\\376\\005\\020\\032\\\"\\021172.16.4.39:41337\"     encoded_task_meta: \"\\010\\360\\200\\260\\244\\201\\242\\355\\376\\005\\020\\033\\\"\\021172.16.4.42:41437\"     encoded_task_meta: \"\\010\\360\\200\\260\\244\\201\\242\\355\\376\\005\\020\\034\\\"\\021172.16.4.79:41337\"     partition_keys {       tp: ColumnRef       val: \"\\200\\000\\000\\000\\000\\000\\000\\000\"       sig: Unspecified       field_type {         tp: 3         flag: 4099         flen: 11         decimal: 0         collate: 63         charset: \"binary\"       }       has_distinct: false     }     child {       tp: TypeTableScan       tbl_scan {         table_id: 63         columns {           column_id: 1           tp: 3           collation: 63           columnLen: 11           decimal: 0           flag: 4099           pk_handle: true         }         desc: false         next_read_engine: Local       }       executor_id: \"TableFullScan_217\"     }     types {       tp: 3       flag: 4099       flen: 11       decimal: 0       collate: 63       charset: \"binary\"     }     all_field_types {       tp: 3       flag: 4099       flen: 11       decimal: 0       collate: 63       charset: \"binary\"     }   } } "] [thread_id=51765]
[2022/03/09 14:00:52.553 +08:00] [DEBUG] [LearnerRead.cpp:272] ["MPPTask:<query:431700219966259312,task:20> DAGStorageInterpreter Batch read index, original size 12, send & get 12 message, cost 0ms"] [thread_id=51765]
[2022/03/09 14:00:52.680 +08:00] [DEBUG] [LearnerRead.cpp:389] ["MPPTask:<query:431700219966259312,task:20> DAGStorageInterpreter Finish wait index | resolve locks | check memory cache for 12 regions, cost 0ms, 0 unavailable regions"] [thread_id=51765]
[2022/03/09 14:00:52.775 +08:00] [DEBUG] [LearnerRead.cpp:417] ["MPPTask:<query:431700219966259312,task:20> DAGStorageInterpreter [Learner Read] batch read index | wait index cost 383 ms totally, regions_num=12, concurrency=1"] [thread_id=51765]
[2022/03/09 14:00:52.775 +08:00] [INFO] [DAGStorageInterpreter.cpp:436] ["MPPTask:<query:431700219966259312,task:20> DAGStorageInterpreter DB::DAGStorageInterpreter::getAndLockStorage(DB::Int64)::<lambda(const String&, DB::Int64)> Table 63 schema OK, no syncing required. Schema version [storage, global, query]: [34, 250, 250]."] [thread_id=51765]
[2022/03/09 14:00:52.775 +08:00] [DEBUG] [DAGQueryBlockInterpreter.cpp:1035] ["MPPTask:<query:431700219966259312,task:20> DAGQueryBlockInterpreter execution stream size for query block(before aggregation) __QB_1_ is 16"] [thread_id=51765]
[2022/03/09 14:00:52.864 +08:00] [DEBUG] [<unknown>] ["MPPTask:<query:431700219966259312,task:20> Query pipeline:\nUnion\n ExchangeSender × 16\n  Expression\n   DeltaMergeSegmentThread\n"] [thread_id=51765]
[2022/03/09 14:00:52.864 +08:00] [DEBUG] [MPPTask.cpp:301] ["MPPTask:<query:431700219966259312,task:20> Estimate new thread count of query :19 including tunnel_threads: 2 , receiver_threads: 0"] [thread_id=51765]
[2022/03/09 14:01:08.266 +08:00] [DEBUG] [<unknown>] ["MPPTask:<query:431700219966259312,task:20> tunnel20+28 connected"] [thread_id=48273]
[2022/03/09 14:01:08.266 +08:00] [DEBUG] [FlashService.cpp:227] ["MPPTask:<query:431700219966259312,task:20> tunnel20+28 connect tunnel successfully and begin to wait"] [thread_id=48273]
[2022/03/09 14:01:08.415 +08:00] [INFO] [MinTSOScheduler.cpp:64] ["MinTSOScheduler:<query:431700219966259312,task:20> is put into waiting set (size=71) due to unavailable threads or active set is full (size =  28), apply for 19 threads, but used 5485 of the thread soft limit 5000."] [thread_id=51765]
[2022/03/09 14:01:08.415 +08:00] [INFO] [MPPTask.cpp:438] ["MPPTask:<query:431700219966259312,task:20> task waits for schedule"] [thread_id=51765]
[2022/03/09 14:01:09.263 +08:00] [DEBUG] [<unknown>] ["MPPTask:<query:431700219966259312,task:20> tunnel20+26 connected"] [thread_id=51169]
[2022/03/09 14:01:09.479 +08:00] [DEBUG] [<unknown>] ["MPPTask:<query:431700219966259312,task:20> tunnel20+27 connected"] [thread_id=50500]
[2022/03/09 14:01:09.480 +08:00] [DEBUG] [FlashService.cpp:227] ["MPPTask:<query:431700219966259312,task:20> tunnel20+27 connect tunnel successfully and begin to wait"] [thread_id=50500]
[2022/03/09 14:01:11.626 +08:00] [INFO] [MPPTask.cpp:448] ["MPPTask:<query:431700219966259312,task:20> task gets schedule"] [thread_id=53325]
[2022/03/09 14:01:11.626 +08:00] [INFO] [MinTSOScheduler.cpp:149] ["MinTSOScheduler:<query:431700219966259312,task:20> is scheduled (active set size = 25) due to available threads, after applied for 19 threads, used 5573 of the thread hard limit 8000."] [thread_id=53325]
[2022/03/09 14:01:11.647 +08:00] [INFO] [MPPTask.cpp:442] ["MPPTask:<query:431700219966259312,task:20> task waits for 3210 ms to schedule and starts to run in parallel."] [thread_id=51765]
[2022/03/09 14:01:11.660 +08:00] [INFO] [<unknown>] ["MPPTask:<query:431700219966259312,task:20> task starts running"] [thread_id=51765]
[2022/03/09 14:01:11.676 +08:00] [DEBUG] [<unknown>] ["MPPTask:<query:431700219966259312,task:20> begin read "] [thread_id=51765]
[2022/03/09 14:01:11.933 +08:00] [WARN] [MPPTask.cpp:400] ["MPPTask:<query:431700219966259312,task:20> Begin cancel task: <query:431700219966259312,task:20>"] [thread_id=56667]
[2022/03/09 14:01:11.933 +08:00] [INFO] [MPPTask.cpp:448] ["MPPTask:<query:431700219966259312,task:20> task gets schedule"] [thread_id=56667]
[2022/03/09 14:01:11.933 +08:00] [WARN] [<unknown>] ["TaskManager:Remaining task in query 431700219966259312 are: <query:431700219966259312,task:26> <query:431700219966259312,task:45> <query:431700219966259312,task:20> <query:431700219966259312,task:8> <query:431700219966259312,task:7> <query:431700219966259312,task:24> "] [thread_id=48890]
[2022/03/09 14:01:12.310 +08:00] [ERROR] [<unknown>] ["MPPTask:<query:431700219966259312,task:20> tunnel20+28 grpc writes failed."] [thread_id=54905]
[2022/03/09 14:01:12.382 +08:00] [ERROR] [MPPTask.cpp:336] ["MPPTask:<query:431700219966259312,task:20> task running meets error: DB::Exception: Consumer exits unexpected, grpc writes failed. Stack Trace : 0. bin/tiflash/tiflash(StackTrace::StackTrace()+0x16) [0x369c576]\n1. bin/tiflash/tiflash(DB::Exception::Exception(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, int)+0x26) [0x36900f6]\n2. bin/tiflash/tiflash(DB::MPPTunnelBase<grpc_impl::ServerWriter<mpp::MPPDataPacket> >::waitForConsumerFinish(bool)+0x236) [0x7b5d446]\n3. bin/tiflash/tiflash(DB::MPPTunnelBase<grpc_impl::ServerWriter<mpp::MPPDataPacket> >::writeDone()+0x6af) [0x7b63caf]\n4. bin/tiflash/tiflash(DB::MPPTask::finishWrite()+0x21) [0x7b4e891]\n5. bin/tiflash/tiflash(DB::MPPTask::runImpl()+0x4a9) [0x7b53e09]\n6. bin/tiflash/tiflash(std::_Function_handler<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> (), std::__future_base::_Task_setter<std::unique_ptr<std::__future_base::_Result<void>, std::__future_base::_Result_base::_Deleter>, std::__future_base::_Task_state<auto DB::wrapInvocable<std::function<void ()>&>(bool, std::function<void ()>&)::{lambda()#1}, std::allocator<int>, void ()>::_M_run()::{lambda()#1}, void> >::_M_invoke(std::_Any_data const&)+0x68) [0x7c8e018]\n7. bin/tiflash/tiflash(std::__future_base::_State_baseV2::_M_do_set(std::function<std::unique_ptr<std::__future_base::_Result_base, std::__future_base::_Result_base::_Deleter> ()>*, bool*)+0x1f) [0x79dc7bf]\n8. /lib64/libpthread.so.0(+0x620b) [0x7f1a0154020b]\n9. bin/tiflash/tiflash(DB::ExecutableTask<std::packaged_task<void ()> >::execute()+0x11e) [0x7c8ebee]\n10. bin/tiflash/tiflash(DB::DynamicThreadPool::dynamicWork(std::unique_ptr<DB::IExecutableTask, std::default_delete<DB::IExecutableTask> >)+0x41) [0x7c63dc1]\n11. bin/tiflash/tiflash(_ZNSt6thread11_State_implINS_8_InvokerISt5tupleIJZN2DB13ThreadFactory9newThreadIMNS3_17DynamicThreadPoolEFvSt10unique_ptrINS3_15IExecutableTaskESt14default_deleteIS8_EEEJPS6_SB_EEES_bNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEEOT_DpOT0_EUlDpOT_E_SE_SB_EEEEE6_M_runEv+0x88) [0x7c65ab8]\n12. bin/tiflash/tiflash() [0x8a250af]\n13. /lib64/libpthread.so.0(+0x7ea5) [0x7f1a01541ea5]\n14. /lib64/libc.so.6(clone+0x6d) [0x7f1a00f68b0d]\n"] [thread_id=51765]
[2022/03/09 15:03:53.693 +08:00] [WARN] [<unknown>] ["MPPTask:<query:431700219966259312,task:20> Finish cancel task from running"] [thread_id=56667]
[2022/03/09 15:03:53.698 +08:00] [INFO] [FlashService.cpp:229] ["MPPTask:<query:431700219966259312,task:20> tunnel20+27 connection for tunnel20+27 cost 3764215 ms."] [thread_id=50500]
[2022/03/09 15:03:53.698 +08:00] [INFO] [MPPTask.cpp:368] ["MPPTask:<query:431700219966259312,task:20> task ends, time cost is 3781661 ms."] [thread_id=51765]
[2022/03/09 15:03:53.698 +08:00] [DEBUG] [<unknown>] ["MPPTask:<query:431700219966259312,task:20> task unregistered"] [thread_id=51765]
[2022/03/09 15:03:53.827 +08:00] [ERROR] [<unknown>] ["TaskManager:The task <query:431700219966259312,task:20> cannot be found and fail to unregister"] [thread_id=51765]
[2022/03/09 15:03:53.832 +08:00] [WARN] [<unknown>] ["MPPTask:<query:431700219966259312,task:20> finish task which was cancelled before"] [thread_id=51765]
[2022/03/09 15:03:53.845 +08:00] [INFO] [MPPTaskStatistics.cpp:113] ["mpp_task_tracing:<query:431700219966259312,task:20> {\"query_tso\":431700219966259312,\"task_id\":20,\"is_root\":false,\"sender_executor_id\":\"ExchangeSender_218\",\"executors\":[{\"id\":\"ExchangeSender_218\",\"type\":\"ExchangeSender\",\"children\":[\"TableFullScan_217\"],\"outbound_rows\":0,\"outbound_blocks\":0,\"outbound_bytes\":0,\"execution_time_ns\":0,\"partition_num\":3,\"sender_target_task_ids\":[26,27,28],\"exchange_type\":\"Hash\",\"connection_details\":[{\"tunnel_id\":\"tunnel20+26\",\"sender_target_task_id\":26,\"sender_target_host\":\"172.16.4.39:41337\",\"is_local\":true,\"packets\":0,\"bytes\":0},{\"tunnel_id\":\"tunnel20+27\",\"sender_target_task_id\":27,\"sender_target_host\":\"172.16.4.42:41437\",\"is_local\":false,\"packets\":0,\"bytes\":0},{\"tunnel_id\":\"tunnel20+28\",\"sender_target_task_id\":28,\"sender_target_host\":\"172.16.4.79:41337\",\"is_local\":false,\"packets\":0,\"bytes\":0}]},{\"id\":\"TableFullScan_217\",\"type\":\"TableScan\",\"children\":[],\"outbound_rows\":0,\"outbound_blocks\":0,\"outbound_bytes\":0,\"execution_time_ns\":0,\"connection_details\":[{\"is_local\":true,\"packets\":0,\"bytes\":0},{\"is_local\":false,\"packets\":0,\"bytes\":0}]}],\"host\":\"172.16.4.39:41337\",\"task_init_timestamp\":1646805649485433530,\"task_start_timestamp\":1646805671660705370,\"task_end_timestamp\":1646809433832466073,\"compile_start_timestamp\":1646805652044999329,\"compile_end_timestamp\":1646805652864753927,\"read_wait_index_start_timestamp\":1646805652297365387,\"read_wait_index_end_timestamp\":1646805652681046239,\"local_input_bytes\":0,\"remote_input_bytes\":0,\"output_bytes\":0,\"status\":\"CANCELLED\",\"error_message\":\"DB::Exception: Consumer exits unexpected, grpc writes failed.\",\"working_time\":0,\"memory_peak\":0}"] [thread_id=51765]                                                                                                         

[2022/03/09 14:00:49.466 +08:00] [DEBUG] [MPPTask.cpp:239] ["MPPTask:<query:431700219966259312,task:21> begin to register the tunnel tunnel21+26"] [thread_id=38480]
[2022/03/09 14:00:49.511 +08:00] [DEBUG] [MPPTask.cpp:239] ["MPPTask:<query:431700219966259312,task:21> begin to register the tunnel tunnel21+27"] [thread_id=38480]
[2022/03/09 14:00:49.562 +08:00] [DEBUG] [MPPTask.cpp:239] ["MPPTask:<query:431700219966259312,task:21> begin to register the tunnel tunnel21+28"] [thread_id=38480]
[2022/03/09 14:00:49.599 +08:00] [DEBUG] [MPPTask.cpp:250] ["MPPTask:<query:431700219966259312,task:21> begin to register the task <query:431700219966259312,task:21>"] [thread_id=38480]
[2022/03/09 14:00:50.190 +08:00] [INFO] [MPPTaskStatistics.cpp:113] ["mpp_task_tracing:<query:431700219966259312,task:21> {\"query_tso\":431700219966259312,\"task_id\":21,\"is_root\":false,\"sender_executor_id\":\"ExchangeSender_218\",\"executors\":[{\"id\":\"ExchangeSender_218\",\"type\":\"ExchangeSender\",\"children\":[\"TableFullScan_217\"],\"outbound_rows\":0,\"outbound_blocks\":0,\"outbound_bytes\":0,\"execution_time_ns\":0,\"partition_num\":3,\"sender_target_task_ids\":[26,27,28],\"exchange_type\":\"Hash\",\"connection_details\":[{\"tunnel_id\":\"tunnel21+26\",\"sender_target_task_id\":26,\"sender_target_host\":\"172.16.4.39:41337\",\"is_local\":false,\"packets\":0,\"bytes\":0},{\"tunnel_id\":\"tunnel21+27\",\"sender_target_task_id\":27,\"sender_target_host\":\"172.16.4.42:41437\",\"is_local\":true,\"packets\":0,\"bytes\":0},{\"tunnel_id\":\"tunnel21+28\",\"sender_target_task_id\":28,\"sender_target_host\":\"172.16.4.79:41337\",\"is_local\":false,\"packets\":0,\"bytes\":0}]},{\"id\":\"TableFullScan_217\",\"type\":\"TableScan\",\"children\":[],\"outbound_rows\":0,\"outbound_blocks\":0,\"outbound_bytes\":0,\"execution_time_ns\":0,\"connection_details\":[{\"is_local\":true,\"packets\":0,\"bytes\":0},{\"is_local\":false,\"packets\":0,\"bytes\":0}]}],\"host\":\"172.16.4.42:41437\",\"task_init_timestamp\":1646805649431967776,\"task_start_timestamp\":0,\"task_end_timestamp\":0,\"compile_start_timestamp\":0,\"compile_end_timestamp\":0,\"read_wait_index_start_timestamp\":0,\"read_wait_index_end_timestamp\":0,\"local_input_bytes\":0,\"remote_input_bytes\":0,\"output_bytes\":0,\"status\":\"INITIALIZING\",\"error_message\":\"\",\"working_time\":0,\"memory_peak\":0}"] [thread_id=38480]
[2022/03/09 14:00:50.217 +08:00] [INFO] [<unknown>] ["MPPTask:<query:431700219966259312,task:21> task starts preprocessing"] [thread_id=41209]
[2022/03/09 14:00:50.262 +08:00] [DEBUG] [executeQuery.cpp:83] ["MPPTask:<query:431700219966259312,task:21> (from 172.16.5.85:33787, query_id: 8ad495a9-a46b-4c0d-8399-3183b004bbf9) time_zone_offset: 28800 flags: 226 output_offsets: 0 encode_type: TypeCHBlock time_zone_name: \"Asia/Shanghai\" collect_execution_summaries: true chunk_memory_layout {   endian: LittleEndian } root_executor {   tp: TypeExchangeSender   executor_id: \"ExchangeSender_218\"   exchange_sender {     tp: Hash     encoded_task_meta: \"\\010\\360\\200\\260\\244\\201\\242\\355\\376\\005\\020\\032\\\"\\021172.16.4.39:41337\"     encoded_task_meta: \"\\010\\360\\200\\260\\244\\201\\242\\355\\376\\005\\020\\033\\\"\\021172.16.4.42:41437\"     encoded_task_meta: \"\\010\\360\\200\\260\\244\\201\\242\\355\\376\\005\\020\\034\\\"\\021172.16.4.79:41337\"     partition_keys {       tp: ColumnRef       val: \"\\200\\000\\000\\000\\000\\000\\000\\000\"       sig: Unspecified       field_type {         tp: 3         flag: 4099         flen: 11         decimal: 0         collate: 63         charset: \"binary\"       }       has_distinct: false     }     child {       tp: TypeTableScan       tbl_scan {         table_id: 63         columns {           column_id: 1           tp: 3           collation: 63           columnLen: 11           decimal: 0           flag: 4099           pk_handle: true         }         desc: false         next_read_engine: Local       }       executor_id: \"TableFullScan_217\"     }     types {       tp: 3       flag: 4099       flen: 11       decimal: 0       collate: 63       charset: \"binary\"     }     all_field_types {       tp: 3       flag: 4099       flen: 11       decimal: 0       collate: 63       charset: \"binary\"     }   } } "] [thread_id=41209]
[2022/03/09 14:00:50.300 +08:00] [DEBUG] [LearnerRead.cpp:272] ["MPPTask:<query:431700219966259312,task:21> DAGStorageInterpreter Batch read index, original size 13, send & get 13 message, cost 16ms"] [thread_id=41209]
[2022/03/09 14:00:50.321 +08:00] [DEBUG] [LearnerRead.cpp:389] ["MPPTask:<query:431700219966259312,task:21> DAGStorageInterpreter Finish wait index | resolve locks | check memory cache for 13 regions, cost 0ms, 0 unavailable regions"] [thread_id=41209]
[2022/03/09 14:00:50.343 +08:00] [DEBUG] [LearnerRead.cpp:417] ["MPPTask:<query:431700219966259312,task:21> DAGStorageInterpreter [Learner Read] batch read index | wait index cost 58 ms totally, regions_num=13, concurrency=1"] [thread_id=41209]
[2022/03/09 14:00:50.398 +08:00] [INFO] [DAGStorageInterpreter.cpp:436] ["MPPTask:<query:431700219966259312,task:21> DAGStorageInterpreter DB::DAGStorageInterpreter::getAndLockStorage(DB::Int64)::<lambda(const String&, DB::Int64)> Table 63 schema OK, no syncing required. Schema version [storage, global, query]: [37, 250, 250]."] [thread_id=41209]
[2022/03/09 14:00:50.515 +08:00] [DEBUG] [DAGQueryBlockInterpreter.cpp:1035] ["MPPTask:<query:431700219966259312,task:21> DAGQueryBlockInterpreter execution stream size for query block(before aggregation) __QB_1_ is 17"] [thread_id=41209]
[2022/03/09 14:00:50.515 +08:00] [DEBUG] [<unknown>] ["MPPTask:<query:431700219966259312,task:21> Query pipeline:\nUnion\n ExchangeSender × 17\n  Expression\n   DeltaMergeSegmentThread\n"] [thread_id=41209]
[2022/03/09 14:00:50.537 +08:00] [DEBUG] [MPPTask.cpp:301] ["MPPTask:<query:431700219966259312,task:21> Estimate new thread count of query :20 including tunnel_threads: 2 , receiver_threads: 0"] [thread_id=41209]
[2022/03/09 14:01:00.494 +08:00] [DEBUG] [<unknown>] ["MPPTask:<query:431700219966259312,task:21> tunnel21+27 connected"] [thread_id=44024]
[2022/03/09 14:01:07.776 +08:00] [INFO] [MinTSOScheduler.cpp:64] ["MinTSOScheduler:<query:431700219966259312,task:21> is put into waiting set (size=58) due to unavailable threads or active set is full (size =  27), apply for 20 threads, but used 5304 of the thread soft limit 5000."] [thread_id=41209]
[2022/03/09 14:01:07.777 +08:00] [INFO] [MPPTask.cpp:438] ["MPPTask:<query:431700219966259312,task:21> task waits for schedule"] [thread_id=41209]
[2022/03/09 14:01:08.065 +08:00] [DEBUG] [<unknown>] ["MPPTask:<query:431700219966259312,task:21> tunnel21+28 connected"] [thread_id=38862]
[2022/03/09 14:01:08.065 +08:00] [DEBUG] [FlashService.cpp:227] ["MPPTask:<query:431700219966259312,task:21> tunnel21+28 connect tunnel successfully and begin to wait"] [thread_id=38862]
[2022/03/09 14:01:08.696 +08:00] [DEBUG] [<unknown>] ["MPPTask:<query:431700219966259312,task:21> tunnel21+26 connected"] [thread_id=40891]
[2022/03/09 14:01:08.696 +08:00] [DEBUG] [FlashService.cpp:227] ["MPPTask:<query:431700219966259312,task:21> tunnel21+26 connect tunnel successfully and begin to wait"] [thread_id=40891]
[2022/03/09 14:01:11.496 +08:00] [INFO] [MPPTask.cpp:448] ["MPPTask:<query:431700219966259312,task:21> task gets schedule"] [thread_id=42984]
[2022/03/09 14:01:11.500 +08:00] [INFO] [MinTSOScheduler.cpp:149] ["MinTSOScheduler:<query:431700219966259312,task:21> is scheduled (active set size = 25) due to available threads, after applied for 20 threads, used 5194 of the thread hard limit 8000."] [thread_id=42984]
[2022/03/09 14:01:11.505 +08:00] [INFO] [MPPTask.cpp:442] ["MPPTask:<query:431700219966259312,task:21> task waits for 3719 ms to schedule and starts to run in parallel."] [thread_id=41209]
[2022/03/09 14:01:11.509 +08:00] [INFO] [<unknown>] ["MPPTask:<query:431700219966259312,task:21> task starts running"] [thread_id=41209]
[2022/03/09 14:01:11.518 +08:00] [DEBUG] [<unknown>] ["MPPTask:<query:431700219966259312,task:21> begin read "] [thread_id=41209]
[2022/03/09 14:01:11.653 +08:00] [INFO] [FlashService.cpp:229] ["MPPTask:<query:431700219966259312,task:21> tunnel21+26 connection for tunnel21+26 cost 2963 ms."] [thread_id=40891]
[2022/03/09 14:01:11.654 +08:00] [INFO] [FlashService.cpp:229] ["MPPTask:<query:431700219966259312,task:21> tunnel21+28 connection for tunnel21+28 cost 3588 ms."] [thread_id=38862]
[2022/03/09 14:01:41.941 +08:00] [WARN] [<unknown>] ["TaskManager:Remaining task in query 431700219966259312 are: <query:431700219966259312,task:21> "] [thread_id=38643]
[2022/03/09 14:01:41.942 +08:00] [WARN] [MPPTask.cpp:400] ["MPPTask:<query:431700219966259312,task:21> Begin cancel task: <query:431700219966259312,task:21>"] [thread_id=46695]
[2022/03/09 14:01:41.942 +08:00] [INFO] [MPPTask.cpp:448] ["MPPTask:<query:431700219966259312,task:21> task gets schedule"] [thread_id=46695]