Backport #59662 to 24.1: Fix query start time on non initial queries

src/Interpreters/executeQuery.cpp

@@ -663,31 +663,25 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
     if (query_span && query_span->trace_id != UUID{})
         LOG_TRACE(getLogger("executeQuery"), "Query span trace_id for opentelemetry log: {}", query_span->trace_id);
 
+    /// Used for logging query start time in system.query_log
     auto query_start_time = std::chrono::system_clock::now();
 
-    /// Used to set the watch in QueryStatus and the output formats. It is not based on query_start_time as that might be based on
-    /// the value passed by the client
+    /// Used for:
+    /// * Setting the watch in QueryStatus (controls timeouts and progress) and the output formats
+    /// * Logging query duration (system.query_log)
     Stopwatch start_watch{CLOCK_MONOTONIC};
 
     const auto & client_info = context->getClientInfo();
 
-    if (!internal)
+    if (!internal && client_info.initial_query_start_time == 0)
     {
         // If it's not an internal query and we don't see an initial_query_start_time yet, initialize it
         // to current time. Internal queries are those executed without an independent client context,
         // thus should not set initial_query_start_time, because it might introduce data race. It's also
         // possible to have unset initial_query_start_time for non-internal and non-initial queries. For
         // example, the query is from an initiator that is running an old version of clickhouse.
         // On the other hand, if it's initialized then take it as the start of the query
-        if (client_info.initial_query_start_time == 0)
-        {
-            context->setInitialQueryStartTime(query_start_time);
-        }
-        else
-        {
-            query_start_time = std::chrono::time_point<std::chrono::system_clock>(
-                std::chrono::microseconds{client_info.initial_query_start_time_microseconds});
-        }
+        context->setInitialQueryStartTime(query_start_time);
     }
 
     assert(internal || CurrentThread::get().getQueryContext());

tests/queries/0_stateless/02985_shard_query_start_time.reference

@@ -0,0 +1,2 @@
+QueryStart	2	2	2	2
+QueryFinish	2	2	2	2

tests/queries/0_stateless/02985_shard_query_start_time.sql

@@ -0,0 +1,34 @@
+DROP TABLE IF EXISTS sharded_table;
+CREATE TABLE sharded_table (dummy UInt8) ENGINE = Distributed('test_cluster_two_shards', 'system', 'one');
+
+SET prefer_localhost_replica=0;
+SELECT * FROM sharded_table FORMAT Null SETTINGS log_comment='02985_shard_query_start_time_query_1';
+
+SYSTEM FLUSH LOGS;
+
+-- Check that there are 2 queries to shards and for each one query_start_time_microseconds is more recent
+-- than initial_query_start_time_microseconds, and initial_query_start_time_microseconds matches the original query
+-- query_start_time_microseconds
+WITH
+(
+    SELECT
+        (query_id, query_start_time, query_start_time_microseconds)
+    FROM
+        system.query_log
+    WHERE
+          event_date >= yesterday()
+      AND current_database = currentDatabase()
+      AND log_comment = '02985_shard_query_start_time_query_1'
+      AND type = 'QueryFinish'
+) AS id_and_start_tuple
+SELECT
+    type,
+    countIf(query_start_time >= initial_query_start_time), -- Using >= because it's comparing seconds
+    countIf(query_start_time_microseconds > initial_query_start_time_microseconds),
+    countIf(initial_query_start_time = id_and_start_tuple.2),
+    countIf(initial_query_start_time_microseconds = id_and_start_tuple.3)
+FROM
+    system.query_log
+WHERE
+    NOT is_initial_query AND initial_query_id = id_and_start_tuple.1
+GROUP BY type;