Skip to content

Commit

Permalink
*: Fix verbose logging in the DeltaTree engine (#5811)
Browse files Browse the repository at this point in the history 
ref #5718
  • Loading branch information
@JaySon-Huang
JaySon-Huang authored Sep 8, 2022
1 parent dd3e6a0 commit 949bd03
Show file tree
Hide file tree
Showing 3 changed files with 22 additions and 24 deletions.
5 changes: 3 additions & 2 deletions dbms/src/Debug/dbgFuncMisc.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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<query:435802637197639681,task:1>"
auto pos = line.find("query:");
if (pos != std::string::npos && regex_search(line.cbegin() + pos, line.cend(), m, rx))
{
return std::stoul(m[1]);
Expand Down Expand Up @@ -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<String>(typeid_cast<const ASTLiteral &>(*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<String>(typeid_cast<const ASTLiteral &>(*args[1]).value);
auto log_path = context.getConfigRef().getString("logger.log");

Expand Down
12 changes: 4 additions & 8 deletions dbms/src/Storages/StorageDeltaMerge.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);

Expand Down Expand Up @@ -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,
Expand Down
29 changes: 15 additions & 14 deletions tests/delta-merge-test/query/misc/timestamp_rough_set_filter.test
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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 │
Expand All @@ -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 │
└────────────┴───────────────────────────┘
Expand All @@ -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 │
└────────────┴───────────────────────────┘
Expand All @@ -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 │
└────────────┴───────────────────────────┘
Expand All @@ -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 │
└────────────┴───────────────────────────┘
Expand All @@ -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 │
└────────────┴───────────────────────────┘
Expand All @@ -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 │
└─────────────────────────────────────────────┘
Expand Down

0 comments on commit 949bd03

Please sign in to comment.