Merge pull request #14760 from bharatnc/ncb/event_time_microsec_p2

add event_time_microseconds field for system.{trace,text,query,query_thread}_log tables
2024-11-24 08:32:02 +00:00 · 2020-09-28 18:34:21 +03:00 · 2020-09-28 18:34:21 +03:00 · 421d3b0b86
commit 421d3b0b86
parent 071ff6c9af 7486539862
22 changed files with 232 additions and 109 deletions
--- a/base/loggers/ExtendedLogChannel.cpp
+++ b/base/loggers/ExtendedLogChannel.cpp
@ -23,6 +23,7 @@ ExtendedLogMessage ExtendedLogMessage::getFrom(const Poco::Message & base)

    msg_ext.time_seconds = static_cast<UInt32>(tv.tv_sec);
    msg_ext.time_microseconds = static_cast<UInt32>(tv.tv_usec);
+    msg_ext.time_in_microseconds = static_cast<UInt64>((tv.tv_sec) * 1000000U + (tv.tv_usec));

    if (current_thread)
    {
--- a/base/loggers/ExtendedLogChannel.h
+++ b/base/loggers/ExtendedLogChannel.h
@ -23,6 +23,7 @@ public:

    uint32_t time_seconds = 0;
    uint32_t time_microseconds = 0;
+    uint64_t time_in_microseconds = 0;

    uint64_t thread_id = 0;
    std::string query_id;
--- a/base/loggers/OwnSplitChannel.cpp
+++ b/base/loggers/OwnSplitChannel.cpp
@ -76,6 +76,7 @@ void OwnSplitChannel::logSplit(const Poco::Message & msg)
        TextLogElement elem;

        elem.event_time = msg_ext.time_seconds;
+        elem.event_time_microseconds = msg_ext.time_in_microseconds;
        elem.microseconds = msg_ext.time_microseconds;

        elem.thread_name = getThreadName();
--- a/docs/en/operations/system-tables/query_log.md
+++ b/docs/en/operations/system-tables/query_log.md
@ -33,6 +33,7 @@ Columns:
    -   `'ExceptionWhileProcessing' = 4` — Exception during the query execution.
 -   `event_date` ([Date](../../sql-reference/data-types/date.md)) — Query starting date.
 -   `event_time` ([DateTime](../../sql-reference/data-types/datetime.md)) — Query starting time.
+-   `event_time_microseconds` ([DateTime](../../sql-reference/data-types/datetime.md)) — Query starting time with microseconds precision.
 -   `query_start_time` ([DateTime](../../sql-reference/data-types/datetime.md)) — Start time of query execution.
 -   `query_start_time_microseconds` ([DateTime64](../../sql-reference/data-types/datetime64.md)) — Start time of query execution with microsecond precision.
 -   `query_duration_ms` ([UInt64](../../sql-reference/data-types/int-uint.md#uint-ranges)) — Duration of query execution in milliseconds.
@ -84,54 +85,57 @@ Columns:
 **Example**

 ``` sql
-SELECT * FROM system.query_log LIMIT 1 FORMAT Vertical;
+SELECT * FROM system.query_log LIMIT 1 \G
 ```

 ``` text
 Row 1:
 ──────
-type:                 QueryStart
-event_date:           2020-05-13
-event_time:           2020-05-13 14:02:28
-query_start_time:     2020-05-13 14:02:28
-query_duration_ms:    0
-read_rows:            0
-read_bytes:           0
-written_rows:         0
-written_bytes:        0
-result_rows:          0
-result_bytes:         0
-memory_usage:         0
-query:                SELECT 1
-exception_code:       0
-exception:
-stack_trace:
-is_initial_query:     1
-user:                 default
-query_id:             5e834082-6f6d-4e34-b47b-cd1934f4002a
-address:              ::ffff:127.0.0.1
-port:                 57720
-initial_user:         default
-initial_query_id:     5e834082-6f6d-4e34-b47b-cd1934f4002a
-initial_address:      ::ffff:127.0.0.1
-initial_port:         57720
-interface:            1
-os_user:              bayonet
-client_hostname:      clickhouse.ru-central1.internal
-client_name:          ClickHouse client
-client_revision:      54434
-client_version_major: 20
-client_version_minor: 4
-client_version_patch: 1
-http_method:          0
-http_user_agent:
-quota_key:
-revision:             54434
-thread_ids:           []
-ProfileEvents.Names:  []
-ProfileEvents.Values: []
-Settings.Names:       ['use_uncompressed_cache','load_balancing','log_queries','max_memory_usage']
-Settings.Values:      ['0','random','1','10000000000']
+type:                          QueryStart
+event_date:                    2020-09-11
+event_time:                    2020-09-11 10:08:17
+event_time_microseconds:       2020-09-11 10:08:17.063321
+query_start_time:              2020-09-11 10:08:17
+query_start_time_microseconds: 2020-09-11 10:08:17.063321
+query_duration_ms:             0
+read_rows:                     0
+read_bytes:                    0
+written_rows:                  0
+written_bytes:                 0
+result_rows:                   0
+result_bytes:                  0
+memory_usage:                  0
+current_database:              default
+query:                         INSERT INTO test1 VALUES
+exception_code:                0
+exception:                     
+stack_trace:                   
+is_initial_query:              1
+user:                          default
+query_id:                      50a320fd-85a8-49b8-8761-98a86bcbacef
+address:                       ::ffff:127.0.0.1
+port:                          33452
+initial_user:                  default
+initial_query_id:              50a320fd-85a8-49b8-8761-98a86bcbacef
+initial_address:               ::ffff:127.0.0.1
+initial_port:                  33452
+interface:                     1
+os_user:                       bharatnc
+client_hostname:               tower
+client_name:                   ClickHouse 
+client_revision:               54437
+client_version_major:          20
+client_version_minor:          7
+client_version_patch:          2
+http_method:                   0
+http_user_agent:               
+quota_key:                     
+revision:                      54440
+thread_ids:                    []
+ProfileEvents.Names:           []
+ProfileEvents.Values:          []
+Settings.Names:                ['use_uncompressed_cache','load_balancing','log_queries','max_memory_usage','allow_introspection_functions']
+Settings.Values:               ['0','random','1','10000000000','1']
 ```

 **See Also**
--- a/docs/en/operations/system-tables/query_thread_log.md
+++ b/docs/en/operations/system-tables/query_thread_log.md
@ -15,6 +15,7 @@ Columns:

 -   `event_date` ([Date](../../sql-reference/data-types/date.md)) — The date when the thread has finished execution of the query.
 -   `event_time` ([DateTime](../../sql-reference/data-types/datetime.md)) — The date and time when the thread has finished execution of the query.
+-   `event_time_microsecinds` ([DateTime](../../sql-reference/data-types/datetime.md)) — The date and time when the thread has finished execution of the query with microseconds precision.
 -   `query_start_time` ([DateTime](../../sql-reference/data-types/datetime.md)) — Start time of query execution.
 -   `query_start_time_microseconds` ([DateTime64](../../sql-reference/data-types/datetime64.md)) — Start time of query execution with microsecond precision.
 -   `query_duration_ms` ([UInt64](../../sql-reference/data-types/int-uint.md#uint-ranges)) — Duration of query execution.
@ -63,50 +64,51 @@ Columns:
 **Example**

 ``` sql
- SELECT * FROM system.query_thread_log LIMIT 1 FORMAT Vertical
+ SELECT * FROM system.query_thread_log LIMIT 1 \G
 ```

 ``` text
 Row 1:
 ──────
-event_date:           2020-05-13
-event_time:           2020-05-13 14:02:28
-query_start_time:     2020-05-13 14:02:28
-query_duration_ms:    0
-read_rows:            1
-read_bytes:           1
-written_rows:         0
-written_bytes:        0
-memory_usage:         0
-peak_memory_usage:    0
-thread_name:          QueryPipelineEx
-thread_id:            28952
-master_thread_id:     28924
-query:                SELECT 1
-is_initial_query:     1
-user:                 default
-query_id:             5e834082-6f6d-4e34-b47b-cd1934f4002a
-address:              ::ffff:127.0.0.1
-port:                 57720
-initial_user:         default
-initial_query_id:     5e834082-6f6d-4e34-b47b-cd1934f4002a
-initial_address:      ::ffff:127.0.0.1
-initial_port:         57720
-interface:            1
-os_user:              bayonet
-client_hostname:      clickhouse.ru-central1.internal
-client_name:          ClickHouse client
-client_revision:      54434
-client_version_major: 20
-client_version_minor: 4
-client_version_patch: 1
-http_method:          0
-http_user_agent:
-quota_key:
-revision:             54434
-ProfileEvents.Names:  ['ContextLock','RealTimeMicroseconds','UserTimeMicroseconds','OSCPUWaitMicroseconds','OSCPUVirtualTimeMicroseconds']
-ProfileEvents.Values: [1,97,81,5,81]
-...
+event_date:                    2020-09-11
+event_time:                    2020-09-11 10:08:17
+event_time_microseconds:       2020-09-11 10:08:17.134042
+query_start_time:              2020-09-11 10:08:17
+query_start_time_microseconds: 2020-09-11 10:08:17.063150
+query_duration_ms:             70
+read_rows:                     0
+read_bytes:                    0
+written_rows:                  1
+written_bytes:                 12
+memory_usage:                  4300844
+peak_memory_usage:             4300844
+thread_name:                   TCPHandler
+thread_id:                     638133
+master_thread_id:              638133
+query:                         INSERT INTO test1 VALUES
+is_initial_query:              1
+user:                          default
+query_id:                      50a320fd-85a8-49b8-8761-98a86bcbacef
+address:                       ::ffff:127.0.0.1
+port:                          33452
+initial_user:                  default
+initial_query_id:              50a320fd-85a8-49b8-8761-98a86bcbacef
+initial_address:               ::ffff:127.0.0.1
+initial_port:                  33452
+interface:                     1
+os_user:                       bharatnc
+client_hostname:               tower
+client_name:                   ClickHouse 
+client_revision:               54437
+client_version_major:          20
+client_version_minor:          7
+client_version_patch:          2
+http_method:                   0
+http_user_agent:               
+quota_key:                     
+revision:                      54440
+ProfileEvents.Names:           ['Query','InsertQuery','FileOpen','WriteBufferFromFileDescriptorWrite','WriteBufferFromFileDescriptorWriteBytes','ReadCompressedBytes','CompressedReadBufferBlocks','CompressedReadBufferBytes','IOBufferAllocs','IOBufferAllocBytes','FunctionExecute','CreatedWriteBufferOrdinary','DiskWriteElapsedMicroseconds','NetworkReceiveElapsedMicroseconds','NetworkSendElapsedMicroseconds','InsertedRows','InsertedBytes','SelectedRows','SelectedBytes','MergeTreeDataWriterRows','MergeTreeDataWriterUncompressedBytes','MergeTreeDataWriterCompressedBytes','MergeTreeDataWriterBlocks','MergeTreeDataWriterBlocksAlreadySorted','ContextLock','RWLockAcquiredReadLocks','RealTimeMicroseconds','UserTimeMicroseconds','SoftPageFaults','OSCPUVirtualTimeMicroseconds','OSWriteBytes','OSReadChars','OSWriteChars']
+ProfileEvents.Values:          [1,1,11,11,591,148,3,71,29,6533808,1,11,72,18,47,1,12,1,12,1,12,189,1,1,10,2,70853,2748,49,2747,45056,422,1520]
 ```

 **See Also**
--- a/docs/en/operations/system-tables/text_log.md
+++ b/docs/en/operations/system-tables/text_log.md
@ -6,6 +6,7 @@ Columns:

 -   `event_date` (Date) — Date of the entry.
 -   `event_time` (DateTime) — Time of the entry.
+-   `event_time_microseconds` (DateTime) — Time of the entry with microseconds precision.
 -   `microseconds` (UInt32) — Microseconds of the entry.
 -   `thread_name` (String) — Name of the thread from which the logging was done.
 -   `thread_id` (UInt64) — OS thread ID.
@ -25,4 +26,28 @@ Columns:
 -   `source_file` (LowCardinality(String)) — Source file from which the logging was done.
 -   `source_line` (UInt64) — Source line from which the logging was done.

+**Example**
+
+``` sql
+SELECT * FROM system.text_log LIMIT 1 \G
+```
+
+``` text
+Row 1:
+──────
+event_date:              2020-09-10
+event_time:              2020-09-10 11:23:07
+event_time_microseconds: 2020-09-10 11:23:07.871397
+microseconds:            871397
+thread_name:             clickhouse-serv
+thread_id:               564917
+level:                   Information
+query_id:                
+logger_name:             DNSCacheUpdater
+message:                 Update period 15 seconds
+revision:                54440
+source_file:             /ClickHouse/src/Interpreters/DNSCacheUpdater.cpp; void DB::DNSCacheUpdater::start()
+source_line:             45
+```
+ 
 [Original article](https://clickhouse.tech/docs/en/operations/system_tables/text_log) <!--hide-->
--- a/docs/en/operations/system-tables/trace_log.md
+++ b/docs/en/operations/system-tables/trace_log.md
@ -12,6 +12,8 @@ Columns:

 -   `event_time` ([DateTime](../../sql-reference/data-types/datetime.md)) — Timestamp of the sampling moment.

+-   `event_time_microseconds` ([DateTime](../../sql-reference/data-types/datetime.md)) — Timestamp of the sampling moment with microseconds precision.
+
 -   `timestamp_ns` ([UInt64](../../sql-reference/data-types/int-uint.md)) — Timestamp of the sampling moment in nanoseconds.

 -   `revision` ([UInt32](../../sql-reference/data-types/int-uint.md)) — ClickHouse server build revision.
@ -38,13 +40,16 @@ SELECT * FROM system.trace_log LIMIT 1 \G
 ``` text
 Row 1:
 ──────
-event_date:    2019-11-15
-event_time:    2019-11-15 15:09:38
-revision:      54428
-timer_type:    Real
-thread_number: 48
-query_id:      acc4d61f-5bd1-4a3e-bc91-2180be37c915
-trace:         [94222141367858,94222152240175,94222152325351,94222152329944,94222152330796,94222151449980,94222144088167,94222151682763,94222144088167,94222151682763,94222144088167,94222144058283,94222144059248,94222091840750,94222091842302,94222091831228,94222189631488,140509950166747,140509942945935]
+event_date:              2020-09-10
+event_time:              2020-09-10 11:23:09
+event_time_microseconds: 2020-09-10 11:23:09.872924
+timestamp_ns:            1599762189872924510
+revision:                54440
+trace_type:              Memory
+thread_id:               564963
+query_id:                
+trace:                   [371912858,371912789,371798468,371799717,371801313,371790250,624462773,566365041,566440261,566445834,566460071,566459914,566459842,566459580,566459469,566459389,566459341,566455774,371993941,371988245,372158848,372187428,372187309,372187093,372185478,140222123165193,140222122205443]
+size:                    5244400
 ```

 [Original article](https://clickhouse.tech/docs/en/operations/system_tables/trace_log) <!--hide-->
--- a/src/Common/Stopwatch.h
+++ b/src/Common/Stopwatch.h
@ -13,7 +13,6 @@ inline UInt64 clock_gettime_ns(clockid_t clock_type = CLOCK_MONOTONIC)
    return UInt64(ts.tv_sec * 1000000000LL + ts.tv_nsec);
 }

-
 /** Differs from Poco::Stopwatch only by using 'clock_gettime' instead of 'gettimeofday',
  *  returns nanoseconds instead of microseconds, and also by other minor differencies.
  */
--- a/src/Common/TraceCollector.cpp
+++ b/src/Common/TraceCollector.cpp
@ -141,8 +141,14 @@ void TraceCollector::run()

        if (trace_log)
        {
-            UInt64 time = clock_gettime_ns(CLOCK_REALTIME);
-            TraceLogElement element{time_t(time / 1000000000), time, trace_type, thread_id, query_id, trace, size};
+            // time and time_in_microseconds are both being constructed from the same timespec so that the
+            // times will be equal upto the precision of a second.
+            struct timespec ts;
+            clock_gettime(CLOCK_REALTIME, &ts);
+
+            UInt64 time = UInt64(ts.tv_sec * 1000000000LL + ts.tv_nsec);
+            UInt64 time_in_microseconds = UInt64((ts.tv_sec * 1000000LL) + (ts.tv_nsec / 1000));
+            TraceLogElement element{time_t(time / 1000000000), time_in_microseconds, time, trace_type, thread_id, query_id, trace, size};
            trace_log->add(element);
        }
    }
--- a/src/Interpreters/QueryLog.cpp
+++ b/src/Interpreters/QueryLog.cpp
@ -39,6 +39,7 @@ Block QueryLogElement::createBlock()
        {std::move(query_status_datatype),                                    "type"},
        {std::make_shared<DataTypeDate>(),                                    "event_date"},
        {std::make_shared<DataTypeDateTime>(),                                "event_time"},
+        {std::make_shared<DataTypeDateTime64>(6),                             "event_time_microseconds"},
        {std::make_shared<DataTypeDateTime>(),                                "query_start_time"},
        {std::make_shared<DataTypeDateTime64>(6),                             "query_start_time_microseconds"},
        {std::make_shared<DataTypeUInt64>(),                                  "query_duration_ms"},
@ -97,6 +98,7 @@ void QueryLogElement::appendToBlock(MutableColumns & columns) const
    columns[i++]->insert(type);
    columns[i++]->insert(DateLUT::instance().toDayNum(event_time));
    columns[i++]->insert(event_time);
+    columns[i++]->insert(event_time_microseconds);
    columns[i++]->insert(query_start_time);
    columns[i++]->insert(query_start_time_microseconds);
    columns[i++]->insert(query_duration_ms);
--- a/src/Interpreters/QueryLog.h
+++ b/src/Interpreters/QueryLog.h
@ -30,6 +30,7 @@ struct QueryLogElement
    /// Depending on the type of query and type of stage, not all the fields may be filled.

    time_t event_time{};
+    UInt64 event_time_microseconds{};
    time_t query_start_time{};
    UInt64 query_start_time_microseconds{};
    UInt64 query_duration_ms{};
--- a/src/Interpreters/QueryThreadLog.cpp
+++ b/src/Interpreters/QueryThreadLog.cpp
@ -23,6 +23,7 @@ Block QueryThreadLogElement::createBlock()
    return {
        {std::make_shared<DataTypeDate>(),          "event_date"},
        {std::make_shared<DataTypeDateTime>(),      "event_time"},
+        {std::make_shared<DataTypeDateTime64>(6),   "event_time_microseconds"},
        {std::make_shared<DataTypeDateTime>(),      "query_start_time"},
        {std::make_shared<DataTypeDateTime64>(6),   "query_start_time_microseconds"},
        {std::make_shared<DataTypeUInt64>(),        "query_duration_ms"},
@ -73,6 +74,7 @@ void QueryThreadLogElement::appendToBlock(MutableColumns & columns) const

    columns[i++]->insert(DateLUT::instance().toDayNum(event_time));
    columns[i++]->insert(event_time);
+    columns[i++]->insert(event_time_microseconds);
    columns[i++]->insert(query_start_time);
    columns[i++]->insert(query_start_time_microseconds);
    columns[i++]->insert(query_duration_ms);
--- a/src/Interpreters/QueryThreadLog.h
+++ b/src/Interpreters/QueryThreadLog.h
@ -16,6 +16,7 @@ namespace DB
 struct QueryThreadLogElement
 {
    time_t event_time{};
+    UInt64 event_time_microseconds{};
    /// When query was attached to current thread
    time_t query_start_time{};
    /// same as above but adds microsecond precision
--- a/src/Interpreters/TextLog.cpp
+++ b/src/Interpreters/TextLog.cpp
@ -2,6 +2,7 @@
 #include <DataTypes/DataTypeEnum.h>
 #include <DataTypes/DataTypesNumber.h>
 #include <DataTypes/DataTypeDateTime.h>
+#include <DataTypes/DataTypeDateTime64.h>
 #include <DataTypes/DataTypeDate.h>
 #include <DataTypes/DataTypeString.h>
 #include <Common/ClickHouseRevision.h>
@ -29,6 +30,7 @@ Block TextLogElement::createBlock()
    {
        {std::make_shared<DataTypeDate>(),                                                    "event_date"},
        {std::make_shared<DataTypeDateTime>(),                                                "event_time"},
+        {std::make_shared<DataTypeDateTime64>(6),                                             "event_time_microseconds"},
        {std::make_shared<DataTypeUInt32>(),                                                  "microseconds"},

        {std::make_shared<DataTypeLowCardinality>(std::make_shared<DataTypeString>()),        "thread_name"},
@ -52,6 +54,7 @@ void TextLogElement::appendToBlock(MutableColumns & columns) const

    columns[i++]->insert(DateLUT::instance().toDayNum(event_time));
    columns[i++]->insert(event_time);
+    columns[i++]->insert(event_time_microseconds);
    columns[i++]->insert(microseconds);

    columns[i++]->insertData(thread_name.data(), thread_name.size());
--- a/src/Interpreters/TextLog.h
+++ b/src/Interpreters/TextLog.h
@ -9,6 +9,7 @@ using Poco::Message;
 struct TextLogElement
 {
    time_t event_time{};
+    UInt64 event_time_microseconds{};
    UInt32 microseconds;

    String thread_name;
--- a/src/Interpreters/ThreadStatusExt.cpp
+++ b/src/Interpreters/ThreadStatusExt.cpp
@ -322,7 +322,14 @@ void ThreadStatus::logToQueryThreadLog(QueryThreadLog & thread_log)
 {
    QueryThreadLogElement elem;

-    elem.event_time = time(nullptr);
+    // construct current_time and current_time_microseconds using the same time point
+    // so that the two times will always be equal up to a 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);
+
+    elem.event_time = current_time;
+    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;
--- a/src/Interpreters/TraceLog.cpp
+++ b/src/Interpreters/TraceLog.cpp
@ -4,6 +4,7 @@
 #include <DataTypes/DataTypesNumber.h>
 #include <DataTypes/DataTypeDate.h>
 #include <DataTypes/DataTypeDateTime.h>
+#include <DataTypes/DataTypeDateTime64.h>
 #include <Common/ClickHouseRevision.h>


@ -26,6 +27,7 @@ Block TraceLogElement::createBlock()
    {
        {std::make_shared<DataTypeDate>(),                                    "event_date"},
        {std::make_shared<DataTypeDateTime>(),                                "event_time"},
+        {std::make_shared<DataTypeDateTime64>(6),                             "event_time_microseconds"},
        {std::make_shared<DataTypeUInt64>(),                                  "timestamp_ns"},
        {std::make_shared<DataTypeUInt32>(),                                  "revision"},
        {std::make_shared<TraceDataType>(trace_values),                       "trace_type"},
@ -42,6 +44,7 @@ void TraceLogElement::appendToBlock(MutableColumns & columns) const

    columns[i++]->insert(DateLUT::instance().toDayNum(event_time));
    columns[i++]->insert(event_time);
+    columns[i++]->insert(event_time_microseconds);
    columns[i++]->insert(timestamp_ns);
    columns[i++]->insert(ClickHouseRevision::getVersionRevision());
    columns[i++]->insert(static_cast<UInt8>(trace_type));
--- a/src/Interpreters/TraceLog.h
+++ b/src/Interpreters/TraceLog.h
@ -18,6 +18,7 @@ struct TraceLogElement
    static const TraceDataType::Values trace_values;

    time_t event_time{};
+    UInt64 event_time_microseconds{};
    UInt64 timestamp_ns{};
    TraceType trace_type{};
    UInt64 thread_id{};
--- a/src/Interpreters/executeQuery.cpp
+++ b/src/Interpreters/executeQuery.cpp
@ -206,10 +206,11 @@ static void onExceptionBeforeStart(const String & query_for_logging, Context & c

    elem.type = QueryLogElementType::EXCEPTION_BEFORE_START;

-    // 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
+    // all callers to onExceptionBeforeStart method construct the timespec for event_time and
+    // event_time_microseconds from the same time point. So, it can be assumed that both of these
    // times are equal upto the precision of a second.
    elem.event_time = current_time;
+    elem.event_time_microseconds = current_time_microseconds;
    elem.query_start_time = current_time;
    elem.query_start_time_microseconds = current_time_microseconds;

@ -319,7 +320,9 @@ 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);
+        }

        throw;
    }
@ -484,6 +487,7 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
            elem.type = QueryLogElementType::QUERY_START;

            elem.event_time = current_time;
+            elem.event_time_microseconds = current_time_microseconds;
            elem.query_start_time = current_time;
            elem.query_start_time_microseconds = current_time_microseconds;

@ -554,8 +558,11 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(

                elem.type = QueryLogElementType::QUERY_FINISH;

-                elem.event_time = time(nullptr);
-
+                // construct event_time and event_time_microseconds using the same time point
+                // so that the two times will always be equal up to a precision of a second.
+                const auto time_now = std::chrono::system_clock::now();
+                elem.event_time = time_in_seconds(time_now);
+                elem.event_time_microseconds = time_in_microseconds(time_now);
                status_info_to_query_log(elem, info, ast);

                auto progress_callback = context.getProgressCallback();
@ -615,7 +622,12 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(

                elem.type = QueryLogElementType::EXCEPTION_WHILE_PROCESSING;

-                elem.event_time = time(nullptr);
+                // event_time and event_time_microseconds are being constructed from the same time point
+                // to ensure that both the times will be equal upto the precision of a second.
+                const auto time_now = std::chrono::system_clock::now();
+
+                elem.event_time = time_in_seconds(time_now);
+                elem.event_time_microseconds = time_in_microseconds(time_now);
                elem.query_duration_ms = 1000 * (elem.event_time - elem.query_start_time);
                elem.exception_code = getCurrentExceptionCode();
                elem.exception = getCurrentExceptionMessage(false);
--- a/tests/queries/0_stateless/01473_event_time_microseconds.reference
+++ b/tests/queries/0_stateless/01473_event_time_microseconds.reference
@ -1,2 +1,10 @@
 01473_metric_log_table_event_start_time_microseconds_test
 ok
+01473_trace_log_table_event_start_time_microseconds_test
+ok
+01473_query_log_table_event_start_time_microseconds_test
+ok
+01473_query_thread_log_table_event_start_time_microseconds_test
+ok
+01473_text_log_table_event_start_time_microseconds_test
+ok
--- a/tests/queries/0_stateless/01473_event_time_microseconds.sql
+++ b/tests/queries/0_stateless/01473_event_time_microseconds.sql
@ -3,22 +3,55 @@
 -- an integration test as those metrics take 60s by default to be updated.
 -- Refer: tests/integration/test_asynchronous_metric_log_table.

-set log_queries = 1;
+SET log_queries = 1;
+SET query_profiler_real_time_period_ns = 100000000;
+-- a long enough query to trigger the query profiler and to record trace log
+SELECT sleep(2) FORMAT Null;
+SET query_profiler_real_time_period_ns = 1000000000;
+SYSTEM FLUSH LOGS;

-select '01473_metric_log_table_event_start_time_microseconds_test';
-system flush logs;
+SELECT '01473_metric_log_table_event_start_time_microseconds_test';
 -- query assumes that the event_time field is accurate.
 WITH (
-    (
-        SELECT event_time_microseconds
+        SELECT event_time_microseconds, event_time
        FROM system.metric_log
        ORDER BY event_time DESC
        LIMIT 1
-    ) AS time_with_microseconds,
-    (
-        SELECT event_time
-        FROM system.metric_log
+    ) AS time
+SELECT if(dateDiff('second', toDateTime(time.1), toDateTime(time.2)) = 0, 'ok', toString(time));
+
+SELECT '01473_trace_log_table_event_start_time_microseconds_test';
+WITH (
+          SELECT event_time_microseconds, event_time
+          FROM system.trace_log
+          ORDER BY event_time DESC
+          LIMIT 1
+      ) AS time
+SELECT if(dateDiff('second', toDateTime(time.1), toDateTime(time.2)) = 0, 'ok', toString(time));
+
+SELECT '01473_query_log_table_event_start_time_microseconds_test';
+WITH (
+        SELECT event_time_microseconds, event_time
+        FROM system.query_log
        ORDER BY event_time DESC
        LIMIT 1
-    ) AS time)
-SELECT if(dateDiff('second', toDateTime(time_with_microseconds), toDateTime(time)) = 0, 'ok', 'fail')
+    ) AS time
+SELECT if(dateDiff('second', toDateTime(time.1), toDateTime(time.2)) = 0, 'ok', toString(time));
+
+SELECT '01473_query_thread_log_table_event_start_time_microseconds_test';
+WITH (
+        SELECT event_time_microseconds, event_time
+        FROM system.query_thread_log
+        ORDER BY event_time DESC
+        LIMIT 1
+    ) AS time
+SELECT if(dateDiff('second', toDateTime(time.1), toDateTime(time.2)) = 0, 'ok', toString(time));
+
+SELECT '01473_text_log_table_event_start_time_microseconds_test';
+WITH (
+          SELECT event_time_microseconds, event_time
+          FROM system.query_thread_log
+          ORDER BY event_time DESC
+          LIMIT 1
+      ) AS time
+SELECT if(dateDiff('second', toDateTime(time.1), toDateTime(time.2)) = 0, 'ok', toString(time));
--- a/tests/queries/skip_list.json
+++ b/tests/queries/skip_list.json
@ -17,6 +17,7 @@
        "00151_replace_partition_with_different_granularity",
        "00157_cache_dictionary",
        "01193_metadata_loading",
+        "01473_event_time_microseconds",
        "01474_executable_dictionary" /// informational stderr from sanitizer at start
    ],
    "address-sanitizer": [
@ -25,6 +26,7 @@
        "memory_profiler",
        "odbc_roundtrip",
        "01103_check_cpu_instructions_at_startup",
+        "01473_event_time_microseconds",
        "01193_metadata_loading"
    ],
    "ub-sanitizer": [
@ -33,6 +35,7 @@
        "memory_profiler",
        "01103_check_cpu_instructions_at_startup",
        "00900_orc_load",
+        "01473_event_time_microseconds",
        "01193_metadata_loading"
    ],
    "memory-sanitizer": [
@ -43,6 +46,7 @@
        "01086_odbc_roundtrip", /// can't pass because odbc libraries are not instrumented
        "00877_memory_limit_for_new_delete", /// memory limits don't work correctly under msan because it replaces malloc/free
        "01114_mysql_database_engine_segfault", /// it fails in _nss_files_parse_servent while using NSS from GLibc to authenticate (need to get rid of it)
+        "01473_event_time_microseconds",
        "01193_metadata_loading"
    ],
    "debug-build": [
@ -57,6 +61,7 @@
        "01037_polygon_dicts_",
        "hyperscan",
        "01193_metadata_loading",
+        "01473_event_time_microseconds",
        "01396_inactive_replica_cleanup_nodes"
    ],
    "unbundled-build": [