From 7152469cc3e73c5ecd90c267a41dba5828a310f9 Mon Sep 17 00:00:00 2001 From: Evan Tschannen Date: Fri, 3 Jan 2020 12:15:38 -0800 Subject: [PATCH] log the base trace event before the endpoint messages --- fdbrpc/LoadBalance.actor.h | 3 +- flow/Trace.cpp | 67 +++++++++++++++++++++----------------- flow/Trace.h | 3 ++ 3 files changed, 42 insertions(+), 31 deletions(-) diff --git a/fdbrpc/LoadBalance.actor.h b/fdbrpc/LoadBalance.actor.h index d6192209cc..407c20654f 100644 --- a/fdbrpc/LoadBalance.actor.h +++ b/fdbrpc/LoadBalance.actor.h @@ -287,9 +287,10 @@ Future< REPLY_TYPE(Request) > loadBalance( ev.detail("Backoff", backoff); ev.detail("TriedAllOptions", triedAllOptions); if(ev.isEnabled()) { + ev.log(); for(int alternativeNum=0; alternativeNumsize(); alternativeNum++) { RequestStream const* thisStream = &alternatives->get( alternativeNum, channel ); - TraceEvent(g_network->isSimulated() ? SevWarn : SevWarnAlways, "LoadBalanceTooLongEndpoint").detail("Addr", thisStream->getEndpoint().getPrimaryAddress()).detail("Token", thisStream->getEndpoint().token).detail("Failed", IFailureMonitor::failureMonitor().getState( thisStream->getEndpoint() ).failed); + TraceEvent(SevWarn, "LoadBalanceTooLongEndpoint").detail("Addr", thisStream->getEndpoint().getPrimaryAddress()).detail("Token", thisStream->getEndpoint().token).detail("Failed", IFailureMonitor::failureMonitor().getState( thisStream->getEndpoint() ).failed); } } } diff --git a/flow/Trace.cpp b/flow/Trace.cpp index 41fa71ae73..ed283ba8da 100644 --- a/flow/Trace.cpp +++ b/flow/Trace.cpp @@ -653,13 +653,13 @@ void removeTraceRole(std::string role) { g_traceLog.removeRole(role); } -TraceEvent::TraceEvent( const char* type, UID id ) : id(id), type(type), severity(SevInfo), initialized(false), enabled(true) { +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), + : 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); @@ -668,7 +668,7 @@ TraceEvent::TraceEvent( Severity severity, const char* type, UID id ) TraceEvent::TraceEvent( TraceInterval& interval, UID id ) : id(id), type(interval.type), severity(interval.severity), - initialized(false), + initialized(false), logged(false), enabled(g_network == nullptr || FLOW_KNOBS->MIN_TRACE_SEVERITY <= interval.severity) { g_trace_depth++; @@ -680,7 +680,7 @@ TraceEvent::TraceEvent( TraceInterval& interval, UID id ) TraceEvent::TraceEvent( Severity severity, TraceInterval& interval, UID id ) : id(id), type(interval.type), severity(severity), - initialized(false), + initialized(false), logged(false), enabled(g_network == nullptr || FLOW_KNOBS->MIN_TRACE_SEVERITY <= severity) { g_trace_depth++; @@ -938,40 +938,47 @@ TraceEvent& TraceEvent::backtrace(const std::string& prefix) { return detail(prefix + "Backtrace", platform::get_backtrace()); } -TraceEvent::~TraceEvent() { - init(); - try { - if (enabled) { - if (this->severity == SevError) { - severity = SevInfo; - backtrace(); - severity = SevError; - } +void TraceEvent::log() { + if(!logged) { + logged = true; + init(); + try { + if (enabled) { + if (this->severity == SevError) { + severity = SevInfo; + backtrace(); + severity = SevError; + } - if(isNetworkThread()) { - TraceEvent::eventCounts[severity/10]++; - } + if(isNetworkThread()) { + TraceEvent::eventCounts[severity/10]++; + } - g_traceLog.writeEvent( fields, trackingKey, severity > SevWarnAlways ); + g_traceLog.writeEvent( fields, trackingKey, severity > SevWarnAlways ); - if (g_traceLog.isOpen()) { - // Log Metrics - if(g_traceLog.logTraceEventMetrics && isNetworkThread()) { - // Get the persistent Event Metric representing this trace event and push the fields (details) accumulated in *this to it and then log() it. - // Note that if the event metric is disabled it won't actually be logged BUT any new fields added to it will be registered. - // If the event IS logged, a timestamp will be returned, if not then 0. Either way, pass it through to be used if possible - // in the Sev* event metrics. + if (g_traceLog.isOpen()) { + // Log Metrics + if(g_traceLog.logTraceEventMetrics && isNetworkThread()) { + // Get the persistent Event Metric representing this trace event and push the fields (details) accumulated in *this to it and then log() it. + // Note that if the event metric is disabled it won't actually be logged BUT any new fields added to it will be registered. + // If the event IS logged, a timestamp will be returned, if not then 0. Either way, pass it through to be used if possible + // in the Sev* event metrics. - uint64_t event_ts = DynamicEventMetric::getOrCreateInstance(format("TraceEvent.%s", type), StringRef(), true)->setFieldsAndLogFrom(tmpEventMetric); - g_traceLog.log(severity, type, id, event_ts); + uint64_t event_ts = DynamicEventMetric::getOrCreateInstance(format("TraceEvent.%s", type), StringRef(), true)->setFieldsAndLogFrom(tmpEventMetric); + g_traceLog.log(severity, type, id, event_ts); + } } } + } catch( Error &e ) { + TraceEvent(SevError, "TraceEventDestructorError").error(e,true); } - } catch( Error &e ) { - TraceEvent(SevError, "TraceEventDestructorError").error(e,true); + delete tmpEventMetric; + g_trace_depth--; } - delete tmpEventMetric; - g_trace_depth--; +} + +TraceEvent::~TraceEvent() { + log(); } thread_local bool TraceEvent::networkThread = false; diff --git a/flow/Trace.h b/flow/Trace.h index a49d676df4..2f3c927393 100644 --- a/flow/Trace.h +++ b/flow/Trace.h @@ -464,6 +464,8 @@ public: return enabled; } + void log(); + ~TraceEvent(); // Actually logs the event // Return the number of invocations of TraceEvent() at the specified logging level. @@ -474,6 +476,7 @@ public: private: bool initialized; bool enabled; + bool logged; std::string trackingKey; TraceEventFields fields; Severity severity;