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..a2a1b3b458 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); } + 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); + } 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,31 @@ 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) { + 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() { pairID = nondeterministicRandom()->randomUniqueID(); count = 0; @@ -1153,6 +1193,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 +1204,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 +1215,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)); diff --git a/flow/Trace.h b/flow/Trace.h index baabcceded..7193e7b89b 100644 --- a/flow/Trace.h +++ b/flow/Trace.h @@ -26,6 +26,7 @@ #include #include #include +#include #include #include #include "flow/IRandom.h" @@ -388,6 +389,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) {