From 3b188921dd6320289eddb108fe7cdcbaeb28537f Mon Sep 17 00:00:00 2001 From: Azat Khuzhin Date: Sat, 31 Oct 2020 11:15:27 +0300 Subject: [PATCH] Fix query_thread_log.query_duration_ms unit There is a similar problem as in [1], the problem is that getCurrentTimeNanoseconds() returns time using CLOCK_MONOTONIC. [1]: c0e15ba348dae4030bd592ca1635fb3b09043afc ("Fix RealTimeMicroseconds ProfileEvents") --- src/Interpreters/ThreadStatusExt.cpp | 2 +- ...548_query_log_query_execution_ms.reference | 2 ++ .../01548_query_log_query_execution_ms.sql | 28 +++++++++++++++++++ 3 files changed, 31 insertions(+), 1 deletion(-) create mode 100644 tests/queries/0_stateless/01548_query_log_query_execution_ms.reference create mode 100644 tests/queries/0_stateless/01548_query_log_query_execution_ms.sql diff --git a/src/Interpreters/ThreadStatusExt.cpp b/src/Interpreters/ThreadStatusExt.cpp index 2ce98819a44..ffb9e140ce6 100644 --- a/src/Interpreters/ThreadStatusExt.cpp +++ b/src/Interpreters/ThreadStatusExt.cpp @@ -336,7 +336,7 @@ void ThreadStatus::logToQueryThreadLog(QueryThreadLog & thread_log, const String elem.event_time_microseconds = current_time_microseconds; elem.query_start_time = query_start_time; elem.query_start_time_microseconds = query_start_time_microseconds; - elem.query_duration_ms = (getCurrentTimeNanoseconds() - query_start_time_nanoseconds) / 1000000U; + elem.query_duration_ms = (time_in_nanoseconds(now) - query_start_time_nanoseconds) / 1000000U; elem.read_rows = progress_in.read_rows.load(std::memory_order_relaxed); elem.read_bytes = progress_in.read_bytes.load(std::memory_order_relaxed); diff --git a/tests/queries/0_stateless/01548_query_log_query_execution_ms.reference b/tests/queries/0_stateless/01548_query_log_query_execution_ms.reference new file mode 100644 index 00000000000..6ed281c757a --- /dev/null +++ b/tests/queries/0_stateless/01548_query_log_query_execution_ms.reference @@ -0,0 +1,2 @@ +1 +1 diff --git a/tests/queries/0_stateless/01548_query_log_query_execution_ms.sql b/tests/queries/0_stateless/01548_query_log_query_execution_ms.sql new file mode 100644 index 00000000000..e80e84646be --- /dev/null +++ b/tests/queries/0_stateless/01548_query_log_query_execution_ms.sql @@ -0,0 +1,28 @@ +set log_query_threads=1; +set log_queries_min_type='QUERY_FINISH'; +set log_queries=1; +select '01548_query_log_query_execution_ms', sleep(0.4) format Null; +set log_queries=0; +set log_query_threads=0; + +system flush logs; + +select count() +from system.query_log +where + query like '%01548_query_log_query_execution_ms%' + and current_database = currentDatabase() + and query_duration_ms between 100 and 800 + and event_date = today() + and event_time >= now() - interval 1 minute; + +-- at least two threads for processing +-- (but one just waits for another, sigh) +select count() == 2 +from system.query_thread_log +where + query like '%01548_query_log_query_execution_ms%' + and current_database = currentDatabase() + and query_duration_ms between 100 and 800 + and event_date = today() + and event_time >= now() - interval 1 minute;