microsecond precision for start/finish time

programs/server/config.xml

@@ -611,7 +611,7 @@
         <engine>
             engine MergeTree
             partition by toYYYYMM(finish_date)
-            order by (finish_date, finish_time, trace_id)
+            order by (finish_date, finish_time_us, trace_id)
         </engine>
         <database>system</database>
         <table>opentelemetry_log</table>

src/Interpreters/ClientInfo.cpp

@@ -62,11 +62,12 @@ void ClientInfo::write(WriteBuffer & out, const UInt64 server_protocol_revision)
 
     if (server_protocol_revision >= DBMS_MIN_REVISION_WITH_OPENTELEMETRY)
     {
-        // No point writing these numbers with variable length, because they
-        // are random and will probably require the full length anyway.
         if (opentelemetry_trace_id)
         {
+            // Have OpenTelemetry header.
             writeBinary(uint8_t(1), out);
+            // No point writing these numbers with variable length, because they
+            // are random and will probably require the full length anyway.
             writeBinary(opentelemetry_trace_id, out);
             writeBinary(opentelemetry_span_id, out);
             writeBinary(opentelemetry_parent_span_id, out);
@@ -75,6 +76,7 @@ void ClientInfo::write(WriteBuffer & out, const UInt64 server_protocol_revision)
         }
         else
         {
+            // Don't have OpenTelemetry header.
             writeBinary(uint8_t(0), out);
         }
     }

src/Interpreters/OpenTelemetryLog.cpp

@@ -3,6 +3,7 @@
 #include <DataTypes/DataTypeArray.h>
 #include <DataTypes/DataTypeDate.h>
 #include <DataTypes/DataTypeDateTime.h>
+#include <DataTypes/DataTypeDateTime64.h>
 #include <DataTypes/DataTypesNumber.h>
 #include <DataTypes/DataTypeString.h>
 #include <DataTypes/DataTypeUUID.h>
@@ -17,8 +18,8 @@ Block OpenTelemetrySpanLogElement::createBlock()
         {std::make_shared<DataTypeUInt64>(), "span_id"},
         {std::make_shared<DataTypeUInt64>(), "parent_span_id"},
         {std::make_shared<DataTypeString>(), "operation_name"},
-        {std::make_shared<DataTypeDateTime>(), "start_time"},
-        {std::make_shared<DataTypeDateTime>(), "finish_time"},
+        {std::make_shared<DataTypeDateTime64>(6), "start_time_us"},
+        {std::make_shared<DataTypeDateTime64>(6), "finish_time_us"},
         {std::make_shared<DataTypeDate>(), "finish_date"},
         {std::make_shared<DataTypeArray>(std::make_shared<DataTypeString>()),
             "attribute.names"},
@@ -35,9 +36,9 @@ void OpenTelemetrySpanLogElement::appendToBlock(MutableColumns & columns) const
     columns[i++]->insert(span_id);
     columns[i++]->insert(parent_span_id);
     columns[i++]->insert(operation_name);
-    columns[i++]->insert(start_time);
-    columns[i++]->insert(finish_time);
-    columns[i++]->insert(DateLUT::instance().toDayNum(finish_time));
+    columns[i++]->insert(start_time_us);
+    columns[i++]->insert(finish_time_us);
+    columns[i++]->insert(DateLUT::instance().toDayNum(finish_time_us / 1000000));
     columns[i++]->insert(attribute_names);
     columns[i++]->insert(attribute_values);
 }

src/Interpreters/OpenTelemetryLog.h

@@ -15,6 +15,10 @@ struct OpenTelemetrySpanContext
 };
 */
 
+// using TimeMicroseconds = std::chrono::time_point<
+//     std::chrono::local_t,
+//     std::chrono::duration<UInt64, std::micro>>;
+
 // TODO figure out precisely which part of this is run time, and which part we
 // must log.
 struct OpenTelemetrySpan
@@ -23,8 +27,8 @@ struct OpenTelemetrySpan
     UInt64 span_id;
     UInt64 parent_span_id;
     std::string operation_name;
-    time_t start_time;
-    time_t finish_time;
+    UInt64 start_time_us;
+    UInt64 finish_time_us;
     UInt64 duration_ns;
     Array attribute_names;
     Array attribute_values;

src/Interpreters/executeQuery.cpp

@@ -205,7 +205,7 @@ inline UInt64 time_in_seconds(std::chrono::time_point<std::chrono::system_clock>
     return std::chrono::duration_cast<std::chrono::seconds>(timepoint.time_since_epoch()).count();
 }
 
