Make event_time in query_log for QueryFinish* match with finish_time_us in opentelemetry_span_log

Author: azat

src/Common/OpenTelemetryTraceContext.cpp

@@ -147,7 +147,7 @@ SpanHolder::SpanHolder(std::string_view _operation_name, SpanKind _kind)
     current_trace_context->span_id = this->span_id;
 }
 
-void SpanHolder::finish() noexcept
+void SpanHolder::finish(std::chrono::system_clock::time_point time) noexcept
 {
     if (!this->isTraceEnabled())
         return;
@@ -163,9 +163,7 @@ void SpanHolder::finish() noexcept
         /// The log might be disabled, check it before use
         if (log)
         {
-            this->finish_time_us
-                = std::chrono::duration_cast<std::chrono::microseconds>(std::chrono::system_clock::now().time_since_epoch()).count();
-
+            this->finish_time_us = std::chrono::duration_cast<std::chrono::microseconds>(time.time_since_epoch()).count();
             log->add(OpenTelemetrySpanLogElement(*this));
         }
     }
@@ -179,7 +177,7 @@ void SpanHolder::finish() noexcept
 
 SpanHolder::~SpanHolder()
 {
-    finish();
+    finish(std::chrono::system_clock::now());
 }
 
 bool TracingContext::parseTraceparentHeader(std::string_view traceparent, String & error)

src/Common/OpenTelemetryTraceContext.h

@@ -161,7 +161,7 @@ struct SpanHolder : public Span
 
     /// Finish a span explicitly if needed.
     /// It's safe to call it multiple times
-    void finish() noexcept;
+    void finish(std::chrono::system_clock::time_point time) noexcept;
 };
 
 }

src/Interpreters/executeQuery.cpp

@@ -583,13 +583,13 @@ void logQueryFinish(
     const Settings & settings = context->getSettingsRef();
     auto log_queries = settings[Setting::log_queries] && !internal;
 
+    const auto time_now = std::chrono::system_clock::now();
     QueryStatusPtr process_list_elem = context->getProcessListElement();
     if (process_list_elem)
     {
         /// Update performance counters before logging to query_log
         CurrentThread::finalizePerformanceCounters();
 
-        auto time_now = std::chrono::system_clock::now();
         QueryStatusInfo info = process_list_elem->getInfo(true, settings[Setting::log_profile_events]);
         logQueryMetricLogFinish(context, internal, elem.client_info.current_query_id, time_now, std::make_shared<QueryStatusInfo>(info));
         elem.type = QueryLogElementType::QUERY_FINISH;
@@ -652,7 +652,7 @@ void logQueryFinish(
                 query_span->addAttribute(fmt::format("clickhouse.setting.{}", change.name), convertFieldToString(change.value));
             }
         }
-        query_span->finish();
+        query_span->finish(time_now);
     }
 }
 
@@ -721,7 +721,7 @@ void logQueryException(
         query_span->addAttribute("clickhouse.query_id", elem.client_info.current_query_id);
         query_span->addAttribute("clickhouse.exception", elem.exception);
         query_span->addAttribute("clickhouse.exception_code", elem.exception_code);
-        query_span->finish();
+        query_span->finish(time_now);
     }
 }
 
@@ -843,7 +843,7 @@ void logExceptionBeforeStart(
         query_span->addAttribute("clickhouse.exception", elem.exception);
         query_span->addAttribute("db.statement", elem.query);
         query_span->addAttribute("clickhouse.query_id", elem.client_info.current_query_id);
-        query_span->finish();
+        query_span->finish(query_end_time);
     }
 
     ProfileEvents::increment(ProfileEvents::FailedQuery);