pingcap / pingcap/tiflash

"stream unknown error" log Enhancement

Open
#6,989 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

type/enhancement
Dominant language
C++
Stars
1k
Forks
423
Avg merge
1d 15h
Merged PRs (30d)
24

Description

Enhancement

"stream unknown error" To make the log more useful for debugging purposes, the log level should be changed from "info" to "debug". Additionally, it would be beneficial to provide more precise expressions in the log messages to help pinpoint any issues that may arise.

reproduce：

-- When there is a 'limit' clause in the SQL statement, the issue occurs.
mysql> select /*+ read_from_storage(TIFLASH[a]) */ * from a limit 1;
+---+------+
| a | b    |
+---+------+
| 1 |    1 |
+---+------+
1 row in set (0.01 sec)
 

[root@vm172-16-201-186 tidb-4111]# cat tidb.log | grep 439941574777110531
[2023/03/08 10:52:50.119 +08:00] [INFO] [mpp_gather.go:80] ["Dispatch mpp task"] [timestamp=439941574777110531] [ID=1] [address=172.16.201.17:3930] [plan="Table(a)->Limit->Send(-1, )"]
[2023/03/08 10:52:50.124 +08:00] [INFO] [mpp.go:411] ["stream unknown error"] [error="rpc error: code = Canceled desc = context canceled"] [timestamp=439941574777110531] [task=1]


