From 949bd03b1fafb1c38dcbe59dde2860254e8cebfe Mon Sep 17 00:00:00 2001 From: JaySon Date: Thu, 8 Sep 2022 14:44:57 +0800 Subject: [PATCH] *: Fix verbose logging in the DeltaTree engine (#5811) ref pingcap/tiflash#5718 --- dbms/src/Debug/dbgFuncMisc.cpp | 5 ++-- dbms/src/Storages/StorageDeltaMerge.cpp | 12 +++----- .../misc/timestamp_rough_set_filter.test | 29 ++++++++++--------- 3 files changed, 22 insertions(+), 24 deletions(-) diff --git a/dbms/src/Debug/dbgFuncMisc.cpp b/dbms/src/Debug/dbgFuncMisc.cpp index b6f4521b4fa..50b6ebffb52 100644 --- a/dbms/src/Debug/dbgFuncMisc.cpp +++ b/dbms/src/Debug/dbgFuncMisc.cpp @@ -29,7 +29,8 @@ inline size_t getReadTSOForLog(const String & line) { std::regex rx(R"((0|[1-9][0-9]*))"); std::smatch m; - auto pos = line.find("read_tso="); + // Rely on that MPP task prefix "MPP" + auto pos = line.find("query:"); if (pos != std::string::npos && regex_search(line.cbegin() + pos, line.cend(), m, rx)) { return std::stoul(m[1]); @@ -61,7 +62,7 @@ void dbgFuncSearchLogForKey(Context & context, const ASTs & args, DBGInvoker::Pr throw Exception("Args not matched, should be: key, thread_hint", ErrorCodes::BAD_ARGUMENTS); auto key = safeGet(typeid_cast(*args[0]).value); - // the candidate line must be printed by a thread which also print a line contains `thread_hint` + // the candidate line must be printed by a thread which also print a line contains `tso_hint` auto tso_hint = safeGet(typeid_cast(*args[1]).value); auto log_path = context.getConfigRef().getString("logger.log"); diff --git a/dbms/src/Storages/StorageDeltaMerge.cpp b/dbms/src/Storages/StorageDeltaMerge.cpp index f62349794d8..55e8348861a 100644 --- a/dbms/src/Storages/StorageDeltaMerge.cpp +++ b/dbms/src/Storages/StorageDeltaMerge.cpp @@ -639,16 +639,12 @@ BlockInputStreams StorageDeltaMerge::read( } // Read with MVCC filtering - if (unlikely(!query_info.mvcc_query_info)) - throw Exception("mvcc query info is null", ErrorCodes::LOGICAL_ERROR); - TMTContext & tmt = context.getTMTContext(); - if (unlikely(!tmt.isInitialized())) - throw Exception("TMTContext is not initialized", ErrorCodes::LOGICAL_ERROR); + RUNTIME_CHECK(query_info.mvcc_query_info != nullptr); + RUNTIME_CHECK(tmt.isInitialized()); const auto & mvcc_query_info = *query_info.mvcc_query_info; - auto req_id = fmt::format("{} read_tso={}", query_info.req_id, mvcc_query_info.read_tso); - auto tracing_logger = Logger::get("StorageDeltaMerge", log->identifier(), req_id); + auto tracing_logger = Logger::get("StorageDeltaMerge", log->identifier(), query_info.req_id); LOG_FMT_DEBUG(tracing_logger, "Read with tso: {}", mvcc_query_info.read_tso); @@ -758,7 +754,7 @@ BlockInputStreams StorageDeltaMerge::read( num_streams, /*max_version=*/mvcc_query_info.read_tso, rs_operator, - req_id, + query_info.req_id, query_info.keep_order, /* is_fast_scan */ query_info.is_fast_scan, max_block_size, diff --git a/tests/delta-merge-test/query/misc/timestamp_rough_set_filter.test b/tests/delta-merge-test/query/misc/timestamp_rough_set_filter.test index 2aa3085e5bb..b7a70d25fa6 100644 --- a/tests/delta-merge-test/query/misc/timestamp_rough_set_filter.test +++ b/tests/delta-merge-test/query/misc/timestamp_rough_set_filter.test @@ -14,6 +14,7 @@ # Must enable DT rough set filter and open debug level log to run this test, otherwise disable this test # Preparation. +# Use 'mpp_query:true' to make the logging contains tso prefix => DBGInvoke __enable_schema_sync_service('true') => DBGInvoke __drop_tidb_table(default, test) @@ -42,7 +43,7 @@ └───────────────┴────────────┴─────────────────┴───────────────────┘ # The default time zone in cop request is UTC -=> DBGInvoke dag('select * from default.test') +=> DBGInvoke dag('select * from default.test', 4, 'mpp_query:true') ┌─test.col_1─┬────────────────test.col_2─┐ │ 50 │ 2019-06-10 09:00:00.00000 │ │ 51 │ 2019-06-11 07:00:00.00000 │ @@ -52,14 +53,14 @@ │ 55 │ 2019-06-13 12:00:01.00000 │ └────────────┴───────────────────────────┘ -=> DBGInvoke dag('select * from default.test where col_2 < cast_string_datetime(\'2019-06-10 09:00:00.00000\')') +=> DBGInvoke dag('select * from default.test where col_2 < cast_string_datetime(\'2019-06-10 09:00:00.00000\')', 4, 'mpp_query:true') => DBGInvoke search_log_for_key('RSFilter exclude rate', 'Rough set filter') ┌─search_log_for_key("RSFilter exclude rate")─┐ │ 100.00 │ └─────────────────────────────────────────────┘ -=> DBGInvoke dag('select * from default.test where col_2 <= cast_string_datetime(\'2019-06-10 09:00:00.00000\')') +=> DBGInvoke dag('select * from default.test where col_2 <= cast_string_datetime(\'2019-06-10 09:00:00.00000\')', 4, 'mpp_query:true') ┌─test.col_1─┬────────────────test.col_2─┐ │ 50 │ 2019-06-10 09:00:00.00000 │ └────────────┴───────────────────────────┘ @@ -72,14 +73,14 @@ # when using 'default' encoding, return timestamp value is shown in UTC time zone # but the literal timestamp value in where clause is in the time zone specified by the cop request # so '2019-06-10 17:00:00.00000'(tz_offset:28800) below is equal to '2019-06-10 09:00:00.00000' in UTC -=> DBGInvoke dag('select * from default.test where col_2 < cast_string_datetime(\'2019-06-10 17:00:00.00000\')',4,'encode_type:default,tz_offset:28800') +=> DBGInvoke dag('select * from default.test where col_2 < cast_string_datetime(\'2019-06-10 17:00:00.00000\')',4,'encode_type:default,tz_offset:28800,mpp_query:true') => DBGInvoke search_log_for_key('RSFilter exclude rate', 'Rough set filter') ┌─search_log_for_key("RSFilter exclude rate")─┐ │ 100.00 │ └─────────────────────────────────────────────┘ -=> DBGInvoke dag('select * from default.test where col_2 <= cast_string_datetime(\'2019-06-10 17:00:00.00000\')',4,'encode_type:default,tz_offset:28800') +=> DBGInvoke dag('select * from default.test where col_2 <= cast_string_datetime(\'2019-06-10 17:00:00.00000\')',4,'encode_type:default,tz_offset:28800,mpp_query:true') ┌─test.col_1─┬────────────────test.col_2─┐ │ 50 │ 2019-06-10 09:00:00.00000 │ └────────────┴───────────────────────────┘ @@ -89,14 +90,14 @@ │ 0.00 │ └─────────────────────────────────────────────┘ -=> DBGInvoke dag('select * from default.test where col_2 < cast_string_datetime(\'2019-06-10 04:00:00.00000\')',4,'encode_type:default,tz_name:America/Chicago') +=> DBGInvoke dag('select * from default.test where col_2 < cast_string_datetime(\'2019-06-10 04:00:00.00000\')',4,'encode_type:default,tz_name:America/Chicago,mpp_query:true') => DBGInvoke search_log_for_key('RSFilter exclude rate', 'Rough set filter') ┌─search_log_for_key("RSFilter exclude rate")─┐ │ 100.00 │ └─────────────────────────────────────────────┘ -=> DBGInvoke dag('select * from default.test where col_2 <= cast_string_datetime(\'2019-06-10 04:00:00.00000\')',4,'encode_type:default,tz_name:America/Chicago') +=> DBGInvoke dag('select * from default.test where col_2 <= cast_string_datetime(\'2019-06-10 04:00:00.00000\')',4,'encode_type:default,tz_name:America/Chicago,mpp_query:true') ┌─test.col_1─┬────────────────test.col_2─┐ │ 50 │ 2019-06-10 09:00:00.00000 │ └────────────┴───────────────────────────┘ @@ -106,14 +107,14 @@ │ 0.00 │ └─────────────────────────────────────────────┘ -=> DBGInvoke dag('select * from default.test where col_2 > cast_string_datetime(\'2019-06-13 12:00:01.00000\')') +=> DBGInvoke dag('select * from default.test where col_2 > cast_string_datetime(\'2019-06-13 12:00:01.00000\')', 4, 'mpp_query:true') => DBGInvoke search_log_for_key('RSFilter exclude rate', 'Rough set filter') ┌─search_log_for_key("RSFilter exclude rate")─┐ │ 100.00 │ └─────────────────────────────────────────────┘ -=> DBGInvoke dag('select * from default.test where col_2 >= cast_string_datetime(\'2019-06-13 12:00:01.00000\')') +=> DBGInvoke dag('select * from default.test where col_2 >= cast_string_datetime(\'2019-06-13 12:00:01.00000\')', 4, 'mpp_query:true') ┌─test.col_1─┬────────────────test.col_2─┐ │ 55 │ 2019-06-13 12:00:01.00000 │ └────────────┴───────────────────────────┘ @@ -123,14 +124,14 @@ │ 0.00 │ └─────────────────────────────────────────────┘ -=> DBGInvoke dag('select * from default.test where col_2 > cast_string_datetime(\'2019-06-13 20:00:01.00000\')',4,'encode_type:default,tz_offset:28800') +=> DBGInvoke dag('select * from default.test where col_2 > cast_string_datetime(\'2019-06-13 20:00:01.00000\')',4,'encode_type:default,tz_offset:28800,mpp_query:true') => DBGInvoke search_log_for_key('RSFilter exclude rate', 'Rough set filter') ┌─search_log_for_key("RSFilter exclude rate")─┐ │ 100.00 │ └─────────────────────────────────────────────┘ -=> DBGInvoke dag('select * from default.test where col_2 >= cast_string_datetime(\'2019-06-13 20:00:01.00000\')',4,'encode_type:default,tz_offset:28800') +=> DBGInvoke dag('select * from default.test where col_2 >= cast_string_datetime(\'2019-06-13 20:00:01.00000\')',4,'encode_type:default,tz_offset:28800,mpp_query:true') ┌─test.col_1─┬────────────────test.col_2─┐ │ 55 │ 2019-06-13 12:00:01.00000 │ └────────────┴───────────────────────────┘ @@ -140,19 +141,19 @@ │ 0.00 │ └─────────────────────────────────────────────┘ -=> DBGInvoke dag('select * from default.test where col_2 > cast_string_datetime(\'2019-06-13 07:00:01.00000\')',4,'encode_type:default,tz_name:America/Chicago') +=> DBGInvoke dag('select * from default.test where col_2 > cast_string_datetime(\'2019-06-13 07:00:01.00000\')',4,'encode_type:default,tz_name:America/Chicago,mpp_query:true') => DBGInvoke search_log_for_key('RSFilter exclude rate', 'Rough set filter') ┌─search_log_for_key("RSFilter exclude rate")─┐ │ 100.00 │ └─────────────────────────────────────────────┘ -=> DBGInvoke dag('select * from default.test where col_2 >= cast_string_datetime(\'2019-06-13 07:00:01.00000\')',4,'encode_type:default,tz_name:America/Chicago') +=> DBGInvoke dag('select * from default.test where col_2 >= cast_string_datetime(\'2019-06-13 07:00:01.00000\')',4,'encode_type:default,tz_name:America/Chicago,mpp_query:true') ┌─test.col_1─┬────────────────test.col_2─┐ │ 55 │ 2019-06-13 12:00:01.00000 │ └────────────┴───────────────────────────┘ -=> DBGInvoke search_log_for_key('RSFilter exclude rate', 'Rough set filter') +=> DBGInvoke search_log_for_key('RSFilter exclude rate', 'Rough set filter', 4, 'mpp_query:true') ┌─search_log_for_key("RSFilter exclude rate")─┐ │ 0.00 │ └─────────────────────────────────────────────┘