Merge pull request #16563 from azat/query_thread_log_query_duration_ms-fix

Fix query_thread_log.query_duration_ms

src/Common/ThreadProfileEvents.h

@@ -75,13 +75,6 @@ inline TUInt safeDiff(TUInt prev, TUInt curr)
 }
 
 
-inline UInt64 getCurrentTimeNanoseconds(clockid_t clock_type = CLOCK_MONOTONIC)
-{
-    struct timespec ts;
-    clock_gettime(clock_type, &ts);
-    return ts.tv_sec * 1000000000ULL + ts.tv_nsec;
-}
-
 struct RUsageCounters
 {
     /// In nanoseconds
@@ -108,13 +101,13 @@ struct RUsageCounters
         hard_page_faults = static_cast<UInt64>(rusage.ru_majflt);
     }
 
-    static RUsageCounters current(UInt64 real_time_ = getCurrentTimeNanoseconds())
+    static RUsageCounters current()
     {
         ::rusage rusage {};
 #if !defined(__APPLE__)
         ::getrusage(RUSAGE_THREAD, &rusage);
 #endif
-        return RUsageCounters(rusage, real_time_);
+        return RUsageCounters(rusage, getClockMonotonic());
     }
 
     static void incrementProfileEvents(const RUsageCounters & prev, const RUsageCounters & curr, ProfileEvents::Counters & profile_events)
@@ -133,6 +126,14 @@ struct RUsageCounters
         incrementProfileEvents(last_counters, current_counters, profile_events);
         last_counters = current_counters;
     }
+
+private:
+    static inline UInt64 getClockMonotonic()
+    {
+        struct timespec ts;
+        clock_gettime(CLOCK_MONOTONIC, &ts);
+        return ts.tv_sec * 1000000000ULL + ts.tv_nsec;
+    }
 };
 
 // thread_local is disabled in Arcadia, so we have to use a dummy implementation

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);

tests/queries/0_stateless/01548_query_log_query_execution_ms.reference

+1
+1

tests/queries/0_stateless/01548_query_log_query_execution_ms.sql

+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;

tests/queries/0_stateless/arcadia_skip_list.txt

@@ -156,3 +156,4 @@
 01526_max_untracked_memory
 01530_drop_database_atomic_sync
 01547_query_log_current_database
+01548_query_log_query_execution_ms