[2023/03/08 10:52:22.736 +08:00] [DEBUG] [FlashService.cpp:201] ["Handling mpp dispatch request: meta {\n  start_ts:439941574777110531\n  task_id: 1\n  address: \"172.16.201.17:3930\"\n}\nencoded_plan: \"\\030\\200\\341\\001 \\342\\001(\\000(\\001@\\001Z\\rAsia/Shanghai`\\001r\\002\\010\\000\\212\\001\\351\\001\\010\\tR\\021ExchangeSender_15b\\312\\001\\010\\000\\022\\025\\010\\203\\200\\220\\264\\200\\221\\277\\215\\006\\020\\377\\377\\377\\377\\377\\377\\377\\377\\377\\001\\\"t\\010\\005:`\\010\\001\\022\\\\\\010\\000\\022@\\010\\260\\001\\022\\031\\010\\001\\020\\003\\030\\301\\377\\377\\377\\377\\377\\377\\377\\377\\001 \\013(\\0000\\203\\004\\250\\001\\001\\022\\030\\010\\002\\020\\003\\030\\301\\377\\377\\377\\377\\377\\377\\377\\377\\001 \\013(\\0000\\000\\250\\001\\000\\030\\000(\\000@\\000H\\000R\\020TableFullScan_13\\210\\001\\000\\220\\001\\000R\\010Limit_14\\210\\001\\000\\220\\001\\0002\\034\\010\\003\\020\\203\\004\\030\\013 \\000(\\301\\377\\377\\377\\377\\377\\377\\377\\377\\0012\\006binary2\\033\\010\\003\\020\\000\\030\\013 \\000(\\301\\377\\377\\377\\377\\377\\377\\377\\377\\0012\\006binary\\210\\001\\000\\220\\001\\200@\"\ntimeout: 60\nregions {\n  region_id: 5039\n  region_epoch {\n    conf_ver: 107\n    version: 104\n  }\n  ranges {\n    start: \"t\\200\\000\\000\\000\\000\\000\\000\\260_r\\000\\000\\000\\000\\000\\000\\000\\000\"\n    end: \"t\\200\\000\\000\\000\\000\\000\\000\\260_r\\377\\377\\377\\377\\377\\377\\377\\377\\000\"\n  }\n}\nschema_ver: 263\n"] [source=FlashService] [thread_id=46]
[2023/03/08 10:52:22.736 +08:00] [DEBUG] [MPPTask.cpp:241] ["Handling 1 regions from 1 physical tables in MPP task"] [source=MPP<query:439941574777110531,task:1>] [thread_id=46]
[2023/03/08 10:52:22.736 +08:00] [DEBUG] [MPPTask.cpp:139] ["begin to register the tunnel tunnel1+-1, is_local: false, is_async: true"] [source=MPP<query:439941574777110531,task:1>] [thread_id=46]
[2023/03/08 10:52:22.736 +08:00] [DEBUG] [MPPTask.cpp:303] ["begin to register the task MPP<query:439941574777110531,task:1>"] [source=MPP<query:439941574777110531,task:1>] [thread_id=46]
[2023/03/08 10:52:22.736 +08:00] [INFO] [MPPTaskStatistics.cpp:124] ["{\"query_tso\":439941574777110531,\"task_id\":1,\"is_root\":true,\"sender_executor_id\":\"ExchangeSender_15\",\"executors\":[{\"id\":\"ExchangeSender_15\",\"type\":\"ExchangeSender\",\"children\":[\"Limit_14\"],\"outbound_rows\":0,\"outbound_blocks\":0,\"outbound_bytes\":0,\"execution_time_ns\":0,\"partition_num\":1,\"sender_target_task_ids\":[-1],\"exchange_type\":\"PassThrough\",\"connection_details\":[{\"tunnel_id\":\"tunnel1+-1\",\"sender_target_task_id\":-1,\"sender_target_host\":\"172.16.201.186:16220\",\"is_local\":false,\"packets\":0,\"bytes\":0}]},{\"id\":\"Limit_14\",\"type\":\"Limit\",\"children\":[\"TableFullScan_13\"],\"outbound_rows\":0,\"outbound_blocks\":0,\"outbound_bytes\":0,\"execution_time_ns\":0},{\"id\":\"TableFullScan_13\",\"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.201.17:3930\",\"task_init_timestamp\":1678243942736338000,\"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}"] [source="mpp_task_tracing MPP<query:439941574777110531,task:1>"] [thread_id=46]
[2023/03/08 10:52:22.736 +08:00] [INFO] [MPPTask.cpp:364] ["task starts preprocessing"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.736 +08:00] [DEBUG] [MPPTask.cpp:327] ["init exchange receiver done"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.736 +08:00] [DEBUG] [executeQuery.cpp:386] ["(from 172.16.201.186:16220, query_id: d2f958f3-1481-4c47-9b2f-1afc210b85d1) time_zone_offset: 28800 flags: 226 output_offsets: 0 output_offsets: 1 encode_type: TypeChunk time_zone_name: \"Asia/Shanghai\" collect_execution_summaries: true chunk_memory_layout {   endian: LittleEndian } root_executor {   tp: TypeExchangeSender   executor_id: \"ExchangeSender_15\"   exchange_sender {     tp: PassThrough     encoded_task_meta: \"\\010\\203\\200\\220\\264\\200\\221\\277\\215\\006\\020\\377\\377\\377\\377\\377\\377\\377\\377\\377\\001\"     child {       tp: TypeLimit       limit {         limit: 1         child {           tp: TypeTableScan           tbl_scan {             table_id: 176             columns {               column_id: 1               tp: 3               collation: -63               columnLen: 11               decimal: 0               flag: 515               pk_handle: true             }             columns {               column_id: 2               tp: 3               collation: -63               columnLen: 11               decimal: 0               flag: 0               pk_handle: false             }             desc: false             next_read_engine: Local             keep_order: false             is_fast_scan: false           }           executor_id: \"TableFullScan_13\"           fine_grained_shuffle_stream_count: 0           fine_grained_shuffle_batch_size: 0         }       }       executor_id: \"Limit_14\"       fine_grained_shuffle_stream_count: 0       fine_grained_shuffle_batch_size: 0     }     all_field_types {       tp: 3       flag: 515       flen: 11       decimal: 0       collate: -63       charset: \"binary\"     }     all_field_types {       tp: 3       flag: 0       flen: 11       decimal: 0       collate: -63       charset: \"binary\"     }   }   fine_grained_shuffle_stream_count: 0   fine_grained_shuffle_batch_size: 8192 } "] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.736 +08:00] [DEBUG] [PhysicalPlan.cpp:253] ["build unoptimized physical plan: \n<ExchangeSender, ExchangeSender_15> | is_tidb_operator: true, schema: <ExchangeSender_15_table_scan_0, Int32>, <ExchangeSender_15_table_scan_1, Nullable(Int32)>\n <Projection, Limit_14> | is_tidb_operator: false, schema: <ExchangeSender_15_table_scan_0, Int32>, <ExchangeSender_15_table_scan_1, Nullable(Int32)>\n  <Limit, Limit_14> | is_tidb_operator: true, schema: <table_scan_0, Int32>, <table_scan_1, Nullable(Int32)>\n   <TableScan, TableFullScan_13> | is_tidb_operator: true, schema: <table_scan_0, Int32>, <table_scan_1, Nullable(Int32)>\n"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.736 +08:00] [DEBUG] [PhysicalPlan.cpp:259] ["build optimized physical plan: \n<ExchangeSender, ExchangeSender_15> | is_tidb_operator: true, schema: <ExchangeSender_15_table_scan_0, Int32>, <ExchangeSender_15_table_scan_1, Nullable(Int32)>\n <Projection, Limit_14> | is_tidb_operator: false, schema: <ExchangeSender_15_table_scan_0, Int32>, <ExchangeSender_15_table_scan_1, Nullable(Int32)>\n  <Limit, Limit_14> | is_tidb_operator: true, schema: <table_scan_0, Int32>, <table_scan_1, Nullable(Int32)>\n   <TableScan, TableFullScan_13> | is_tidb_operator: true, schema: <table_scan_0, Int32>, <table_scan_1, Nullable(Int32)>\n"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.737 +08:00] [DEBUG] [FlashService.cpp:257] ["Handling establish mpp connection request: sender_meta {\n  start_ts: 439941574777110531\n  task_id: 1\n  address: \"172.16.201.17:3930\"\n}\nreceiver_meta {\n  start_ts: 439941574777110531\n  task_id: -1\n}\n"] [source=FlashService] [thread_id=56]
[2023/03/08 10:52:22.737 +08:00] [DEBUG] [MPPTunnel.cpp:246] ["Tunnel connected in async mode"] [source="MPP<query:439941574777110531,task:1> tunnel1+-1"] [thread_id=56]
[2023/03/08 10:52:22.737 +08:00] [DEBUG] [LearnerRead.cpp:287] ["Batch read index, original size 1, send & get 1 message, cost 0ms"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.737 +08:00] [DEBUG] [LearnerRead.cpp:405] ["Finish wait index | resolve locks | check memory cache for 1 regions, cost 0ms, 0 unavailable regions"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.737 +08:00] [DEBUG] [LearnerRead.cpp:433] ["[Learner Read] batch read index | wait index cost 0 ms totally, regions_num=1, concurrency=1"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.737 +08:00] [INFO] [DAGStorageInterpreter.cpp:998] ["Table 176 schema OK, no syncing required. Schema version [storage, global, query]: [258, 263, 263]"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.737 +08:00] [DEBUG] [StorageDeltaMerge.cpp:646] ["Read with tso: 439941574777110531"] [source="db_144.t_176 MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [DeltaMergeStore.cpp:1586] ["[sorted_ranges: 1] [tasks before split: 1] [tasks final: 1] [ranges final: 1]"] [source="table_id=176 MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [DeltaMergeStore.cpp:987] ["Read create segment snapshot done, keep_order=false dt_enable_read_thread=true enable_read_thread=true"] [source="table_id=176 MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [UnorderedInputStream.h:55] ["Created, pool_id=5 ref_no=0"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [UnorderedInputStream.h:55] ["Created, pool_id=5 ref_no=1"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [UnorderedInputStream.h:55] ["Created, pool_id=5 ref_no=2"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [UnorderedInputStream.h:55] ["Created, pool_id=5 ref_no=3"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [UnorderedInputStream.h:55] ["Created, pool_id=5 ref_no=4"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [UnorderedInputStream.h:55] ["Created, pool_id=5 ref_no=5"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [UnorderedInputStream.h:55] ["Created, pool_id=5 ref_no=6"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [UnorderedInputStream.h:55] ["Created, pool_id=5 ref_no=7"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [DeltaMergeStore.cpp:1041] ["Read create stream done"] [source="table_id=176 MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [executeQuery.cpp:439] ["Query pipeline:\nUnion: <for mpp>\n ExchangeSender x 8\n  Expression: <final projection>\n   SharedQuery: <restore concurrency>\n    Limit, limit = 1\n     Union: <for partial limit>\n      Limit x 8, limit = 1\n       Expression: <table scan schema projection>\n        UnorderedInputStream\n"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [MPPTask.cpp:329] ["init query executor done"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [DEBUG] [MPPTask.cpp:367] ["Estimate new thread count of query: 18 including tunnel_threads: 0, receiver_threads: 0"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [INFO] [MinTSOScheduler.cpp:264] ["min_tso query is updated from 18446744073709551615 to 439941574777110531 when directly schedule it, used threads = 0, 0 active and 0 waiting queries."] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [INFO] [MPPTaskScheduleEntry.cpp:44] ["task is scheduled."] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [INFO] [MinTSOScheduler.cpp:206] ["MPP<query:439941574777110531,task:1> is scheduled (active set size = 1) due to available threads directly, after applied for 18 threads, used 18 of the thread hard limit 10000."] [thread_id=55]
[2023/03/08 10:52:22.738 +08:00] [INFO] [MPPTask.cpp:371] ["task starts running"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.739 +08:00] [DEBUG] [Segment.cpp:1907] ["Begin segment getReadInfo"] [source="table_id=176 segment_id=1 epoch=3 MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=6]
[2023/03/08 10:52:22.739 +08:00] [DEBUG] [Segment.cpp:1922] ["Finish segment getReadInfo"] [source="table_id=176 segment_id=1 epoch=3 MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=6]
[2023/03/08 10:52:22.739 +08:00] [DEBUG] [StableValueSpace.cpp:351] ["max_data_version: 439941574777110531, enable_handle_clean_read: false, is_fast_mode: false, enable_del_clean_read: false"] [source="table_id=176 segment_id=1 epoch=3"] [thread_id=6]
[2023/03/08 10:52:22.739 +08:00] [DEBUG] [DMFilePackFilter.h:224] ["RSFilter exclude rate: 0.00, after_pk: 1, after_read_packs: 1, after_filter: 1, handle_ranges: {[-9223372036854775808,9223372036854775807)}, read_packs: 0, pack_count: 1"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=6]
[2023/03/08 10:52:22.739 +08:00] [DEBUG] [SegmentReadTaskPool.cpp:161] ["getInputStream succ, pool_id=5 segment_id=1"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=6]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [SegmentReadTaskPool.cpp:174] ["finishSegment pool_id=5 segment_id=1 pool_finished=true"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=6]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [DMVersionFilterBlockInputStream.h:80] ["Total rows: 2, pass: 100.00%, complete pass: 100.00%, complete not pass: 0.00%, not clean: 0.00%, is deleted: 0.00%, effective: 0.00%, read tso: 439941574777110531"] [source="mode=MVCC MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=6]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [ColumnSharingCache.h:137] ["dmfile /ssd/tidb-dr-data/tiflash-9000/data/t_176/stable/dmf_6 stat add_count=0 add_stale=0 add_ratio=0 get_miss=5 get_part=0 get_hit=0 get_copy=0 cached_ratio=0"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=6]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:119] ["Finish read from storage, pool_id=5 ref_no=0 rows=1"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=58]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:119] ["Finish read from storage, pool_id=5 ref_no=1 rows=1"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=58]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:119] ["Finish read from storage, pool_id=5 ref_no=2 rows=0"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=58]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:119] ["Finish read from storage, pool_id=5 ref_no=3 rows=0"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=58]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:119] ["Finish read from storage, pool_id=5 ref_no=4 rows=0"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=58]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:119] ["Finish read from storage, pool_id=5 ref_no=5 rows=0"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=58]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:119] ["Finish read from storage, pool_id=5 ref_no=6 rows=0"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=58]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:119] ["Finish read from storage, pool_id=5 ref_no=7 rows=0"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=58]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [ExchangeSenderBlockInputStream.h:49] ["finish write with 1 rows"] [source="ExchangeSender MPP<query:439941574777110531,task:1>"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [ExchangeSenderBlockInputStream.h:49] ["finish write with 0 rows"] [source="ExchangeSender MPP<query:439941574777110531,task:1>"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [ExchangeSenderBlockInputStream.h:49] ["finish write with 0 rows"] [source="ExchangeSender MPP<query:439941574777110531,task:1>"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [ExchangeSenderBlockInputStream.h:49] ["finish write with 0 rows"] [source="ExchangeSender MPP<query:439941574777110531,task:1>"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [ExchangeSenderBlockInputStream.h:49] ["finish write with 0 rows"] [source="ExchangeSender MPP<query:439941574777110531,task:1>"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [ExchangeSenderBlockInputStream.h:49] ["finish write with 0 rows"] [source="ExchangeSender MPP<query:439941574777110531,task:1>"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [ExchangeSenderBlockInputStream.h:49] ["finish write with 0 rows"] [source="ExchangeSender MPP<query:439941574777110531,task:1>"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [ExchangeSenderBlockInputStream.h:49] ["finish write with 0 rows"] [source="ExchangeSender MPP<query:439941574777110531,task:1>"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [INFO] [EstablishCall.cpp:209] ["connection for tunnel1+-1 cost 3 ms, including 0 ms to waiting task."] [source="MPP<query:439941574777110531,task:1> tunnel1+-1"] [thread_id=59]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [MPPTask.cpp:400] ["finish with 1 rows, 1 blocks, 9 bytes"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [INFO] [MPPTask.cpp:411] ["finish task"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [INFO] [MPPTaskStatistics.cpp:124] ["{\"query_tso\":439941574777110531,\"task_id\":1,\"is_root\":true,\"sender_executor_id\":\"ExchangeSender_15\",\"executors\":[{\"id\":\"ExchangeSender_15\",\"type\":\"ExchangeSender\",\"children\":[\"Limit_14\"],\"outbound_rows\":1,\"outbound_blocks\":1,\"outbound_bytes\":9,\"execution_time_ns\":2000000,\"partition_num\":1,\"sender_target_task_ids\":[-1],\"exchange_type\":\"PassThrough\",\"connection_details\":[{\"tunnel_id\":\"tunnel1+-1\",\"sender_target_task_id\":-1,\"sender_target_host\":\"172.16.201.186:16220\",\"is_local\":false,\"packets\":2,\"bytes\":177}]},{\"id\":\"Limit_14\",\"type\":\"Limit\",\"children\":[\"TableFullScan_13\"],\"outbound_rows\":1,\"outbound_blocks\":1,\"outbound_bytes\":9,\"execution_time_ns\":2000000},{\"id\":\"TableFullScan_13\",\"type\":\"TableScan\",\"children\":[],\"outbound_rows\":2,\"outbound_blocks\":2,\"outbound_bytes\":18,\"execution_time_ns\":1000000,\"connection_details\":[{\"is_local\":true,\"packets\":0,\"bytes\":18},{\"is_local\":false,\"packets\":0,\"bytes\":0}]}],\"host\":\"172.16.201.17:3930\",\"task_init_timestamp\":1678243942736338000,\"task_start_timestamp\":1678243942738913000,\"task_end_timestamp\":1678243942740722000,\"compile_start_timestamp\":1678243942736624000,\"compile_end_timestamp\":1678243942738873000,\"read_wait_index_start_timestamp\":1678243942736791000,\"read_wait_index_end_timestamp\":1678243942737554000,\"local_input_bytes\":18,\"remote_input_bytes\":0,\"output_bytes\":9,\"status\":\"FINISHED\",\"error_message\":\"\",\"working_time\":0,\"memory_peak\":3411984}"] [source="mpp_task_tracing MPP<query:439941574777110531,task:1>"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [INFO] [MPPTask.cpp:445] ["task ends, time cost is 4 ms."] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [MinTSOScheduler.cpp:100] ["Finished query 439941574777110531 (is min = true) is deleted from active set true left 1 or waiting set false left 0."] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [INFO] [MinTSOScheduler.cpp:264] ["min_tso query is updated from 439941574777110531 to 18446744073709551615 as finishing it, used threads = 18, 0 active and 0 waiting queries."] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [MPPTask.cpp:225] ["task unregistered"] [source=MPP<query:43994157477711053,task:1>] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [MPPTask.cpp:74] ["finish MPPTask: MPP<query:439941574777110531,task:1>"] [source=MPP<query:439941574777110531,task:1>] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:61] ["Destroy, pool_id=5 ref_no=7"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:61] ["Destroy, pool_id=5 ref_no=6"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:61] ["Destroy, pool_id=5 ref_no=5"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:61] ["Destroy, pool_id=5 ref_no=4"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:61] ["Destroy, pool_id=5 ref_no=3"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:61] ["Destroy, pool_id=5 ref_no=2"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:61] ["Destroy, pool_id=5 ref_no=1"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [UnorderedInputStream.h:61] ["Destroy, pool_id=5 ref_no=0"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=55]
[2023/03/08 10:52:22.740 +08:00] [DEBUG] [SegmentReadTaskPool.h:206] ["Done. pool_id=5 table_id=176 pop=8 pop_empty=8 pop_empty_ratio=1 max_queue_size=2 blk_avg_bytes=9 approximate_max_pending_block_bytes=0.00MB total_count=2 total_bytes=0.00MB"] [source="MPP<query:439941574777110531,task:1> table_id=176"] [thread_id=41]
[2023/03/08 10:52:22.741 +08:00] [DEBUG] [FlashService.cpp:329] ["cancel mpp task request: meta {\n  start_ts: 439941574777110531\n}\n"] [source=FlashService] [thread_id=39]
[2023/03/08 10:52:22.741 +08:00] [WARN] [MPPTaskManager.cpp:152] ["Begin to abort query: 439941574777110531, abort type: ONCANCELLATION, reason: Receive cancel request from TiDB"] [thread_id=39]
[2023/03/08 10:52:22.741 +08:00] [WARN] [MPPTaskManager.cpp:162] ["439941574777110531 does not found in task manager, skip abort"] [thread_id=39]

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 in mpp.go around line 411, where the “stream unknown error” message is logged, and compare it with the reproduced LIMIT query and accompanying TiFlash logs. Change the requested log level and make the message more precise; done means the resulting log is more useful for debugging this cancellation case.

Written by the indexing model from the issue text.

Assessment

Tech stack
cpp, go
Domain
distributed-systems, observability
Issue type
Feature
Difficulty
2/5
Estimated time
1-3 hours
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.