From 50e515c29a62ce56e9a0bd9ca70b93e6fd3b5483 Mon Sep 17 00:00:00 2001 From: David Youngworth Date: Wed, 21 Oct 2020 17:57:27 -0700 Subject: [PATCH 1/4] Add DateTime to trace, initial commit --- flow/Knobs.cpp | 1 + flow/Knobs.h | 1 + flow/Trace.cpp | 65 ++++++++++++++++++++++++++++++++++++++++++++++---- flow/Trace.h | 13 ++++++++++ 4 files changed, 76 insertions(+), 4 deletions(-) diff --git a/flow/Knobs.cpp b/flow/Knobs.cpp index 3df410ddcb..28b7deb180 100644 --- a/flow/Knobs.cpp +++ b/flow/Knobs.cpp @@ -151,6 +151,7 @@ FlowKnobs::FlowKnobs(bool randomize, bool isSimulated) { init( TRACE_RETRY_OPEN_INTERVAL, 1.00 ); init( MIN_TRACE_SEVERITY, isSimulated ? 0 : 10 ); // Related to the trace severity in Trace.h init( MAX_TRACE_SUPPRESSIONS, 1e4 ); + init( TRACE_DATETIME_ENABLED, true ); // trace time in human readable format (always real time) init( TRACE_SYNC_ENABLED, 0 ); init( TRACE_EVENT_METRIC_UNITS_PER_SAMPLE, 500 ); init( TRACE_EVENT_THROTTLER_SAMPLE_EXPIRY, 1800.0 ); // 30 mins diff --git a/flow/Knobs.h b/flow/Knobs.h index d42807305c..5dd746cc84 100644 --- a/flow/Knobs.h +++ b/flow/Knobs.h @@ -173,6 +173,7 @@ public: double TRACE_RETRY_OPEN_INTERVAL; int MIN_TRACE_SEVERITY; int MAX_TRACE_SUPPRESSIONS; + bool TRACE_DATETIME_ENABLED; int TRACE_SYNC_ENABLED; int TRACE_EVENT_METRIC_UNITS_PER_SAMPLE; int TRACE_EVENT_THROTTLER_SAMPLE_EXPIRY; diff --git a/flow/Trace.cpp b/flow/Trace.cpp index ec46772eeb..a70e48f5f0 100644 --- a/flow/Trace.cpp +++ b/flow/Trace.cpp @@ -29,7 +29,8 @@ #include #include #include - +#include +#include #include "flow/IThreadPool.h" #include "flow/ThreadHelper.actor.h" #include "flow/FastRef.h" @@ -422,6 +423,7 @@ public: if (roll) { auto o = new WriterThread::Roll; + double time = 0; writer->post(o); std::vector events = latestEventCache.getAllUnsafe(); @@ -430,9 +432,15 @@ public: TraceEventFields rolledFields; for(auto itr = events[idx].begin(); itr != events[idx].end(); ++itr) { if(itr->first == "Time") { - rolledFields.addField("Time", format("%.6f", TraceEvent::getCurrentTime())); + time = TraceEvent::getCurrentTime(); + rolledFields.addField("Time", format("%.6f", time)); rolledFields.addField("OriginalTime", itr->second); } + if (itr->first == "DateTime") { + UNSTOPPABLE_ASSERT(time > 0); // "Time" field should always come first + rolledFields.addField("DateTime", TraceEvent::printRealTime(time)); + rolledFields.addField("OriginalDateTime", itr->second); + } else if(itr->first == "TrackLatestType") { rolledFields.addField("TrackLatestType", "Rolled"); } @@ -797,6 +805,9 @@ bool TraceEvent::init() { detail("Severity", int(severity)); detail("Time", "0.000000"); timeIndex = fields.size() - 1; + if (FLOW_KNOBS->TRACE_DATETIME_ENABLED) { + detail("DateTime", ""); + } detail("Type", type); if(g_network && g_network->isSimulated()) { @@ -997,7 +1008,7 @@ TraceEvent& TraceEvent::GetLastError() { // We're cheating in counting, as in practice, we only use {10,20,30,40}. static_assert(SevMaxUsed / 10 + 1 == 5, "Please bump eventCounts[5] to SevMaxUsed/10+1"); -unsigned long TraceEvent::eventCounts[5] = {0,0,0,0,0}; +unsigned long TraceEvent::eventCounts[5] = { 0, 0, 0, 0, 0 }; unsigned long TraceEvent::CountEventsLoggedAt(Severity sev) { return TraceEvent::eventCounts[sev/10]; @@ -1015,7 +1026,11 @@ void TraceEvent::log() { ++g_allocation_tracing_disabled; try { if (enabled) { - fields.mutate(timeIndex).second = format("%.6f", TraceEvent::getCurrentTime()); + double time = TraceEvent::getCurrentTime(); + fields.mutate(timeIndex).second = format("%.6f", time); + if (FLOW_KNOBS->TRACE_DATETIME_ENABLED) { + fields.mutate(timeIndex + 1).second = TraceEvent::printRealTime(time); + } if (this->severity == SevError) { severity = SevInfo; @@ -1086,6 +1101,15 @@ double TraceEvent::getCurrentTime() { } } +std::string TraceEvent::printRealTime(double time) { + if (g_network != nullptr) { + static RealTimePrinter realTimePrinter; + return realTimePrinter.toString(time); + } else { + return "0"; + } +} + TraceInterval& TraceInterval::begin() { pairID = nondeterministicRandom()->randomUniqueID(); count = 0; @@ -1153,6 +1177,9 @@ void TraceBatch::dump() { TraceBatch::EventInfo::EventInfo(double time, const char *name, uint64_t id, const char *location) { fields.addField("Severity", format("%d", (int)SevInfo)); fields.addField("Time", format("%.6f", time)); + if (FLOW_KNOBS->TRACE_DATETIME_ENABLED) { + fields.addField("DateTime", TraceEvent::printRealTime(time)); + } fields.addField("Type", name); fields.addField("ID", format("%016" PRIx64, id)); fields.addField("Location", location); @@ -1161,6 +1188,9 @@ TraceBatch::EventInfo::EventInfo(double time, const char *name, uint64_t id, con TraceBatch::AttachInfo::AttachInfo(double time, const char *name, uint64_t id, uint64_t to) { fields.addField("Severity", format("%d", (int)SevInfo)); fields.addField("Time", format("%.6f", time)); + if (FLOW_KNOBS->TRACE_DATETIME_ENABLED) { + fields.addField("DateTime", TraceEvent::printRealTime(time)); + } fields.addField("Type", name); fields.addField("ID", format("%016" PRIx64, id)); fields.addField("To", format("%016" PRIx64, to)); @@ -1169,6 +1199,9 @@ TraceBatch::AttachInfo::AttachInfo(double time, const char *name, uint64_t id, u TraceBatch::BuggifyInfo::BuggifyInfo(double time, int activated, int line, std::string file) { fields.addField("Severity", format("%d", (int)SevInfo)); fields.addField("Time", format("%.6f", time)); + if (FLOW_KNOBS->TRACE_DATETIME_ENABLED) { + fields.addField("DateTime", TraceEvent::printRealTime(time)); + } fields.addField("Type", "BuggifySection"); fields.addField("Activated", format("%d", activated)); fields.addField("File", std::move(file)); @@ -1371,3 +1404,27 @@ std::string traceableStringToString(const char* value, size_t S) { return std::string(value, S - 1); // Exclude trailing \0 byte } + +RealTimePrinter::RealTimePrinter() : beginTime(Clock::now()), flowBeginTime(g_network->now()) {} + +// converts the given flow time into a +// string. now has to be larger +// then flowBeginTime. +// %Y-%m-%dT%H:%M:%S +// This only has second-resolution for the simple reason +// that std::put_time does not support higher resolution. +// As we always also log the flow time and this is only for +// human readability, this is good enough for now. +std::string RealTimePrinter::toString(double now) { + time_t n = Clock::to_time_t(beginTime + std::chrono::microseconds(std::lround(1e6 * (now - flowBeginTime)))); + if (g_network->isSimulated()) { + // in simulation, the clock is simulated as well. Therefore, + // actual time might be very different from simulated time. + n = Clock::to_time_t(Clock::now()); + } + std::stringstream ss; + // Use thread-safe localtime_r instead of localtime + struct tm result; + ss << std::put_time(::localtime_r(&n, &result), "%Y-%m-%dT%H:%M:%S"); + return ss.str(); +} diff --git a/flow/Trace.h b/flow/Trace.h index baabcceded..4c90b78236 100644 --- a/flow/Trace.h +++ b/flow/Trace.h @@ -26,6 +26,7 @@ #include #include #include +#include #include #include #include "flow/IRandom.h" @@ -374,6 +375,16 @@ struct SpecialTraceMetricType TRACE_METRIC_TYPE(double, double); +struct RealTimePrinter { + using Clock = std::chrono::system_clock; + + Clock::time_point beginTime; + double flowBeginTime; + + RealTimePrinter(); + std::string toString(double now); +}; + struct TraceEvent { TraceEvent(); TraceEvent( const char* type, UID id = UID() ); // Assumes SevInfo severity @@ -388,6 +399,7 @@ struct TraceEvent { static bool isNetworkThread(); static double getCurrentTime(); + static std::string printRealTime(double time); //Must be called directly after constructing the trace event TraceEvent& error(const class Error& e, bool includeCancelled=false) { @@ -501,6 +513,7 @@ private: static unsigned long eventCounts[5]; static thread_local bool networkThread; + static thread_local RealTimePrinter realTimePrinter; bool init(); bool init( struct TraceInterval& ); From 490fe61032f3b21faa72929a210fd431cbd4b5ab Mon Sep 17 00:00:00 2001 From: David Youngworth Date: Wed, 4 Nov 2020 11:55:39 -0800 Subject: [PATCH 2/4] Fix bug in rolled Trace code --- flow/Trace.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/flow/Trace.cpp b/flow/Trace.cpp index a70e48f5f0..1d63e822df 100644 --- a/flow/Trace.cpp +++ b/flow/Trace.cpp @@ -436,7 +436,7 @@ public: rolledFields.addField("Time", format("%.6f", time)); rolledFields.addField("OriginalTime", itr->second); } - if (itr->first == "DateTime") { + else if (itr->first == "DateTime") { UNSTOPPABLE_ASSERT(time > 0); // "Time" field should always come first rolledFields.addField("DateTime", TraceEvent::printRealTime(time)); rolledFields.addField("OriginalDateTime", itr->second); From 5ade54f7671afeecf11ae0f9232ebf0b3c44cc40 Mon Sep 17 00:00:00 2001 From: David Youngworth Date: Thu, 5 Nov 2020 11:31:14 -0800 Subject: [PATCH 3/4] Fix windows build, DateTime to use UTC --- flow/Trace.cpp | 12 +++++++++--- 1 file changed, 9 insertions(+), 3 deletions(-) diff --git a/flow/Trace.cpp b/flow/Trace.cpp index 1d63e822df..56cf273a03 100644 --- a/flow/Trace.cpp +++ b/flow/Trace.cpp @@ -1410,7 +1410,7 @@ RealTimePrinter::RealTimePrinter() : beginTime(Clock::now()), flowBeginTime(g_ne // converts the given flow time into a // string. now has to be larger // then flowBeginTime. -// %Y-%m-%dT%H:%M:%S +// %Y-%m-%dT%H:%M:%SZ // This only has second-resolution for the simple reason // that std::put_time does not support higher resolution. // As we always also log the flow time and this is only for @@ -1423,8 +1423,14 @@ std::string RealTimePrinter::toString(double now) { n = Clock::to_time_t(Clock::now()); } std::stringstream ss; - // Use thread-safe localtime_r instead of localtime + +#ifdef _WIN32 + // MSVC gmtime is threadsafe + ss << std::put_time(::gmtime(&n), "%Y-%m-%dT%H:%M:%SZ"); +#else + // use threadsafe gmt struct tm result; - ss << std::put_time(::localtime_r(&n, &result), "%Y-%m-%dT%H:%M:%S"); + ss << std::put_time(::gmtime_r(&n, &result), "%Y-%m-%dT%H:%M:%SZ"); +#endif return ss.str(); } From b1256b5dcd22ad58aa5eede436b89f4133a650d2 Mon Sep 17 00:00:00 2001 From: David Youngworth Date: Wed, 18 Nov 2020 16:45:37 -0800 Subject: [PATCH 4/4] Address review comments, simplify DateTime --- flow/Trace.cpp | 56 +++++++++++++++++++------------------------------- flow/Trace.h | 11 ---------- 2 files changed, 21 insertions(+), 46 deletions(-) diff --git a/flow/Trace.cpp b/flow/Trace.cpp index 56cf273a03..a2a1b3b458 100644 --- a/flow/Trace.cpp +++ b/flow/Trace.cpp @@ -1101,13 +1101,29 @@ double TraceEvent::getCurrentTime() { } } +// converts the given flow time into a string +// with format: %Y-%m-%dT%H:%M:%S +// This only has second-resolution for the simple reason +// that std::put_time does not support higher resolution. +// This is fine since we always log the flow time as well. std::string TraceEvent::printRealTime(double time) { - if (g_network != nullptr) { - static RealTimePrinter realTimePrinter; - return realTimePrinter.toString(time); - } else { - return "0"; + using Clock = std::chrono::system_clock; + time_t ts = Clock::to_time_t(Clock::time_point( + std::chrono::duration_cast(std::chrono::duration>(time)))); + if (g_network && g_network->isSimulated()) { + // The clock is simulated, so return the real time + ts = Clock::to_time_t(Clock::now()); } + std::stringstream ss; +#ifdef _WIN32 + // MSVC gmtime is threadsafe + ss << std::put_time(::gmtime(&ts), "%Y-%m-%dT%H:%M:%SZ"); +#else + // use threadsafe gmt + struct tm result; + ss << std::put_time(::gmtime_r(&ts, &result), "%Y-%m-%dT%H:%M:%SZ"); +#endif + return ss.str(); } TraceInterval& TraceInterval::begin() { @@ -1404,33 +1420,3 @@ std::string traceableStringToString(const char* value, size_t S) { return std::string(value, S - 1); // Exclude trailing \0 byte } - -RealTimePrinter::RealTimePrinter() : beginTime(Clock::now()), flowBeginTime(g_network->now()) {} - -// converts the given flow time into a -// string. now has to be larger -// then flowBeginTime. -// %Y-%m-%dT%H:%M:%SZ -// This only has second-resolution for the simple reason -// that std::put_time does not support higher resolution. -// As we always also log the flow time and this is only for -// human readability, this is good enough for now. -std::string RealTimePrinter::toString(double now) { - time_t n = Clock::to_time_t(beginTime + std::chrono::microseconds(std::lround(1e6 * (now - flowBeginTime)))); - if (g_network->isSimulated()) { - // in simulation, the clock is simulated as well. Therefore, - // actual time might be very different from simulated time. - n = Clock::to_time_t(Clock::now()); - } - std::stringstream ss; - -#ifdef _WIN32 - // MSVC gmtime is threadsafe - ss << std::put_time(::gmtime(&n), "%Y-%m-%dT%H:%M:%SZ"); -#else - // use threadsafe gmt - struct tm result; - ss << std::put_time(::gmtime_r(&n, &result), "%Y-%m-%dT%H:%M:%SZ"); -#endif - return ss.str(); -} diff --git a/flow/Trace.h b/flow/Trace.h index 4c90b78236..7193e7b89b 100644 --- a/flow/Trace.h +++ b/flow/Trace.h @@ -375,16 +375,6 @@ struct SpecialTraceMetricType TRACE_METRIC_TYPE(double, double); -struct RealTimePrinter { - using Clock = std::chrono::system_clock; - - Clock::time_point beginTime; - double flowBeginTime; - - RealTimePrinter(); - std::string toString(double now); -}; - struct TraceEvent { TraceEvent(); TraceEvent( const char* type, UID id = UID() ); // Assumes SevInfo severity @@ -513,7 +503,6 @@ private: static unsigned long eventCounts[5]; static thread_local bool networkThread; - static thread_local RealTimePrinter realTimePrinter; bool init(); bool init( struct TraceInterval& );