Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Use read tso instead of threrad ID in 'DBGInvoke search_log_for_key' #5715

Merged
merged 3 commits into from
Aug 29, 2022
Merged

Use read tso instead of threrad ID in 'DBGInvoke search_log_for_key' #5715

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
b2c8826
Use read tso instead of threrad ID in 'DBGInvoke search_log_for_key'
JinheLin Aug 26, 2022
860824c
Fix lint.
JinheLin Aug 26, 2022
52557af
Merge branch 'master' into use_tso_to_search_log
ti-chi-bot Aug 29, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
26 changes: 13 additions & 13 deletions dbms/src/Debug/dbgFuncMisc.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,13 +23,13 @@

namespace DB
{
inline size_t getThreadIdForLog(const String & line)
inline size_t getReadTSOForLog(const String & line)
{
auto sub_line = line.substr(line.find("thread_id="));
auto sub_line = line.substr(line.find("read_tso="));
std::regex rx(R"((0|[1-9][0-9]*))");
std::smatch m;
if (regex_search(sub_line, m, rx))
return std::stoi(m[1]);
return std::stoul(m[1]);
else
return 0;
}
Expand All @@ -49,41 +49,41 @@ void dbgFuncSearchLogForKey(Context & context, const ASTs & args, DBGInvoker::Pr
if (args.size() < 2)
throw Exception("Args not matched, should be: key, thread_hint", ErrorCodes::BAD_ARGUMENTS);

String key = safeGet<String>(typeid_cast<const ASTLiteral &>(*args[0]).value);
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`
String thread_hint = safeGet<String>(typeid_cast<const ASTLiteral &>(*args[1]).value);
auto tso_hint = safeGet<String>(typeid_cast<const ASTLiteral &>(*args[1]).value);
auto log_path = context.getConfigRef().getString("logger.log");

std::ifstream file(log_path);
// get the lines containing `thread_hint` and `key`
std::vector<String> thread_hint_line_candidates;
std::vector<String> tso_hint_line_candidates;
std::vector<String> key_line_candidates;
{
String line;
while (std::getline(file, line))
{
if ((line.find(thread_hint) != String::npos) && (line.find("DBGInvoke") == String::npos))
thread_hint_line_candidates.emplace_back(line);
if ((line.find(tso_hint) != String::npos) && (line.find("DBGInvoke") == String::npos))
tso_hint_line_candidates.emplace_back(line);
else if ((line.find(key) != String::npos) && (line.find("DBGInvoke") == String::npos))
key_line_candidates.emplace_back(line);
}
}
// get target thread id
if (thread_hint_line_candidates.empty() || key_line_candidates.empty())
// get target read tso
if (tso_hint_line_candidates.empty() || key_line_candidates.empty())
{
output("Invalid");
return;
}
size_t target_thread_id = getThreadIdForLog(thread_hint_line_candidates.back());
if (target_thread_id == 0)
size_t target_read_tso = getReadTSOForLog(tso_hint_line_candidates.back());
if (target_read_tso == 0)
{
output("Invalid");
return;
}
String target_line;
for (auto iter = key_line_candidates.rbegin(); iter != key_line_candidates.rend(); iter++)
{
if (getThreadIdForLog(*iter) == target_thread_id)
if (getReadTSOForLog(*iter) == target_read_tso)
{
target_line = *iter;
break;
Expand Down
5 changes: 3 additions & 2 deletions dbms/src/Storages/StorageDeltaMerge.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -646,7 +646,8 @@ BlockInputStreams StorageDeltaMerge::read(
throw Exception("TMTContext is not initialized", ErrorCodes::LOGICAL_ERROR);

const auto & mvcc_query_info = *query_info.mvcc_query_info;
auto tracing_logger = Logger::get("StorageDeltaMerge", log->identifier(), query_info.req_id);
auto req_id = fmt::format("{} read_tso={}", query_info.req_id, mvcc_query_info.read_tso);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Adding read_tso={} make it too verbose for logging ....

[2022/09/06 17:05:28.830 +08:00] [DEBUG] [Segment.cpp:1470] ["Segment:<segment_id=146 epoch=17> MPP<query:435802637197639681,task:1> Table<129> read_tso=435802637197639681 Begin segment getReadInfo"] [thread_id=89]
[2022/09/06 17:05:28.831 +08:00] [DEBUG] [Segment.cpp:1470] ["Segment:<segment_id=1 epoch=32> MPP<query:435802637197639681,task:1> Table<129> read_tso=435802637197639681 Begin segment getReadInfo"] [thread_id=90]
[2022/09/06 17:05:28.831 +08:00] [DEBUG] [Segment.cpp:1470] ["Segment:<segment_id=146 epoch=17> MPP<query:435802637197639681,task:1> Table<129> read_tso=435802637197639681 Begin segment getReadInfo"] [thread_id=91]
[2022/09/06 17:05:28.831 +08:00] [DEBUG] [Segment.cpp:1485] ["Segment:<segment_id=1 epoch=32> MPP<query:435802637197639681,task:1> Table<129> read_tso=435802637197639681 Finish segment getReadInfo"] [thread_id=90]
[2022/09/06 17:05:28.831 +08:00] [DEBUG] [Segment.cpp:1470] ["Segment:<segment_id=149 epoch=14> MPP<query:435802637197639681,task:1> Table<129> read_tso=435802637197639681 Begin segment getReadInfo"] [thread_id=92]
[2022/09/06 17:05:28.831 +08:00] [DEBUG] [Segment.cpp:1470] ["Segment:<segment_id=149 epoch=14> MPP<query:435802637197639681,task:1> Table<129> read_tso=435802637197639681 Begin segment getReadInfo"] [thread_id=93]
[2022/09/06 17:05:28.832 +08:00] [DEBUG] [Segment.cpp:1485] ["Segment:<segment_id=149 epoch=14> MPP<query:435802637197639681,task:1> Table<129> read_tso=435802637197639681 Finish segment getReadInfo"] [thread_id=92]
[2022/09/06 17:05:28.832 +08:00] [DEBUG] [Segment.cpp:1470] ["Segment:<segment_id=146 epoch=17> MPP<query:435802637197639681,task:1> Table<129> read_tso=435802637197639681 Begin segment getReadInfo"] [thread_id=94]
[2022/09/06 17:05:28.832 +08:00] [DEBUG] [Segment.cpp:1485] ["Segment:<segment_id=149 epoch=14> MPP<query:435802637197639681,task:1> Table<129> read_tso=435802637197639681 Finish segment getReadInfo"] [thread_id=93]
[2022/09/06 17:05:28.832 +08:00] [DEBUG] [Segment.cpp:1470] ["Segment:<segment_id=152 epoch=14> MPP<query:435802637197639681,task:1> Table<129> read_tso=435802637197639681 Begin segment getReadInfo"] [thread_id=95]

auto tracing_logger = Logger::get("StorageDeltaMerge", log->identifier(), req_id);

LOG_FMT_DEBUG(tracing_logger, "Read with tso: {}", mvcc_query_info.read_tso);

Expand Down Expand Up @@ -756,7 +757,7 @@ BlockInputStreams StorageDeltaMerge::read(
num_streams,
/*max_version=*/mvcc_query_info.read_tso,
rs_operator,
query_info.req_id,
req_id,
query_info.keep_order,
/* is_fast_mode */ tidb_table_info.tiflash_mode == TiDB::TiFlashMode::Fast, // read in normal mode or read in fast mode
max_block_size,
Expand Down