Merge pull request #44045 from CurtizJ/fix-tracing-of-profile-events

Fix tracing of profile events

src/Common/ProfileEvents.cpp

@@ -531,6 +531,11 @@ void increment(Event event, Count amount)
     DB::CurrentThread::getProfileEvents().increment(event, amount);
 }
 
+void incrementNoTrace(Event event, Count amount)
+{
+    DB::CurrentThread::getProfileEvents().incrementNoTrace(event, amount);
+}
+
 void Counters::increment(Event event, Count amount)
 {
     Counters * current = this;
@@ -547,6 +552,16 @@ void Counters::increment(Event event, Count amount)
         DB::TraceSender::send(DB::TraceType::ProfileEvent, StackTrace(), {.event = event, .increment = amount});
 }
 
+void Counters::incrementNoTrace(Event event, Count amount)
+{
+    Counters * current = this;
+    do
+    {
+        current->counters[event].fetch_add(amount, std::memory_order_relaxed);
+        current = current->parent;
+    } while (current != nullptr);
+}
+
 CountersIncrement::CountersIncrement(Counters::Snapshot const & snapshot)
 {
     init();

src/Common/ProfileEvents.h

@@ -54,6 +54,7 @@ namespace ProfileEvents
         }
 
         void increment(Event event, Count amount = 1);
+        void incrementNoTrace(Event event, Count amount = 1);
 
         struct Snapshot
         {
@@ -105,6 +106,10 @@ namespace ProfileEvents
     /// Increment a counter for event. Thread-safe.
     void increment(Event event, Count amount = 1);
 
+    /// The same as above but ignores value of setting 'trace_profile_events'
+    /// and never sends profile event to trace log.
+    void incrementNoTrace(Event event, Count amount = 1);
+
     /// Get name of event by identifier. Returns statically allocated string.
     const char * getName(Event event);
 

src/Common/QueryProfiler.cpp

@@ -50,11 +50,11 @@ namespace
                 /// But pass with some frequency to avoid drop of all traces.
                 if (overrun_count > 0 && write_trace_iteration % (overrun_count + 1) == 0)
                 {
-                    ProfileEvents::increment(ProfileEvents::QueryProfilerSignalOverruns, overrun_count);
+                    ProfileEvents::incrementNoTrace(ProfileEvents::QueryProfilerSignalOverruns, overrun_count);
                 }
                 else
                 {
-                    ProfileEvents::increment(ProfileEvents::QueryProfilerSignalOverruns, std::max(0, overrun_count) + 1);
+                    ProfileEvents::incrementNoTrace(ProfileEvents::QueryProfilerSignalOverruns, std::max(0, overrun_count) + 1);
                     return;
                 }
             }
@@ -67,7 +67,7 @@ namespace
         const StackTrace stack_trace(signal_context);
 
         TraceSender::send(trace_type, stack_trace, {});
-        ProfileEvents::increment(ProfileEvents::QueryProfilerRuns);
+        ProfileEvents::incrementNoTrace(ProfileEvents::QueryProfilerRuns);
 
         errno = saved_errno;
     }

src/IO/WriteBufferFromFileDescriptorDiscardOnFailure.cpp

@@ -17,7 +17,10 @@ void WriteBufferFromFileDescriptorDiscardOnFailure::nextImpl()
 
         if ((-1 == res || 0 == res) && errno != EINTR)
         {
-            ProfileEvents::increment(ProfileEvents::CannotWriteToWriteBufferDiscard);
+            /// Never send this profile event to trace log because it may cause another
+            /// write into the same fd and likely will trigger the same error
+            /// and will lead to infinite recursion.
+            ProfileEvents::incrementNoTrace(ProfileEvents::CannotWriteToWriteBufferDiscard);
             break;  /// Discard
         }
 

tests/queries/0_stateless/02497_trace_events_stress_long.reference

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

tests/queries/0_stateless/02497_trace_events_stress_long.sh

@@ -0,0 +1,47 @@
+#!/usr/bin/env bash
+# Tags: long, no-parallel, no-tsan, no-asan, no-debug, no-s3-storage, no-fasttest, no-replicated-database
+
+set -e
+
+CURDIR=$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)
+# shellcheck source=../shell_config.sh
+. "$CURDIR"/../shell_config.sh
+
+function thread1()
+{
+    query_id="$RANDOM-$CLICKHOUSE_DATABASE"
+
+    while true; do
+        $CLICKHOUSE_CLIENT --query_id=$query_id --query "
+            SELECT count() FROM numbers_mt(100000) SETTINGS
+                trace_profile_events = 1,
+                query_profiler_real_time_period_ns = 10000000,
+                query_profiler_cpu_time_period_ns =  10000000,
+                memory_profiler_step = 1024,
+                memory_profiler_sample_probability = 0.9
+            "
+    done
+}
+
+function thread2()
+{
+    while true; do
+        $CLICKHOUSE_CLIENT -q "SYSTEM FLUSH LOGS"
+    done
+}
+
+export -f thread1
+export -f thread2
+
+TIMEOUT=10
+
+timeout $TIMEOUT bash -c thread1 >/dev/null &
+timeout $TIMEOUT bash -c thread1 >/dev/null &
+timeout $TIMEOUT bash -c thread1 >/dev/null &
+timeout $TIMEOUT bash -c thread1 >/dev/null &
+timeout $TIMEOUT bash -c thread2 >/dev/null &
+
+wait
+
+$CLICKHOUSE_CLIENT -q "KILL QUERY WHERE query_id = '$query_id' SYNC"
+$CLICKHOUSE_CLIENT -q "SELECT count() FROM system.processes WHERE query_id = '$query_id'"