Merge pull request #12452 from ClickHouse/system-log-dont-log-under-mutex

nikitamikhaylov · web-flow · commit 1bef33f04f5a · 2020-07-16T14:44:28.000+04:00
SystemLog: do not log under mutex
diff --git a/src/Interpreters/SystemLog.h b/src/Interpreters/SystemLog.h
@@ -233,46 +233,56 @@ void SystemLog<LogElement>::add(const LogElement & element)
     /// Otherwise the tests like 01017_uniqCombined_memory_usage.sql will be flacky.
     auto temporarily_disable_memory_tracker = getCurrentMemoryTrackerActionLock();
 
-    std::lock_guard lock(mutex);
+    /// Should not log messages under mutex.
+    bool queue_is_half_full = false;
 
-    if (is_shutdown)
-        return;
-
-    if (queue.size() == DBMS_SYSTEM_LOG_QUEUE_SIZE / 2)
     {
-        // The queue more than half full, time to flush.
-        // We only check for strict equality, because messages are added one
-        // by one, under exclusive lock, so we will see each message count.
-        // It is enough to only wake the flushing thread once, after the message
-        // count increases past half available size.
-        const uint64_t queue_end = queue_front_index + queue.size();
-        if (requested_flush_before < queue_end)
-            requested_flush_before = queue_end;
+        std::unique_lock lock(mutex);
 
-        flush_event.notify_all();
-        LOG_INFO(log, "Queue is half full for system log '{}'.", demangle(typeid(*this).name()));
-    }
+        if (is_shutdown)
+            return;
 
-    if (queue.size() >= DBMS_SYSTEM_LOG_QUEUE_SIZE)
-    {
-        // Ignore all further entries until the queue is flushed.
-        // Log a message about that. Don't spam it -- this might be especially
-        // problematic in case of trace log. Remember what the front index of the
-        // queue was when we last logged the message. If it changed, it means the
-        // queue was flushed, and we can log again.
-        if (queue_front_index != logged_queue_full_at_index)
+        if (queue.size() == DBMS_SYSTEM_LOG_QUEUE_SIZE / 2)
         {
-            logged_queue_full_at_index = queue_front_index;
+            queue_is_half_full = true;
+
+            // The queue more than half full, time to flush.
+            // We only check for strict equality, because messages are added one
+            // by one, under exclusive lock, so we will see each message count.
+            // It is enough to only wake the flushing thread once, after the message
+            // count increases past half available size.
+            const uint64_t queue_end = queue_front_index + queue.size();
+            if (requested_flush_before < queue_end)
+                requested_flush_before = queue_end;
+
+            flush_event.notify_all();
+        }
 
-            // TextLog sets its logger level to 0, so this log is a noop and
-            // there is no recursive logging.
-            LOG_ERROR(log, "Queue is full for system log '{}' at {}", demangle(typeid(*this).name()), queue_front_index);
+        if (queue.size() >= DBMS_SYSTEM_LOG_QUEUE_SIZE)
+        {
+            // Ignore all further entries until the queue is flushed.
+            // Log a message about that. Don't spam it -- this might be especially
+            // problematic in case of trace log. Remember what the front index of the
+            // queue was when we last logged the message. If it changed, it means the
+            // queue was flushed, and we can log again.
+            if (queue_front_index != logged_queue_full_at_index)
+            {
+                logged_queue_full_at_index = queue_front_index;
+
+                // TextLog sets its logger level to 0, so this log is a noop and
+                // there is no recursive logging.
+                lock.unlock();
+                LOG_ERROR(log, "Queue is full for system log '{}' at {}", demangle(typeid(*this).name()), queue_front_index);
+            }
+
+            return;
         }
 
-        return;
+        queue.push_back(element);
     }
 
-    queue.push_back(element);
+    if (queue_is_half_full)
+        LOG_INFO(log, "Queue is half full for system log '{}'.", demangle(typeid(*this).name()));
 }
 
 
