Add log_queries_min_query_duration_ms

Only queries slower then the value of this setting will go to system.query_log,
i.e. something like slow_query_log in mysql.

v2: log_queries_min_time renamed to log_queries_min_query_duration_ms
v3: add current_database into system.query_thread_log
v4: rewrite test using current_database
v5: fix query_duration_ms in system.query_thread_log

docs/en/operations/settings/settings.md

@@ -680,6 +680,21 @@ Example:
 log_queries=1
 ```
 
+## log_queries_min_query_duration_ms {#settings-log-queries-min-query-duration-ms}
+
+Minimal time for the query to run to get to the following tables:
+
+- `system.query_log`
+- `system.query_thread_log`
+
+Only the queries with the following type will get to the log:
+
+- `QUERY_FINISH`
+- `EXCEPTION_WHILE_PROCESSING`
+
+-   Type: milliseconds
+-   Default value: 0 (any query)
+
 ## log_queries_min_type {#settings-log-queries-min-type}
 
 `query_log` minimal type to log.

src/Common/ThreadStatus.h

@@ -172,7 +172,7 @@ protected:
 
     void finalizeQueryProfiler();
 
-    void logToQueryThreadLog(QueryThreadLog & thread_log, const String & current_database);
+    void logToQueryThreadLog(QueryThreadLog & thread_log, const String & current_database, std::chrono::time_point<std::chrono::system_clock> now);
 
     void assertState(const std::initializer_list<int> & permitted_states, const char * description = nullptr) const;
 

src/Core/Settings.h

@@ -150,6 +150,7 @@ class IColumn;
     \
     M(Bool, log_queries, 1, "Log requests and write the log to the system table.", 0) \
     M(LogQueriesType, log_queries_min_type, QueryLogElementType::QUERY_START, "Minimal type in query_log to log, possible values (from low to high): QUERY_START, QUERY_FINISH, EXCEPTION_BEFORE_START, EXCEPTION_WHILE_PROCESSING.", 0) \
+    M(Milliseconds, log_queries_min_query_duration_ms, 0, "Minimal time for the query to run, to get to the query_log/query_thread_log.", 0) \
     M(UInt64, log_queries_cut_to_length, 100000, "If query length is greater than specified threshold (in bytes), then cut query when writing to query log. Also limit length of printed query in ordinary text log.", 0) \
     \
     M(DistributedProductMode, distributed_product_mode, DistributedProductMode::DENY, "How are distributed subqueries performed inside IN or JOIN sections?", IMPORTANT) \

src/Interpreters/ThreadStatusExt.cpp

@@ -242,8 +242,15 @@ void ThreadStatus::finalizePerformanceCounters()
         {
             const auto & settings = query_context->getSettingsRef();
             if (settings.log_queries && settings.log_query_threads)
-                if (auto thread_log = global_context->getQueryThreadLog())
-                    logToQueryThreadLog(*thread_log, query_context->getCurrentDatabase());
+            {
+                const auto now = std::chrono::system_clock::now();
+                Int64 query_duration_ms = (time_in_microseconds(now) - query_start_time_microseconds) / 1000;
+                if (query_duration_ms >= settings.log_queries_min_query_duration_ms.totalMilliseconds())
+                {
+                    if (auto thread_log = global_context->getQueryThreadLog())
+                        logToQueryThreadLog(*thread_log, query_context->getCurrentDatabase(), now);
+                }
+            }
         }
     }
     catch (...)
@@ -322,15 +329,14 @@ void ThreadStatus::detachQuery(bool exit_if_already_detached, bool thread_exits)
 #endif
 }
 
-void ThreadStatus::logToQueryThreadLog(QueryThreadLog & thread_log, const String & current_database)
+void ThreadStatus::logToQueryThreadLog(QueryThreadLog & thread_log, const String & current_database, std::chrono::time_point<std::chrono::system_clock> now)
 {
     QueryThreadLogElement elem;
 
     // 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);
+    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;

src/Interpreters/executeQuery.cpp

@@ -241,7 +241,7 @@ static void onExceptionBeforeStart(const String & query_for_logging, Context & c
     /// Update performance counters before logging to query_log
     CurrentThread::finalizePerformanceCounters();
 
-    if (settings.log_queries && elem.type >= settings.log_queries_min_type)
+    if (settings.log_queries && elem.type >= settings.log_queries_min_type && !settings.log_queries_min_query_duration_ms.totalMilliseconds())
         if (auto query_log = context.getQueryLog())
             query_log->add(elem);
 
@@ -552,7 +552,7 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
                 if (settings.log_query_settings)
                     elem.query_settings = std::make_shared<Settings>(context.getSettingsRef());
 
-                if (elem.type >= settings.log_queries_min_type)
+                if (elem.type >= settings.log_queries_min_type && !settings.log_queries_min_query_duration_ms.totalMilliseconds())
                 {
                     if (auto query_log = context.getQueryLog())
                         query_log->add(elem);
@@ -588,8 +588,12 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
             };
 
             /// Also make possible for caller to log successful query finish and exception during execution.
-            auto finish_callback = [elem, &context, ast, log_queries, log_queries_min_type = settings.log_queries_min_type,
-                status_info_to_query_log]
+            auto finish_callback = [elem, &context, ast,
+                 log_queries,
+                 log_queries_min_type = settings.log_queries_min_type,
+                 log_queries_min_query_duration_ms = settings.log_queries_min_query_duration_ms.totalMilliseconds(),
+                 status_info_to_query_log
+            ]
                 (IBlockInputStream * stream_in, IBlockOutputStream * stream_out, QueryPipeline * query_pipeline) mutable
             {
                 QueryStatus * process_list_elem = context.getProcessListElement();
@@ -655,7 +659,7 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
                 elem.thread_ids = std::move(info.thread_ids);
                 elem.profile_counters = std::move(info.profile_counters);
 
-                if (log_queries && elem.type >= log_queries_min_type)
+                if (log_queries && elem.type >= log_queries_min_type && Int64(elem.query_duration_ms) >= log_queries_min_query_duration_ms)
                 {
                     if (auto query_log = context.getQueryLog())
                         query_log->add(elem);
@@ -694,8 +698,11 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
                 }
             };
 
-            auto exception_callback = [elem, &context, ast, log_queries, log_queries_min_type = settings.log_queries_min_type, quota(quota),
-                    status_info_to_query_log] () mutable
+            auto exception_callback = [elem, &context, ast,
+                 log_queries,
+                 log_queries_min_type = settings.log_queries_min_type,
+                 log_queries_min_query_duration_ms = settings.log_queries_min_query_duration_ms.totalMilliseconds(),
+                 quota(quota), status_info_to_query_log] () mutable
             {
                 if (quota)
                     quota->used(Quota::ERRORS, 1, /* check_exceeded = */ false);
@@ -729,7 +736,7 @@ static std::tuple<ASTPtr, BlockIO> executeQueryImpl(
                 logException(context, elem);
 
                 /// In case of exception we log internal queries also
-                if (log_queries && elem.type >= log_queries_min_type)
+                if (log_queries && elem.type >= log_queries_min_type && Int64(elem.query_duration_ms) >= log_queries_min_query_duration_ms)
                 {
                     if (auto query_log = context.getQueryLog())
                         query_log->add(elem);

tests/queries/0_stateless/01546_log_queries_min_query_duration_ms.reference

@@ -0,0 +1,4 @@
+0
+0
+1
+1

tests/queries/0_stateless/01546_log_queries_min_query_duration_ms.sql

@@ -0,0 +1,54 @@
+set log_queries_min_query_duration_ms=300000;
+set log_query_threads=1;
+set log_queries=1;
+
+--
+-- fast -- no logging
+--
+select '01546_log_queries_min_query_duration_ms-fast' format Null;
+system flush logs;
+
+-- No logging, since the query is fast enough.
+select count()
+from system.query_log
+where
+    query like '%01546_log_queries_min_query_duration_ms-fast%'
+    and query not like '%system.query_log%'
+    and current_database = currentDatabase()
+    and event_date = today()
+    and event_time >= now() - interval 1 minute;
+select count()
+from system.query_thread_log
+where
+    query like '%01546_log_queries_min_query_duration_ms-fast%'
+    and query not like '%system.query_thread_log%'
+    and current_database = currentDatabase()
+    and event_date = today()
+    and event_time >= now() - interval 1 minute;
+
+--
+-- slow -- query logged
+--
+set log_queries_min_query_duration_ms=300;
+select '01546_log_queries_min_query_duration_ms-slow', sleep(0.4) format Null;
+system flush logs;
+
+-- With the limit on minimum execution time, "query start" and "exception before start" events are not logged, only query finish.
+select count()
+from system.query_log
+where
+    query like '%01546_log_queries_min_query_duration_ms-slow%'
+    and query not like '%system.query_log%'
+    and current_database = currentDatabase()
+    and event_date = today()
+    and event_time >= now() - interval 1 minute;
+-- There at least two threads involved in a simple query
+-- (one thread just waits another, sigh)
+select count() == 2
+from system.query_thread_log
+where
+    query like '%01546_log_queries_min_query_duration_ms-slow%'
+    and query not like '%system.query_thread_log%'
+    and current_database = currentDatabase()
+    and event_date = today()
+    and event_time >= now() - interval 1 minute;