From 2466749648176f074dd4337f3eb8d2c154c6f713 Mon Sep 17 00:00:00 2001 From: "A.J. Beamon" Date: Thu, 12 Mar 2020 11:17:49 -0700 Subject: [PATCH 1/5] Don't disallow allocation tracking when a trace event is open because we now have state trace events. Instead, only block allocation tracking while we are in the middle of allocation tracking already to prevent recursion. --- flow/Arena.cpp | 4 +++- flow/FastAlloc.cpp | 4 +++- flow/Trace.cpp | 7 +------ flow/Trace.h | 2 +- 4 files changed, 8 insertions(+), 9 deletions(-) diff --git a/flow/Arena.cpp b/flow/Arena.cpp index 7701c13e91..88837e102b 100644 --- a/flow/Arena.cpp +++ b/flow/Arena.cpp @@ -184,9 +184,11 @@ ArenaBlock* ArenaBlock::create(int dataSize, Reference& next) { b->bigSize = reqSize; b->bigUsed = sizeof(ArenaBlock); - if (FLOW_KNOBS && g_trace_depth == 0 && + if (FLOW_KNOBS && !g_tracing_allocation && nondeterministicRandom()->random01() < (reqSize / FLOW_KNOBS->HUGE_ARENA_LOGGING_BYTES)) { + g_tracing_allocation = true; hugeArenaSample(reqSize); + g_tracing_allocation = false; } g_hugeArenaMemory.fetch_add(reqSize); diff --git a/flow/FastAlloc.cpp b/flow/FastAlloc.cpp index ac5f4c79b1..8cac3948b4 100644 --- a/flow/FastAlloc.cpp +++ b/flow/FastAlloc.cpp @@ -445,8 +445,10 @@ void FastAllocator::getMagazine() { // FIXME: We should be able to allocate larger magazine sizes here if we // detect that the underlying system supports hugepages. Using hugepages // with smaller-than-2MiB magazine sizes strands memory. See issue #909. - if(FLOW_KNOBS && g_trace_depth == 0 && nondeterministicRandom()->random01() < (magazine_size * Size)/FLOW_KNOBS->FAST_ALLOC_LOGGING_BYTES) { + if(FLOW_KNOBS && !g_tracing_allocation && nondeterministicRandom()->random01() < (magazine_size * Size)/FLOW_KNOBS->FAST_ALLOC_LOGGING_BYTES) { + g_tracing_allocation = true; TraceEvent("GetMagazineSample").detail("Size", Size).backtrace(); + g_tracing_allocation = false; } block = (void **)::allocate(magazine_size * Size, false); #endif diff --git a/flow/Trace.cpp b/flow/Trace.cpp index 1b3f8199c0..9f6a77bc1f 100644 --- a/flow/Trace.cpp +++ b/flow/Trace.cpp @@ -43,7 +43,7 @@ #undef min #endif -thread_local int g_trace_depth = 0; +thread_local bool g_tracing_allocation = false; class DummyThreadPool : public IThreadPool, ReferenceCounted { public: @@ -698,14 +698,12 @@ TraceEvent& TraceEvent::operator=(TraceEvent &&ev) { } TraceEvent::TraceEvent( const char* type, UID id ) : id(id), type(type), severity(SevInfo), initialized(false), enabled(true), logged(false) { - g_trace_depth++; setMaxFieldLength(0); setMaxEventLength(0); } TraceEvent::TraceEvent( Severity severity, const char* type, UID id ) : id(id), type(type), severity(severity), initialized(false), logged(false), enabled(g_network == nullptr || FLOW_KNOBS->MIN_TRACE_SEVERITY <= severity) { - g_trace_depth++; setMaxFieldLength(0); setMaxEventLength(0); } @@ -715,7 +713,6 @@ TraceEvent::TraceEvent( TraceInterval& interval, UID id ) initialized(false), logged(false), enabled(g_network == nullptr || FLOW_KNOBS->MIN_TRACE_SEVERITY <= interval.severity) { - g_trace_depth++; setMaxFieldLength(0); setMaxEventLength(0); @@ -727,7 +724,6 @@ TraceEvent::TraceEvent( Severity severity, TraceInterval& interval, UID id ) initialized(false), logged(false), enabled(g_network == nullptr || FLOW_KNOBS->MIN_TRACE_SEVERITY <= severity) { - g_trace_depth++; setMaxFieldLength(0); setMaxEventLength(0); @@ -1014,7 +1010,6 @@ void TraceEvent::log() { TraceEvent(SevError, "TraceEventLoggingError").error(e,true); } delete tmpEventMetric; - g_trace_depth--; logged = true; } } diff --git a/flow/Trace.h b/flow/Trace.h index b0ab0a81aa..5d7bb242d1 100644 --- a/flow/Trace.h +++ b/flow/Trace.h @@ -43,7 +43,7 @@ inline int fastrand() { //inline static bool TRACE_SAMPLE() { return fastrand()<16; } inline static bool TRACE_SAMPLE() { return false; } -extern thread_local int g_trace_depth; +extern thread_local bool g_tracing_allocation; enum Severity { SevSample=1, From d8cfabe73b7e159fefd3918b8db5590621c9f792 Mon Sep 17 00:00:00 2001 From: "A.J. Beamon" Date: Mon, 16 Mar 2020 13:59:31 -0700 Subject: [PATCH 2/5] Extend the allocation tracing disabling flag to cover more parts of trace logging as a precaution. Make it possible to disable via knob. --- flow/Arena.cpp | 6 +++--- flow/FastAlloc.cpp | 6 +++--- flow/Knobs.cpp | 1 + flow/Knobs.h | 1 + flow/Trace.cpp | 28 +++++++++++++++++++++++++++- flow/Trace.h | 2 +- 6 files changed, 36 insertions(+), 8 deletions(-) diff --git a/flow/Arena.cpp b/flow/Arena.cpp index 88837e102b..e362b72164 100644 --- a/flow/Arena.cpp +++ b/flow/Arena.cpp @@ -184,11 +184,11 @@ ArenaBlock* ArenaBlock::create(int dataSize, Reference& next) { b->bigSize = reqSize; b->bigUsed = sizeof(ArenaBlock); - if (FLOW_KNOBS && !g_tracing_allocation && + if (FLOW_KNOBS && g_allocation_tracing_disabled > 0 && nondeterministicRandom()->random01() < (reqSize / FLOW_KNOBS->HUGE_ARENA_LOGGING_BYTES)) { - g_tracing_allocation = true; + ++g_allocation_tracing_disabled; hugeArenaSample(reqSize); - g_tracing_allocation = false; + --g_allocation_tracing_disabled; } g_hugeArenaMemory.fetch_add(reqSize); diff --git a/flow/FastAlloc.cpp b/flow/FastAlloc.cpp index 8cac3948b4..06adaf383d 100644 --- a/flow/FastAlloc.cpp +++ b/flow/FastAlloc.cpp @@ -445,10 +445,10 @@ void FastAllocator::getMagazine() { // FIXME: We should be able to allocate larger magazine sizes here if we // detect that the underlying system supports hugepages. Using hugepages // with smaller-than-2MiB magazine sizes strands memory. See issue #909. - if(FLOW_KNOBS && !g_tracing_allocation && nondeterministicRandom()->random01() < (magazine_size * Size)/FLOW_KNOBS->FAST_ALLOC_LOGGING_BYTES) { - g_tracing_allocation = true; + if(FLOW_KNOBS && g_allocation_tracing_disabled > 0 && nondeterministicRandom()->random01() < (magazine_size * Size)/FLOW_KNOBS->FAST_ALLOC_LOGGING_BYTES) { + ++g_allocation_tracing_disabled; TraceEvent("GetMagazineSample").detail("Size", Size).backtrace(); - g_tracing_allocation = false; + --g_allocation_tracing_disabled; } block = (void **)::allocate(magazine_size * Size, false); #endif diff --git a/flow/Knobs.cpp b/flow/Knobs.cpp index 276857a966..4057489c52 100644 --- a/flow/Knobs.cpp +++ b/flow/Knobs.cpp @@ -153,6 +153,7 @@ FlowKnobs::FlowKnobs(bool randomize, bool isSimulated) { init( TRACE_EVENT_THROTTLER_MSG_LIMIT, 20000 ); init( MAX_TRACE_FIELD_LENGTH, 495 ); // If the value of this is changed, the corresponding default in Trace.cpp should be changed as well init( MAX_TRACE_EVENT_LENGTH, 4000 ); // If the value of this is changed, the corresponding default in Trace.cpp should be changed as well + init( ALLOCATION_TRACING_ENABLED, true ); //TDMetrics init( MAX_METRICS, 600 ); diff --git a/flow/Knobs.h b/flow/Knobs.h index a3bdd1572f..ae8d58ef6a 100644 --- a/flow/Knobs.h +++ b/flow/Knobs.h @@ -175,6 +175,7 @@ public: int TRACE_EVENT_THROTTLER_MSG_LIMIT; int MAX_TRACE_FIELD_LENGTH; int MAX_TRACE_EVENT_LENGTH; + bool ALLOCATION_TRACING_ENABLED; //TDMetrics int64_t MAX_METRIC_SIZE; diff --git a/flow/Trace.cpp b/flow/Trace.cpp index 9f6a77bc1f..cdab1315ae 100644 --- a/flow/Trace.cpp +++ b/flow/Trace.cpp @@ -43,7 +43,15 @@ #undef min #endif -thread_local bool g_tracing_allocation = false; +// Allocations can only be logged when this value is 0. +// Anybody that needs to disable tracing should increment this by 1 for the duration +// that they need the disabling to be in effect. +// +// This is done for multiple reasons: +// 1. To avoid recursion in the allocation tracing when each trace event does an allocation +// 2. To avoid a historically documented but unknown crash that occurs when logging allocations +// during an open trace event +thread_local int g_allocation_tracing_disabled = 1; class DummyThreadPool : public IThreadPool, ReferenceCounted { public: @@ -745,6 +753,9 @@ bool TraceEvent::init() { if(initialized) { return enabled; } + + ++g_allocation_tracing_disabled; + initialized = true; ASSERT(*type != '\0'); @@ -790,6 +801,7 @@ bool TraceEvent::init() { tmpEventMetric = nullptr; } + --g_allocation_tracing_disabled; return enabled; } @@ -819,6 +831,7 @@ TraceEvent& TraceEvent::errorImpl(class Error const& error, bool includeCancelle TraceEvent& TraceEvent::detailImpl( std::string&& key, std::string&& value, bool writeEventMetricField) { init(); if (enabled) { + ++g_allocation_tracing_disabled; if( maxFieldLength >= 0 && value.size() > maxFieldLength ) { value = value.substr(0, maxFieldLength) + "..."; } @@ -833,20 +846,27 @@ TraceEvent& TraceEvent::detailImpl( std::string&& key, std::string&& value, bool TraceEvent(g_network && g_network->isSimulated() ? SevError : SevWarnAlways, "TraceEventOverflow").setMaxEventLength(1000).detail("TraceFirstBytes", fields.toString().substr(300)); enabled = false; } + --g_allocation_tracing_disabled; } return *this; } void TraceEvent::setField(const char* key, int64_t value) { + ++g_allocation_tracing_disabled; tmpEventMetric->setField(key, value); + --g_allocation_tracing_disabled; } void TraceEvent::setField(const char* key, double value) { + ++g_allocation_tracing_disabled; tmpEventMetric->setField(key, value); + --g_allocation_tracing_disabled; } void TraceEvent::setField(const char* key, const std::string& value) { + ++g_allocation_tracing_disabled; tmpEventMetric->setField(key, Standalone(value)); + --g_allocation_tracing_disabled; } TraceEvent& TraceEvent::detailf( std::string key, const char* valueFormat, ... ) { @@ -977,6 +997,7 @@ TraceEvent& TraceEvent::backtrace(const std::string& prefix) { void TraceEvent::log() { if(!logged) { init(); + ++g_allocation_tracing_disabled; try { if (enabled) { fields.mutate(timeIndex).second = format("%.6f", TraceEvent::getCurrentTime()); @@ -1011,6 +1032,7 @@ void TraceEvent::log() { } delete tmpEventMetric; logged = true; + --g_allocation_tracing_disabled; } } @@ -1021,6 +1043,10 @@ TraceEvent::~TraceEvent() { thread_local bool TraceEvent::networkThread = false; void TraceEvent::setNetworkThread() { + if(FLOW_KNOBS->ALLOCATION_TRACING_ENABLED) { + --g_allocation_tracing_disabled; + } + traceEventThrottlerCache = new TransientThresholdMetricSample>(FLOW_KNOBS->TRACE_EVENT_METRIC_UNITS_PER_SAMPLE, FLOW_KNOBS->TRACE_EVENT_THROTTLER_MSG_LIMIT); networkThread = true; } diff --git a/flow/Trace.h b/flow/Trace.h index 5d7bb242d1..baabcceded 100644 --- a/flow/Trace.h +++ b/flow/Trace.h @@ -43,7 +43,7 @@ inline int fastrand() { //inline static bool TRACE_SAMPLE() { return fastrand()<16; } inline static bool TRACE_SAMPLE() { return false; } -extern thread_local bool g_tracing_allocation; +extern thread_local int g_allocation_tracing_disabled; enum Severity { SevSample=1, From 7769218303395524b71d15c922af284ddb856af6 Mon Sep 17 00:00:00 2001 From: "A.J. Beamon" Date: Mon, 16 Mar 2020 14:11:07 -0700 Subject: [PATCH 3/5] Move an increment after an ASSERT. --- flow/Trace.cpp | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/flow/Trace.cpp b/flow/Trace.cpp index cdab1315ae..9b5974af3c 100644 --- a/flow/Trace.cpp +++ b/flow/Trace.cpp @@ -754,11 +754,11 @@ bool TraceEvent::init() { return enabled; } + initialized = true; + ASSERT(*type != '\0'); + ++g_allocation_tracing_disabled; - initialized = true; - - ASSERT(*type != '\0'); enabled = enabled && ( !g_network || severity >= FLOW_KNOBS->MIN_TRACE_SEVERITY ); // Backstop to throttle very spammy trace events From 96187618a05c72f222de5d6ce9cd749e2cf92bce Mon Sep 17 00:00:00 2001 From: "A.J. Beamon" Date: Mon, 16 Mar 2020 15:12:50 -0700 Subject: [PATCH 4/5] Fix condition to check whether allocation tracing is enabled --- flow/Arena.cpp | 2 +- flow/FastAlloc.cpp | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/flow/Arena.cpp b/flow/Arena.cpp index e362b72164..5e635640df 100644 --- a/flow/Arena.cpp +++ b/flow/Arena.cpp @@ -184,7 +184,7 @@ ArenaBlock* ArenaBlock::create(int dataSize, Reference& next) { b->bigSize = reqSize; b->bigUsed = sizeof(ArenaBlock); - if (FLOW_KNOBS && g_allocation_tracing_disabled > 0 && + if (FLOW_KNOBS && g_allocation_tracing_disabled == 0 && nondeterministicRandom()->random01() < (reqSize / FLOW_KNOBS->HUGE_ARENA_LOGGING_BYTES)) { ++g_allocation_tracing_disabled; hugeArenaSample(reqSize); diff --git a/flow/FastAlloc.cpp b/flow/FastAlloc.cpp index 06adaf383d..a05c91cc79 100644 --- a/flow/FastAlloc.cpp +++ b/flow/FastAlloc.cpp @@ -445,7 +445,7 @@ void FastAllocator::getMagazine() { // FIXME: We should be able to allocate larger magazine sizes here if we // detect that the underlying system supports hugepages. Using hugepages // with smaller-than-2MiB magazine sizes strands memory. See issue #909. - if(FLOW_KNOBS && g_allocation_tracing_disabled > 0 && nondeterministicRandom()->random01() < (magazine_size * Size)/FLOW_KNOBS->FAST_ALLOC_LOGGING_BYTES) { + if(FLOW_KNOBS && g_allocation_tracing_disabled == 0 && nondeterministicRandom()->random01() < (magazine_size * Size)/FLOW_KNOBS->FAST_ALLOC_LOGGING_BYTES) { ++g_allocation_tracing_disabled; TraceEvent("GetMagazineSample").detail("Size", Size).backtrace(); --g_allocation_tracing_disabled; From f1523bd47229f2361ea5bdc94755c7c5dbd33293 Mon Sep 17 00:00:00 2001 From: "A.J. Beamon" Date: Mon, 16 Mar 2020 15:37:06 -0700 Subject: [PATCH 5/5] Setting the network thread more than once is a no-op --- flow/Trace.cpp | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/flow/Trace.cpp b/flow/Trace.cpp index 9b5974af3c..de93602da8 100644 --- a/flow/Trace.cpp +++ b/flow/Trace.cpp @@ -1043,12 +1043,14 @@ TraceEvent::~TraceEvent() { thread_local bool TraceEvent::networkThread = false; void TraceEvent::setNetworkThread() { - if(FLOW_KNOBS->ALLOCATION_TRACING_ENABLED) { - --g_allocation_tracing_disabled; - } + if(!networkThread) { + if(FLOW_KNOBS->ALLOCATION_TRACING_ENABLED) { + --g_allocation_tracing_disabled; + } - traceEventThrottlerCache = new TransientThresholdMetricSample>(FLOW_KNOBS->TRACE_EVENT_METRIC_UNITS_PER_SAMPLE, FLOW_KNOBS->TRACE_EVENT_THROTTLER_MSG_LIMIT); - networkThread = true; + traceEventThrottlerCache = new TransientThresholdMetricSample>(FLOW_KNOBS->TRACE_EVENT_METRIC_UNITS_PER_SAMPLE, FLOW_KNOBS->TRACE_EVENT_THROTTLER_MSG_LIMIT); + networkThread = true; + } } bool TraceEvent::isNetworkThread() {