Small refactor to ease debugging when something happens on the CI

This commit is contained in:
Pablo Marcos 2024-11-08 11:38:43 +00:00
parent 9cdd56abbc
commit 96383d42b1
3 changed files with 12 additions and 13 deletions

View File

@ -148,7 +148,7 @@ void QueryMetricLog::startQuery(const String & query_id, TimePoint start_time, U
{
QueryMetricLogStatus query_status;
query_status.interval_milliseconds = interval_milliseconds;
query_status.next_collect_time = start_time + std::chrono::milliseconds(interval_milliseconds);
query_status.next_collect_time = start_time;
auto context = getContext();
const auto & process_list = context->getProcessList();
@ -213,6 +213,7 @@ void QueryMetricLog::finishQuery(const String & query_id, TimePoint finish_time,
void QueryMetricLogStatus::scheduleNext(String query_id)
{
next_collect_time += std::chrono::milliseconds(interval_milliseconds);
const auto now = std::chrono::system_clock::now();
if (next_collect_time > now)
{
@ -229,8 +230,9 @@ void QueryMetricLogStatus::scheduleNext(String query_id)
std::optional<QueryMetricLogElement> QueryMetricLogStatus::createLogMetricElement(const String & query_id, const QueryStatusInfo & query_info, TimePoint query_info_time, bool schedule_next)
{
LOG_TRACE(logger, "Collecting query_metric_log for query {} and interval {} ms with QueryStatusInfo from {}. Schedule next: {}",
query_id, interval_milliseconds, timePointToString(query_info_time), schedule_next);
LOG_TRACE(logger, "Collecting query_metric_log for query {} and interval {} ms with QueryStatusInfo from {}. Next collection time: {}",
query_id, interval_milliseconds, timePointToString(query_info_time),
schedule_next ? timePointToString(next_collect_time + std::chrono::milliseconds(interval_milliseconds)) : "finished");
if (query_info_time <= last_collect_time)
{
@ -276,15 +278,12 @@ std::optional<QueryMetricLogElement> QueryMetricLogStatus::createLogMetricElemen
}
else
{
LOG_TRACE(logger, "Query {} has no profile counters", query_id);
LOG_WARNING(logger, "Query {} has no profile counters", query_id);
elem.profile_events = std::vector<ProfileEvents::Count>(ProfileEvents::end());
}
if (schedule_next)
{
next_collect_time += std::chrono::milliseconds(interval_milliseconds);
scheduleNext(query_id);
}
return elem;
}

View File

@ -23,8 +23,8 @@
--Interval 123: check that the SleepFunctionCalls, SleepFunctionMilliseconds and ProfileEvent_SleepFunctionElapsedMicroseconds are correct
1
--Check that a query_metric_log_interval=0 disables the collection
0
1
-Check that a query which execution time is less than query_metric_log_interval is never collected
0
1
--Check that there is a final event when queries finish
3
1

View File

@ -84,17 +84,17 @@ check_log 123
# query_metric_log_interval=0 disables the collection altogether
$CLICKHOUSE_CLIENT -m -q """
SELECT '--Check that a query_metric_log_interval=0 disables the collection';
SELECT count() FROM system.query_metric_log WHERE event_date >= yesterday() AND query_id = '${query_prefix}_0'
SELECT count() == 0 FROM system.query_metric_log WHERE event_date >= yesterday() AND query_id = '${query_prefix}_0'
"""
# a quick query that takes less than query_metric_log_interval is never collected
$CLICKHOUSE_CLIENT -m -q """
SELECT '-Check that a query which execution time is less than query_metric_log_interval is never collected';
SELECT count() FROM system.query_metric_log WHERE event_date >= yesterday() AND query_id = '${query_prefix}_fast'
SELECT count() == 0 FROM system.query_metric_log WHERE event_date >= yesterday() AND query_id = '${query_prefix}_fast'
"""
# a query that takes more than query_metric_log_interval is collected including the final row
$CLICKHOUSE_CLIENT -m -q """
SELECT '--Check that there is a final event when queries finish';
SELECT count() FROM system.query_metric_log WHERE event_date >= yesterday() AND query_id = '${query_prefix}_1000'
SELECT count() > 2 FROM system.query_metric_log WHERE event_date >= yesterday() AND query_id = '${query_prefix}_1000'
"""