-static void onExceptionBeforeStart(const String & query_for_logging, Context & context, time_t current_time, UInt64 current_time_microseconds, ASTPtr ast)
+static void onExceptionBeforeStart(const String & query_for_logging, Context & context, UInt64 current_time_us, ASTPtr ast)
 {
     /// Exception before the query execution.
     if (auto quota = context.getQuota())
@@ -221,9 +221,9 @@ static void onExceptionBeforeStart(const String & query_for_logging, Context & c
     // all callers to onExceptionBeforeStart upstream construct the timespec for event_time and
     // event_time_microseconds from the same timespec. So it can be assumed that both of these
     // times are equal upto the precision of a second.
-    elem.event_time = current_time;
-    elem.query_start_time = current_time;
-    elem.query_start_time_microseconds = current_time_microseconds;
+    elem.event_time = current_time_us / 1000000;
+    elem.query_start_time = current_time_us / 1000000;
+    elem.query_start_time_microseconds = current_time_us;
 
     elem.current_database = context.getCurrentDatabase();
     elem.query = query_for_logging;
@@ -252,8 +252,8 @@ static void onExceptionBeforeStart(const String & query_for_logging, Context & c
         span.span_id = context.getClientInfo().opentelemetry_span_id;
         span.parent_span_id = context.getClientInfo().opentelemetry_parent_span_id;
         span.operation_name = "query";
-        span.start_time = current_time;
-        span.finish_time = current_time;
+        span.start_time_us = current_time_us;
+        span.finish_time_us = current_time_us;
         span.duration_ns = 0;
 
         // keep values synchonized to type enum in QueryLogElement::createBlock
@@ -309,12 +309,7 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
     bool has_query_tail,
     ReadBuffer * istr)
 {
-    // current_time and current_time_microseconds are both constructed from the same time point
-    // to ensure that both the times are equal upto the precision of a second.
-    const auto now = std::chrono::system_clock::now();
-
-    auto current_time = time_in_seconds(now);
-    auto current_time_microseconds = time_in_microseconds(now);
+    const auto current_time = std::chrono::system_clock::now();
 
     /// If we already executing query and it requires to execute internal query, than
     /// don't replace thread context with given (it can be temporary). Otherwise, attach context to thread.
@@ -364,7 +359,7 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
         logQuery(query_for_logging, context, internal);
 
         if (!internal)
-            onExceptionBeforeStart(query_for_logging, context, current_time, current_time_microseconds, ast);
+            onExceptionBeforeStart(query_for_logging, context, time_in_microseconds(current_time), ast);
 
         throw;
     }
@@ -528,9 +523,9 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
 
             elem.type = QueryLogElementType::QUERY_START;
 
-            elem.event_time = current_time;
-            elem.query_start_time = current_time;
-            elem.query_start_time_microseconds = current_time_microseconds;
+            elem.event_time = time_in_seconds(current_time);
+            elem.query_start_time = time_in_seconds(current_time);
+            elem.query_start_time_microseconds = time_in_microseconds(current_time);
 
             elem.current_database = context.getCurrentDatabase();
             elem.query = query_for_logging;
@@ -599,7 +594,9 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
 
                 elem.type = QueryLogElementType::QUERY_FINISH;
 
-                elem.event_time = time(nullptr);
+                const auto current_time = std::chrono::system_clock::now();
+
+                elem.event_time = time_in_seconds(current_time);
 
                 status_info_to_query_log(elem, info, ast);
 
@@ -660,8 +657,8 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
                     span.span_id = context.getClientInfo().opentelemetry_span_id;
                     span.parent_span_id = context.getClientInfo().opentelemetry_parent_span_id;
                     span.operation_name = "query";
-                    span.start_time = elem.query_start_time;
-                    span.finish_time = elem.event_time;
+                    span.start_time_us = elem.query_start_time_microseconds;
+                    span.finish_time_us = time_in_microseconds(current_time);
                     span.duration_ns = elapsed_seconds * 1000000000;
 
                     // keep values synchonized to type enum in QueryLogElement::createBlock
@@ -751,7 +748,7 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
             if (query_for_logging.empty())
                 query_for_logging = prepareQueryForLogging(query, context);
 
-            onExceptionBeforeStart(query_for_logging, context, current_time, current_time_microseconds, ast);
+            onExceptionBeforeStart(query_for_logging, context, time_in_microseconds(current_time), ast);
         }
 
         throw;