2017-05-26 04:48:44 +08:00
|
|
|
/*
|
|
|
|
* Trace.cpp
|
|
|
|
*
|
|
|
|
* This source file is part of the FoundationDB open source project
|
|
|
|
*
|
2022-03-22 04:36:23 +08:00
|
|
|
* Copyright 2013-2022 Apple Inc. and the FoundationDB project authors
|
2018-02-22 02:25:11 +08:00
|
|
|
*
|
2017-05-26 04:48:44 +08:00
|
|
|
* Licensed under the Apache License, Version 2.0 (the "License");
|
|
|
|
* you may not use this file except in compliance with the License.
|
|
|
|
* You may obtain a copy of the License at
|
2018-02-22 02:25:11 +08:00
|
|
|
*
|
2017-05-26 04:48:44 +08:00
|
|
|
* http://www.apache.org/licenses/LICENSE-2.0
|
2018-02-22 02:25:11 +08:00
|
|
|
*
|
2017-05-26 04:48:44 +08:00
|
|
|
* Unless required by applicable law or agreed to in writing, software
|
|
|
|
* distributed under the License is distributed on an "AS IS" BASIS,
|
|
|
|
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
|
|
|
* See the License for the specific language governing permissions and
|
|
|
|
* limitations under the License.
|
|
|
|
*/
|
|
|
|
|
2018-10-20 01:30:13 +08:00
|
|
|
#include "flow/Trace.h"
|
|
|
|
#include "flow/FileTraceLogWriter.h"
|
2020-07-08 00:06:13 +08:00
|
|
|
#include "flow/Knobs.h"
|
2018-10-20 01:30:13 +08:00
|
|
|
#include "flow/XmlTraceLogFormatter.h"
|
2018-08-25 06:30:00 +08:00
|
|
|
#include "flow/JsonTraceLogFormatter.h"
|
2018-10-20 01:30:13 +08:00
|
|
|
#include "flow/flow.h"
|
|
|
|
#include "flow/DeterministicRandom.h"
|
2017-05-26 04:48:44 +08:00
|
|
|
#include <stdlib.h>
|
|
|
|
#include <stdarg.h>
|
2018-08-25 06:30:00 +08:00
|
|
|
#include <cctype>
|
2017-05-26 04:48:44 +08:00
|
|
|
#include <time.h>
|
2020-03-13 05:34:19 +08:00
|
|
|
#include <set>
|
2020-10-22 08:57:27 +08:00
|
|
|
#include <iomanip>
|
2018-10-20 01:30:13 +08:00
|
|
|
#include "flow/IThreadPool.h"
|
|
|
|
#include "flow/ThreadHelper.actor.h"
|
|
|
|
#include "flow/FastRef.h"
|
|
|
|
#include "flow/EventTypes.actor.h"
|
|
|
|
#include "flow/TDMetric.actor.h"
|
|
|
|
#include "flow/MetricSample.h"
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2018-06-29 05:59:23 +08:00
|
|
|
#ifdef _WIN32
|
|
|
|
#include <windows.h>
|
|
|
|
#undef max
|
|
|
|
#undef min
|
|
|
|
#endif
|
|
|
|
|
2020-03-17 04:59:31 +08:00
|
|
|
// 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;
|
2019-05-07 08:41:32 +08:00
|
|
|
|
2020-07-08 00:06:13 +08:00
|
|
|
ITraceLogIssuesReporter::~ITraceLogIssuesReporter() {}
|
2020-05-07 05:18:53 +08:00
|
|
|
|
2017-05-26 04:48:44 +08:00
|
|
|
struct SuppressionMap {
|
|
|
|
struct SuppressionInfo {
|
|
|
|
double endTime;
|
|
|
|
int64_t suppressedEventCount;
|
|
|
|
|
|
|
|
SuppressionInfo() : endTime(0), suppressedEventCount(0) {}
|
|
|
|
};
|
|
|
|
|
|
|
|
std::map<std::string, SuppressionInfo> suppressionMap;
|
|
|
|
|
|
|
|
// Returns -1 if this event is suppressed
|
|
|
|
int64_t checkAndInsertSuppression(std::string type, double duration) {
|
2018-05-03 01:44:38 +08:00
|
|
|
ASSERT(g_network);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (suppressionMap.size() >= FLOW_KNOBS->MAX_TRACE_SUPPRESSIONS) {
|
2021-07-27 10:55:10 +08:00
|
|
|
TraceEvent(SevWarnAlways, "ClearingTraceSuppressionMap").log();
|
2017-05-26 04:48:44 +08:00
|
|
|
suppressionMap.clear();
|
|
|
|
}
|
|
|
|
|
|
|
|
auto insertion = suppressionMap.insert(std::make_pair(type, SuppressionInfo()));
|
2021-03-11 02:06:03 +08:00
|
|
|
if (insertion.second || insertion.first->second.endTime <= now()) {
|
2017-05-26 04:48:44 +08:00
|
|
|
int64_t suppressedEventCount = insertion.first->second.suppressedEventCount;
|
|
|
|
insertion.first->second.endTime = now() + duration;
|
|
|
|
insertion.first->second.suppressedEventCount = 0;
|
|
|
|
return suppressedEventCount;
|
2021-03-11 02:06:03 +08:00
|
|
|
} else {
|
2017-05-26 04:48:44 +08:00
|
|
|
++insertion.first->second.suppressedEventCount;
|
|
|
|
return -1;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
};
|
|
|
|
|
2020-10-12 21:57:57 +08:00
|
|
|
#define TRACE_BATCH_IMPLICIT_SEVERITY SevInfo
|
2017-05-26 04:48:44 +08:00
|
|
|
TraceBatch g_traceBatch;
|
2019-12-07 02:15:49 +08:00
|
|
|
std::atomic<trace_clock_t> g_trace_clock{ TRACE_CLOCK_NOW };
|
2017-05-26 04:48:44 +08:00
|
|
|
|
|
|
|
LatestEventCache latestEventCache;
|
|
|
|
SuppressionMap suppressedEvents;
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
static TransientThresholdMetricSample<Standalone<StringRef>>* traceEventThrottlerCache;
|
|
|
|
static const char* TRACE_EVENT_THROTTLE_STARTING_TYPE = "TraceEventThrottle_";
|
|
|
|
static const char* TRACE_EVENT_INVALID_SUPPRESSION = "InvalidSuppression_";
|
2018-07-02 02:30:37 +08:00
|
|
|
static int TRACE_LOG_MAX_PREOPEN_BUFFER = 1000000;
|
2017-10-03 09:43:11 +08:00
|
|
|
|
2017-05-26 04:48:44 +08:00
|
|
|
struct TraceLog {
|
2019-01-03 08:42:00 +08:00
|
|
|
Reference<ITraceLogFormatter> formatter;
|
2018-05-03 01:44:38 +08:00
|
|
|
|
|
|
|
private:
|
2018-06-27 05:37:21 +08:00
|
|
|
Reference<ITraceLogWriter> logWriter;
|
2018-06-01 04:27:35 +08:00
|
|
|
std::vector<TraceEventFields> eventBuffer;
|
|
|
|
int loggedLength;
|
|
|
|
int bufferLength;
|
Fix another TSAN warning
```
Read of size 1 at 0x7f02082ac578 by main thread:
#0 TraceLog::close() /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/Trace.cpp:487:7 (libfdb_c.so+0xf4928c)
#1 closeTraceFile() /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/Trace.cpp:759:13 (libfdb_c.so+0xf3992a)
#2 stopNetwork() /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/fdbclient/NativeAPI.actor.cpp:2052:2 (libfdb_c.so+0x58315c)
#3 ThreadSafeApi::stopNetwork() /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../fdbclient/ThreadSafeTransaction.cpp:466:2 (libfdb_c.so+0xce8ad3)
#4 MultiVersionApi::stopNetwork() /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/fdbclient/MultiVersionTransaction.actor.cpp:1756:20 (libfdb_c.so+0x4f7da3)
#5 fdb_stop_network /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../bindings/c/fdb_c.cpp:134:2 (libfdb_c.so+0x4c84e5)
#6 main /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../bindings/c/test/unit/trace_partial_file_suffix_test.cpp:93:12 (trace_partial_file_suffix_test+0x40b3d0)
Previous write of size 1 at 0x7f02082ac578 by thread T1 (mutexes: write M100):
#0 TraceLog::open(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, unsigned long, unsigned long, Optional<NetworkAddress>, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/Trace.cpp:344:10 (libfdb_c.so+0xf48aaa)
#1 openTraceFile(NetworkAddress const&, unsigned long, unsigned long, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/Trace.cpp:741:13 (libfdb_c.so+0xf3828c)
#2 Database::createDatabase(Reference<ClusterConnectionFile>, int, IsInternal, LocalityData const&, DatabaseContext*) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/fdbclient/NativeAPI.actor.cpp:1695:4 (libfdb_c.so+0x57d57e)
#3 ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7::operator()() const /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../fdbclient/ThreadSafeTransaction.cpp:124:8 (libfdb_c.so+0xcf018c)
#4 internal_thread_helper::DoOnMainThreadVoidActorState<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7, internal_thread_helper::DoOnMainThreadVoidActor<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7> >::a_body1cont1(Void const&, int) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/flow/ThreadHelper.actor.h:45:4 (libfdb_c.so+0xcf018c)
#5 internal_thread_helper::DoOnMainThreadVoidActorState<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7, internal_thread_helper::DoOnMainThreadVoidActor<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7> >::a_body1when1(Void const&, int) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/flow/ThreadHelper.actor.g.h:148:15 (libfdb_c.so+0xcf018c)
#6 internal_thread_helper::DoOnMainThreadVoidActorState<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7, internal_thread_helper::DoOnMainThreadVoidActor<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7> >::a_callback_fire(ActorCallback<internal_thread_helper::DoOnMainThreadVoidActor<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7>, 0, Void>*, Void const&) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/flow/ThreadHelper.actor.g.h:169:4 (libfdb_c.so+0xcefdef)
#7 ActorCallback<internal_thread_helper::DoOnMainThreadVoidActor<ThreadSafeDatabase::ThreadSafeDatabase(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, int)::$_7>, 0, Void>::fire(Void const&) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/flow.h:1074:78 (libfdb_c.so+0xcefdef)
#8 void SAV<Void>::send<Void>(Void&&) /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/flow.h:462:23 (libfdb_c.so+0x4dd542)
#9 void Promise<Void>::send<Void>(Void&&) const /home/jenkins/fdb/extra/long/path/to/work/around/strange/cpack/debug/rpm/behavior/_build/../flow/flow.h:699:8
```
2021-08-10 05:06:38 +08:00
|
|
|
std::atomic<bool> opened;
|
2018-03-28 23:21:22 +08:00
|
|
|
int64_t preopenOverflowCount;
|
2017-05-26 04:48:44 +08:00
|
|
|
std::string basename;
|
|
|
|
std::string logGroup;
|
2021-12-11 07:03:14 +08:00
|
|
|
std::map<std::string, std::string> universalFields;
|
2017-05-26 04:48:44 +08:00
|
|
|
|
|
|
|
std::string directory;
|
|
|
|
std::string processName;
|
2018-05-03 01:44:38 +08:00
|
|
|
Optional<NetworkAddress> localAddress;
|
2021-08-04 00:43:42 +08:00
|
|
|
std::string tracePartialFileSuffix;
|
2017-05-26 04:48:44 +08:00
|
|
|
|
|
|
|
Reference<IThreadPool> writer;
|
|
|
|
uint64_t rollsize;
|
|
|
|
Mutex mutex;
|
|
|
|
|
|
|
|
EventMetricHandle<TraceEventNameID> SevErrorNames;
|
|
|
|
EventMetricHandle<TraceEventNameID> SevWarnAlwaysNames;
|
|
|
|
EventMetricHandle<TraceEventNameID> SevWarnNames;
|
|
|
|
EventMetricHandle<TraceEventNameID> SevInfoNames;
|
|
|
|
EventMetricHandle<TraceEventNameID> SevDebugNames;
|
|
|
|
|
2018-09-06 06:06:14 +08:00
|
|
|
struct RoleInfo {
|
|
|
|
std::map<std::string, int> roles;
|
|
|
|
std::string rolesString;
|
|
|
|
|
|
|
|
void refreshRolesString() {
|
|
|
|
rolesString = "";
|
2021-03-11 02:06:03 +08:00
|
|
|
for (auto itr : roles) {
|
|
|
|
if (!rolesString.empty()) {
|
2018-09-06 06:06:14 +08:00
|
|
|
rolesString += ",";
|
|
|
|
}
|
|
|
|
rolesString += itr.first;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
};
|
|
|
|
|
|
|
|
RoleInfo roleInfo;
|
|
|
|
std::map<NetworkAddress, RoleInfo> roleInfoMap;
|
|
|
|
|
|
|
|
RoleInfo& mutateRoleInfo() {
|
|
|
|
ASSERT(g_network);
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (g_network->isSimulated()) {
|
2018-09-06 06:06:14 +08:00
|
|
|
return roleInfoMap[g_network->getLocalAddress()];
|
|
|
|
}
|
2020-06-11 23:53:29 +08:00
|
|
|
|
2018-09-06 06:06:14 +08:00
|
|
|
return roleInfo;
|
|
|
|
}
|
|
|
|
|
2018-05-03 01:44:38 +08:00
|
|
|
public:
|
|
|
|
bool logTraceEventMetrics;
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
void initMetrics() {
|
2017-05-26 04:48:44 +08:00
|
|
|
SevErrorNames.init(LiteralStringRef("TraceEvents.SevError"));
|
|
|
|
SevWarnAlwaysNames.init(LiteralStringRef("TraceEvents.SevWarnAlways"));
|
|
|
|
SevWarnNames.init(LiteralStringRef("TraceEvents.SevWarn"));
|
|
|
|
SevInfoNames.init(LiteralStringRef("TraceEvents.SevInfo"));
|
|
|
|
SevDebugNames.init(LiteralStringRef("TraceEvents.SevDebug"));
|
|
|
|
logTraceEventMetrics = true;
|
|
|
|
}
|
|
|
|
|
|
|
|
struct BarrierList : ThreadSafeReferenceCounted<BarrierList> {
|
|
|
|
BarrierList() : ntriggered(0) {}
|
2021-03-11 02:06:03 +08:00
|
|
|
void push(ThreadFuture<Void> f) {
|
2017-05-26 04:48:44 +08:00
|
|
|
MutexHolder h(mutex);
|
|
|
|
barriers.push_back(f);
|
|
|
|
}
|
|
|
|
void pop() {
|
|
|
|
MutexHolder h(mutex);
|
|
|
|
unsafeTrigger(0);
|
|
|
|
barriers.pop_front();
|
2021-03-11 02:06:03 +08:00
|
|
|
if (ntriggered)
|
|
|
|
ntriggered--;
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
void triggerAll() {
|
|
|
|
MutexHolder h(mutex);
|
2021-03-11 02:06:03 +08:00
|
|
|
for (uint32_t i = ntriggered; i < barriers.size(); i++)
|
2017-05-26 04:48:44 +08:00
|
|
|
unsafeTrigger(i);
|
|
|
|
ntriggered = barriers.size();
|
|
|
|
}
|
2021-03-11 02:06:03 +08:00
|
|
|
|
2017-05-26 04:48:44 +08:00
|
|
|
private:
|
|
|
|
Mutex mutex;
|
2021-03-11 02:06:03 +08:00
|
|
|
Deque<ThreadFuture<Void>> barriers;
|
2017-05-26 04:48:44 +08:00
|
|
|
int ntriggered;
|
|
|
|
void unsafeTrigger(int i) {
|
|
|
|
auto b = ((ThreadSingleAssignmentVar<Void>*)barriers[i].getPtr());
|
|
|
|
if (!b->isReady())
|
|
|
|
b->send(Void());
|
|
|
|
}
|
|
|
|
};
|
|
|
|
|
2020-03-13 05:34:19 +08:00
|
|
|
Reference<IssuesList> issues;
|
|
|
|
|
2017-05-26 04:48:44 +08:00
|
|
|
Reference<BarrierList> barriers;
|
|
|
|
|
2020-10-08 12:58:24 +08:00
|
|
|
struct WriterThread final : IThreadPoolReceiver {
|
2021-03-11 02:06:03 +08:00
|
|
|
WriterThread(Reference<BarrierList> barriers,
|
|
|
|
Reference<ITraceLogWriter> logWriter,
|
|
|
|
Reference<ITraceLogFormatter> formatter)
|
2021-07-25 02:20:51 +08:00
|
|
|
: logWriter(logWriter), formatter(formatter), barriers(barriers) {}
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2020-10-08 09:41:19 +08:00
|
|
|
void init() override {}
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2018-06-27 05:37:21 +08:00
|
|
|
Reference<ITraceLogWriter> logWriter;
|
|
|
|
Reference<ITraceLogFormatter> formatter;
|
2017-05-26 04:48:44 +08:00
|
|
|
Reference<BarrierList> barriers;
|
|
|
|
|
2020-10-08 12:58:24 +08:00
|
|
|
struct Open final : TypedAction<WriterThread, Open> {
|
2020-10-08 09:41:19 +08:00
|
|
|
double getTimeEstimate() const override { return 0; }
|
2017-05-26 04:48:44 +08:00
|
|
|
};
|
2021-03-11 02:06:03 +08:00
|
|
|
void action(Open& o) {
|
2018-06-01 04:27:35 +08:00
|
|
|
logWriter->open();
|
|
|
|
logWriter->write(formatter->getHeader());
|
2018-05-03 01:44:38 +08:00
|
|
|
}
|
|
|
|
|
2020-10-08 12:58:24 +08:00
|
|
|
struct Close final : TypedAction<WriterThread, Close> {
|
2020-10-08 09:41:19 +08:00
|
|
|
double getTimeEstimate() const override { return 0; }
|
2018-05-03 01:44:38 +08:00
|
|
|
};
|
2021-03-11 02:06:03 +08:00
|
|
|
void action(Close& c) {
|
2018-06-01 04:27:35 +08:00
|
|
|
logWriter->write(formatter->getFooter());
|
|
|
|
logWriter->close();
|
2018-05-03 01:44:38 +08:00
|
|
|
}
|
|
|
|
|
2020-10-08 12:58:24 +08:00
|
|
|
struct Roll final : TypedAction<WriterThread, Roll> {
|
2020-10-08 09:41:19 +08:00
|
|
|
double getTimeEstimate() const override { return 0; }
|
2018-06-01 04:27:35 +08:00
|
|
|
};
|
2021-03-11 02:06:03 +08:00
|
|
|
void action(Roll& c) {
|
2018-06-01 04:27:35 +08:00
|
|
|
logWriter->write(formatter->getFooter());
|
|
|
|
logWriter->roll();
|
|
|
|
logWriter->write(formatter->getHeader());
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2020-10-08 12:58:24 +08:00
|
|
|
struct Barrier final : TypedAction<WriterThread, Barrier> {
|
2020-10-08 09:41:19 +08:00
|
|
|
double getTimeEstimate() const override { return 0; }
|
2017-05-26 04:48:44 +08:00
|
|
|
};
|
2021-03-11 02:06:03 +08:00
|
|
|
void action(Barrier& a) { barriers->pop(); }
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2020-10-08 12:58:24 +08:00
|
|
|
struct WriteBuffer final : TypedAction<WriterThread, WriteBuffer> {
|
2018-06-01 04:27:35 +08:00
|
|
|
std::vector<TraceEventFields> events;
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2018-06-01 04:27:35 +08:00
|
|
|
WriteBuffer(std::vector<TraceEventFields> events) : events(events) {}
|
2020-10-08 09:41:19 +08:00
|
|
|
double getTimeEstimate() const override { return .001; }
|
2017-05-26 04:48:44 +08:00
|
|
|
};
|
2021-03-11 02:06:03 +08:00
|
|
|
void action(WriteBuffer& a) {
|
|
|
|
for (auto event : a.events) {
|
2018-06-09 04:24:30 +08:00
|
|
|
event.validateFormat();
|
2018-06-01 04:27:35 +08:00
|
|
|
logWriter->write(formatter->formatEvent(event));
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (FLOW_KNOBS->TRACE_SYNC_ENABLED) {
|
2018-06-01 04:27:35 +08:00
|
|
|
logWriter->sync();
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
}
|
2020-03-13 05:34:19 +08:00
|
|
|
|
2020-10-08 12:58:24 +08:00
|
|
|
struct Ping final : TypedAction<WriterThread, Ping> {
|
2020-03-17 04:36:55 +08:00
|
|
|
ThreadReturnPromise<Void> ack;
|
2020-03-13 05:34:19 +08:00
|
|
|
|
2020-03-17 04:36:55 +08:00
|
|
|
explicit Ping(){};
|
2020-10-08 09:41:19 +08:00
|
|
|
double getTimeEstimate() const override { return 0; }
|
2020-03-13 05:34:19 +08:00
|
|
|
};
|
2020-03-17 04:36:55 +08:00
|
|
|
void action(Ping& ping) {
|
2020-03-13 05:34:19 +08:00
|
|
|
try {
|
2020-03-17 04:36:55 +08:00
|
|
|
ping.ack.send(Void());
|
2020-03-13 05:34:19 +08:00
|
|
|
} catch (Error& e) {
|
2020-03-17 04:36:55 +08:00
|
|
|
TraceEvent(SevError, "CrashDebugPingActionFailed").error(e);
|
|
|
|
throw;
|
2020-03-13 05:34:19 +08:00
|
|
|
}
|
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
};
|
|
|
|
|
2020-01-30 13:42:30 +08:00
|
|
|
TraceLog()
|
2021-07-25 02:20:51 +08:00
|
|
|
: formatter(new XmlTraceLogFormatter()), loggedLength(0), bufferLength(0), opened(false), preopenOverflowCount(0),
|
|
|
|
logTraceEventMetrics(false), issues(new IssuesList), barriers(new BarrierList) {}
|
2017-05-26 04:48:44 +08:00
|
|
|
|
|
|
|
bool isOpen() const { return opened; }
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
void open(std::string const& directory,
|
|
|
|
std::string const& processName,
|
|
|
|
std::string logGroup,
|
|
|
|
std::string const& timestamp,
|
|
|
|
uint64_t rs,
|
|
|
|
uint64_t maxLogsSize,
|
2021-08-04 00:43:42 +08:00
|
|
|
Optional<NetworkAddress> na,
|
|
|
|
std::string const& tracePartialFileSuffix) {
|
2021-03-11 02:06:03 +08:00
|
|
|
ASSERT(!writer && !opened);
|
2017-05-26 04:48:44 +08:00
|
|
|
|
|
|
|
this->directory = directory;
|
|
|
|
this->processName = processName;
|
2018-06-29 06:28:58 +08:00
|
|
|
this->logGroup = logGroup;
|
2017-05-26 04:48:44 +08:00
|
|
|
this->localAddress = na;
|
2021-08-04 00:43:42 +08:00
|
|
|
this->tracePartialFileSuffix = tracePartialFileSuffix;
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
basename = format("%s/%s.%s.%s",
|
|
|
|
directory.c_str(),
|
|
|
|
processName.c_str(),
|
|
|
|
timestamp.c_str(),
|
|
|
|
deterministicRandom()->randomAlphaNumeric(6).c_str());
|
|
|
|
logWriter = Reference<ITraceLogWriter>(new FileTraceLogWriter(
|
|
|
|
directory,
|
|
|
|
processName,
|
|
|
|
basename,
|
|
|
|
formatter->getExtension(),
|
2021-08-04 00:43:42 +08:00
|
|
|
tracePartialFileSuffix,
|
2021-03-11 02:06:03 +08:00
|
|
|
maxLogsSize,
|
|
|
|
[this]() { barriers->triggerAll(); },
|
|
|
|
issues));
|
|
|
|
|
|
|
|
if (g_network->isSimulated())
|
2017-05-26 04:48:44 +08:00
|
|
|
writer = Reference<IThreadPool>(new DummyThreadPool());
|
|
|
|
else
|
|
|
|
writer = createGenericThreadPool();
|
2021-11-30 01:56:19 +08:00
|
|
|
writer->addThread(new WriterThread(barriers, logWriter, formatter), "fdb-trace-log");
|
2017-05-26 04:48:44 +08:00
|
|
|
|
|
|
|
rollsize = rs;
|
|
|
|
|
|
|
|
auto a = new WriterThread::Open;
|
|
|
|
writer->post(a);
|
|
|
|
|
2018-05-03 01:44:38 +08:00
|
|
|
MutexHolder holder(mutex);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (g_network->isSimulated()) {
|
2018-05-03 01:44:38 +08:00
|
|
|
// We don't support early trace logs in simulation.
|
2021-03-11 02:06:03 +08:00
|
|
|
// This is because we don't know if we're being simulated prior to the network being created, which causes
|
|
|
|
// two ambiguities:
|
2018-05-03 01:44:38 +08:00
|
|
|
//
|
2021-03-11 02:06:03 +08:00
|
|
|
// 1. We need to employ two different methods to determine the time of an event prior to the network
|
|
|
|
// starting for real-world and simulated runs.
|
|
|
|
// 2. Simulated runs manually insert the Machine field at TraceEvent creation time. Real-world runs add this
|
|
|
|
// field at write time.
|
2018-05-03 01:44:38 +08:00
|
|
|
//
|
2021-03-11 02:06:03 +08:00
|
|
|
// Without the ability to resolve the ambiguity, we've chosen to always favor the real-world approach and
|
|
|
|
// not support such events in simulation.
|
2018-06-01 04:27:35 +08:00
|
|
|
eventBuffer.clear();
|
2018-05-03 01:44:38 +08:00
|
|
|
}
|
|
|
|
|
2020-04-10 05:09:00 +08:00
|
|
|
opened = true;
|
2021-03-11 02:06:03 +08:00
|
|
|
for (TraceEventFields& fields : eventBuffer) {
|
2018-06-29 06:28:58 +08:00
|
|
|
annotateEvent(fields);
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (preopenOverflowCount > 0) {
|
2018-03-28 23:21:22 +08:00
|
|
|
TraceEvent(SevWarn, "TraceLogPreopenOverflow").detail("OverflowEventCount", preopenOverflowCount);
|
|
|
|
preopenOverflowCount = 0;
|
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2020-04-02 11:38:48 +08:00
|
|
|
void annotateEvent(TraceEventFields& fields) {
|
2020-04-11 04:03:15 +08:00
|
|
|
MutexHolder holder(mutex);
|
2020-04-10 05:09:00 +08:00
|
|
|
if (!opened || fields.isAnnotated())
|
|
|
|
return;
|
2021-03-11 02:06:03 +08:00
|
|
|
if (localAddress.present()) {
|
2019-02-28 18:37:21 +08:00
|
|
|
fields.addField("Machine", formatIpPort(localAddress.get().ip, localAddress.get().port));
|
2018-05-03 01:44:38 +08:00
|
|
|
}
|
2018-06-09 04:24:30 +08:00
|
|
|
fields.addField("LogGroup", logGroup);
|
2018-09-06 06:06:14 +08:00
|
|
|
|
|
|
|
RoleInfo const& r = mutateRoleInfo();
|
2021-03-11 02:06:03 +08:00
|
|
|
if (r.rolesString.size() > 0) {
|
2018-09-06 06:06:14 +08:00
|
|
|
fields.addField("Roles", r.rolesString);
|
|
|
|
}
|
2021-12-11 07:03:14 +08:00
|
|
|
|
2022-01-05 01:16:26 +08:00
|
|
|
for (auto const& field : universalFields) {
|
2021-12-11 07:03:14 +08:00
|
|
|
fields.addField(field.first, field.second);
|
|
|
|
}
|
|
|
|
|
2020-04-10 05:09:00 +08:00
|
|
|
fields.setAnnotated();
|
2018-06-29 06:28:58 +08:00
|
|
|
}
|
|
|
|
|
2020-04-10 05:09:00 +08:00
|
|
|
void writeEvent(TraceEventFields fields, std::string trackLatestKey, bool trackError) {
|
2018-06-29 06:28:58 +08:00
|
|
|
MutexHolder hold(mutex);
|
|
|
|
|
2020-04-10 05:09:00 +08:00
|
|
|
annotateEvent(fields);
|
2018-05-12 02:24:20 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (!trackLatestKey.empty()) {
|
2018-05-03 01:44:38 +08:00
|
|
|
fields.addField("TrackLatestType", "Original");
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (!isOpen() &&
|
|
|
|
(preopenOverflowCount > 0 || bufferLength + fields.sizeBytes() > TRACE_LOG_MAX_PREOPEN_BUFFER)) {
|
2018-03-28 23:21:22 +08:00
|
|
|
++preopenOverflowCount;
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
2017-05-26 04:48:44 +08:00
|
|
|
// FIXME: What if we are using way too much memory for buffer?
|
2020-04-10 05:09:00 +08:00
|
|
|
ASSERT(!isOpen() || fields.isAnnotated());
|
2018-06-01 04:27:35 +08:00
|
|
|
eventBuffer.push_back(fields);
|
|
|
|
bufferLength += fields.sizeBytes();
|
2018-05-03 01:44:38 +08:00
|
|
|
|
2021-09-25 02:44:10 +08:00
|
|
|
// If we have queued up a large number of events in simulation, then throw an error. This makes it easier to
|
|
|
|
// diagnose cases where we get stuck in a loop logging trace events that eventually runs out of memory.
|
|
|
|
// Without this we would never see any trace events from that loop, and it would be more difficult to identify
|
|
|
|
// where the process is actually stuck.
|
2021-09-25 01:59:24 +08:00
|
|
|
if (g_network && g_network->isSimulated() && bufferLength > 1e8) {
|
2022-03-02 01:04:15 +08:00
|
|
|
fprintf(stderr, "Trace log buffer overflow\n");
|
|
|
|
fprintf(stderr, "Last event: %s\n", fields.toString().c_str());
|
2021-09-25 01:59:24 +08:00
|
|
|
// Setting this to 0 avoids a recurse from the assertion trace event and also prevents a situation where
|
|
|
|
// we roll the trace log only to log the single assertion event when using --crash.
|
|
|
|
bufferLength = 0;
|
|
|
|
ASSERT(false);
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (trackError) {
|
2018-05-03 01:44:38 +08:00
|
|
|
latestEventCache.setLatestError(fields);
|
|
|
|
}
|
2021-03-11 02:06:03 +08:00
|
|
|
if (!trackLatestKey.empty()) {
|
2018-05-03 01:44:38 +08:00
|
|
|
latestEventCache.set(trackLatestKey, fields);
|
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
void log(int severity, const char* name, UID id, uint64_t event_ts) {
|
|
|
|
if (!logTraceEventMetrics)
|
2017-05-26 04:48:44 +08:00
|
|
|
return;
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
EventMetricHandle<TraceEventNameID>* m = nullptr;
|
|
|
|
switch (severity) {
|
|
|
|
case SevError:
|
|
|
|
m = &SevErrorNames;
|
|
|
|
break;
|
|
|
|
case SevWarnAlways:
|
|
|
|
m = &SevWarnAlwaysNames;
|
|
|
|
break;
|
|
|
|
case SevWarn:
|
|
|
|
m = &SevWarnNames;
|
|
|
|
break;
|
|
|
|
case SevInfo:
|
|
|
|
m = &SevInfoNames;
|
|
|
|
break;
|
|
|
|
case SevDebug:
|
|
|
|
m = &SevDebugNames;
|
|
|
|
break;
|
|
|
|
default:
|
2017-05-26 04:48:44 +08:00
|
|
|
break;
|
|
|
|
}
|
2021-03-11 02:06:03 +08:00
|
|
|
if (m != nullptr) {
|
2017-05-26 04:48:44 +08:00
|
|
|
(*m)->name = StringRef((uint8_t*)name, strlen(name));
|
|
|
|
(*m)->id = id.toString();
|
|
|
|
(*m)->log(event_ts);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
ThreadFuture<Void> flush() {
|
2017-11-01 01:35:26 +08:00
|
|
|
traceEventThrottlerCache->poll();
|
2017-10-03 09:43:11 +08:00
|
|
|
|
2017-05-26 04:48:44 +08:00
|
|
|
MutexHolder hold(mutex);
|
|
|
|
bool roll = false;
|
2021-03-11 02:06:03 +08:00
|
|
|
if (!eventBuffer.size())
|
|
|
|
return Void(); // SOMEDAY: maybe we still roll the tracefile here?
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2018-06-01 04:27:35 +08:00
|
|
|
if (rollsize && bufferLength + loggedLength > rollsize) // SOMEDAY: more conditions to roll
|
2017-05-26 04:48:44 +08:00
|
|
|
roll = true;
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
auto a = new WriterThread::WriteBuffer(std::move(eventBuffer));
|
2018-06-01 04:27:35 +08:00
|
|
|
loggedLength += bufferLength;
|
|
|
|
eventBuffer = std::vector<TraceEventFields>();
|
|
|
|
bufferLength = 0;
|
2021-03-11 02:06:03 +08:00
|
|
|
writer->post(a);
|
2017-05-26 04:48:44 +08:00
|
|
|
|
|
|
|
if (roll) {
|
2018-06-01 04:27:35 +08:00
|
|
|
auto o = new WriterThread::Roll;
|
2020-10-22 08:57:27 +08:00
|
|
|
double time = 0;
|
2018-06-01 04:27:35 +08:00
|
|
|
writer->post(o);
|
|
|
|
|
2018-05-03 01:44:38 +08:00
|
|
|
std::vector<TraceEventFields> events = latestEventCache.getAllUnsafe();
|
2017-05-26 04:48:44 +08:00
|
|
|
for (int idx = 0; idx < events.size(); idx++) {
|
2021-03-11 02:06:03 +08:00
|
|
|
if (events[idx].size() > 0) {
|
2018-05-12 02:24:20 +08:00
|
|
|
TraceEventFields rolledFields;
|
2021-03-11 02:06:03 +08:00
|
|
|
for (auto itr = events[idx].begin(); itr != events[idx].end(); ++itr) {
|
|
|
|
if (itr->first == "Time") {
|
2020-10-22 08:57:27 +08:00
|
|
|
time = TraceEvent::getCurrentTime();
|
|
|
|
rolledFields.addField("Time", format("%.6f", time));
|
2018-05-12 02:24:20 +08:00
|
|
|
rolledFields.addField("OriginalTime", itr->second);
|
2021-03-11 02:06:03 +08:00
|
|
|
} else if (itr->first == "DateTime") {
|
2020-10-22 08:57:27 +08:00
|
|
|
UNSTOPPABLE_ASSERT(time > 0); // "Time" field should always come first
|
|
|
|
rolledFields.addField("DateTime", TraceEvent::printRealTime(time));
|
|
|
|
rolledFields.addField("OriginalDateTime", itr->second);
|
2021-03-11 02:06:03 +08:00
|
|
|
} else if (itr->first == "TrackLatestType") {
|
2018-05-12 02:24:20 +08:00
|
|
|
rolledFields.addField("TrackLatestType", "Rolled");
|
2021-03-11 02:06:03 +08:00
|
|
|
} else {
|
2018-05-12 02:24:20 +08:00
|
|
|
rolledFields.addField(itr->first, itr->second);
|
2018-05-03 01:44:38 +08:00
|
|
|
}
|
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2018-06-01 04:27:35 +08:00
|
|
|
eventBuffer.push_back(rolledFields);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2018-06-01 04:27:35 +08:00
|
|
|
loggedLength = 0;
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
ThreadFuture<Void> f(new ThreadSingleAssignmentVar<Void>);
|
|
|
|
barriers->push(f);
|
2021-03-11 02:06:03 +08:00
|
|
|
writer->post(new WriterThread::Barrier);
|
2017-05-26 04:48:44 +08:00
|
|
|
|
|
|
|
return f;
|
|
|
|
}
|
|
|
|
|
|
|
|
void close() {
|
|
|
|
if (opened) {
|
2018-05-03 01:44:38 +08:00
|
|
|
MutexHolder hold(mutex);
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2018-05-03 01:44:38 +08:00
|
|
|
// Write remaining contents
|
2021-03-11 02:06:03 +08:00
|
|
|
auto a = new WriterThread::WriteBuffer(std::move(eventBuffer));
|
2018-06-01 04:27:35 +08:00
|
|
|
loggedLength += bufferLength;
|
|
|
|
eventBuffer = std::vector<TraceEventFields>();
|
|
|
|
bufferLength = 0;
|
2021-03-11 02:06:03 +08:00
|
|
|
writer->post(a);
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2018-05-03 01:44:38 +08:00
|
|
|
auto c = new WriterThread::Close();
|
2021-03-11 02:06:03 +08:00
|
|
|
writer->post(c);
|
2018-05-03 01:44:38 +08:00
|
|
|
|
|
|
|
ThreadFuture<Void> f(new ThreadSingleAssignmentVar<Void>);
|
|
|
|
barriers->push(f);
|
2021-03-11 02:06:03 +08:00
|
|
|
writer->post(new WriterThread::Barrier);
|
2018-05-03 01:44:38 +08:00
|
|
|
|
|
|
|
f.getBlocking();
|
2017-05-26 04:48:44 +08:00
|
|
|
|
|
|
|
opened = false;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2021-06-10 02:37:14 +08:00
|
|
|
void addRole(std::string const& role) {
|
2018-09-06 06:06:14 +08:00
|
|
|
MutexHolder holder(mutex);
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
RoleInfo& r = mutateRoleInfo();
|
2018-09-06 06:06:14 +08:00
|
|
|
++r.roles[role];
|
|
|
|
r.refreshRolesString();
|
|
|
|
}
|
|
|
|
|
2021-06-10 02:37:14 +08:00
|
|
|
void removeRole(std::string const& role) {
|
2018-09-06 06:06:14 +08:00
|
|
|
MutexHolder holder(mutex);
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
RoleInfo& r = mutateRoleInfo();
|
2018-09-06 06:06:14 +08:00
|
|
|
|
|
|
|
auto itr = r.roles.find(role);
|
2018-09-06 06:53:12 +08:00
|
|
|
ASSERT(itr != r.roles.end() || (g_network->isSimulated() && g_network->getLocalAddress() == NetworkAddress()));
|
2018-09-06 06:06:14 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (itr != r.roles.end() && --(*itr).second == 0) {
|
2018-09-06 06:53:12 +08:00
|
|
|
r.roles.erase(itr);
|
2018-09-06 06:06:14 +08:00
|
|
|
r.refreshRolesString();
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2020-03-27 00:55:03 +08:00
|
|
|
void setLogGroup(const std::string& logGroup) {
|
|
|
|
MutexHolder holder(mutex);
|
|
|
|
this->logGroup = logGroup;
|
|
|
|
}
|
2020-03-26 04:27:56 +08:00
|
|
|
|
2021-12-11 07:03:14 +08:00
|
|
|
void addUniversalTraceField(const std::string& name, const std::string& value) {
|
|
|
|
MutexHolder holder(mutex);
|
|
|
|
ASSERT(universalFields.count(name) == 0);
|
|
|
|
universalFields[name] = value;
|
|
|
|
}
|
|
|
|
|
2020-03-17 04:36:55 +08:00
|
|
|
Future<Void> pingWriterThread() {
|
|
|
|
auto ping = new WriterThread::Ping;
|
|
|
|
auto f = ping->ack.getFuture();
|
2020-03-18 02:03:46 +08:00
|
|
|
writer->post(ping);
|
2020-03-17 04:36:55 +08:00
|
|
|
return f;
|
2020-03-13 05:34:19 +08:00
|
|
|
}
|
|
|
|
|
2020-11-05 14:39:56 +08:00
|
|
|
void retrieveTraceLogIssues(std::set<std::string>& out) { return issues->retrieveIssues(out); }
|
2020-03-13 05:34:19 +08:00
|
|
|
|
2017-05-26 04:48:44 +08:00
|
|
|
~TraceLog() {
|
|
|
|
close();
|
2021-03-11 02:06:03 +08:00
|
|
|
if (writer)
|
|
|
|
writer->addref(); // FIXME: We are not shutting down the writer thread at all, because the ThreadPool
|
|
|
|
// shutdown mechanism is blocking (necessarily waits for current work items to finish) and
|
|
|
|
// we might not be able to finish everything.
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
};
|
|
|
|
|
|
|
|
NetworkAddress getAddressIndex() {
|
2021-03-11 02:06:03 +08:00
|
|
|
// ahm
|
|
|
|
// if( g_network->isSimulated() )
|
|
|
|
// return g_simulator.getCurrentProcess()->address;
|
|
|
|
// else
|
2017-05-26 04:48:44 +08:00
|
|
|
return g_network->getLocalAddress();
|
|
|
|
}
|
|
|
|
|
|
|
|
// This does not check for simulation, and as such is not safe for external callers
|
2021-06-10 02:37:14 +08:00
|
|
|
void clearPrefix_internal(std::map<std::string, TraceEventFields>& data, std::string const& prefix) {
|
2021-03-11 02:06:03 +08:00
|
|
|
auto first = data.lower_bound(prefix);
|
|
|
|
auto last = data.lower_bound(strinc(prefix).toString());
|
|
|
|
data.erase(first, last);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2021-06-10 02:37:14 +08:00
|
|
|
void LatestEventCache::clear(std::string const& prefix) {
|
2021-03-11 02:06:03 +08:00
|
|
|
clearPrefix_internal(latest[getAddressIndex()], prefix);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
void LatestEventCache::clear() {
|
|
|
|
latest[getAddressIndex()].clear();
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
void LatestEventCache::set(std::string tag, const TraceEventFields& contents) {
|
2017-05-26 04:48:44 +08:00
|
|
|
latest[getAddressIndex()][tag] = contents;
|
|
|
|
}
|
|
|
|
|
2021-06-10 02:37:14 +08:00
|
|
|
TraceEventFields LatestEventCache::get(std::string const& tag) {
|
2017-05-26 04:48:44 +08:00
|
|
|
return latest[getAddressIndex()][tag];
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
std::vector<TraceEventFields> allEvents(std::map<std::string, TraceEventFields> const& data) {
|
2018-05-03 01:44:38 +08:00
|
|
|
std::vector<TraceEventFields> all;
|
2021-03-11 02:06:03 +08:00
|
|
|
for (auto it = data.begin(); it != data.end(); it++) {
|
|
|
|
all.push_back(it->second);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
return all;
|
|
|
|
}
|
|
|
|
|
2018-05-03 01:44:38 +08:00
|
|
|
std::vector<TraceEventFields> LatestEventCache::getAll() {
|
2021-03-11 02:06:03 +08:00
|
|
|
return allEvents(latest[getAddressIndex()]);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
// if in simulation, all events from all machines will be returned
|
2018-05-03 01:44:38 +08:00
|
|
|
std::vector<TraceEventFields> LatestEventCache::getAllUnsafe() {
|
|
|
|
std::vector<TraceEventFields> all;
|
2021-03-11 02:06:03 +08:00
|
|
|
for (auto it = latest.begin(); it != latest.end(); ++it) {
|
|
|
|
auto m = allEvents(it->second);
|
|
|
|
all.insert(all.end(), m.begin(), m.end());
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
return all;
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
void LatestEventCache::setLatestError(const TraceEventFields& contents) {
|
|
|
|
if (TraceEvent::isNetworkThread()) { // The latest event cache doesn't track errors that happen on other threads
|
2017-05-26 04:48:44 +08:00
|
|
|
latestErrors[getAddressIndex()] = contents;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2018-05-03 01:44:38 +08:00
|
|
|
TraceEventFields LatestEventCache::getLatestError() {
|
2017-05-26 04:48:44 +08:00
|
|
|
return latestErrors[getAddressIndex()];
|
|
|
|
}
|
|
|
|
|
2019-01-03 08:42:00 +08:00
|
|
|
static TraceLog g_traceLog;
|
2018-12-21 05:51:06 +08:00
|
|
|
|
2019-01-30 05:08:47 +08:00
|
|
|
namespace {
|
|
|
|
template <bool validate>
|
|
|
|
bool traceFormatImpl(std::string& format) {
|
2018-12-21 05:51:06 +08:00
|
|
|
std::transform(format.begin(), format.end(), format.begin(), ::tolower);
|
2019-01-30 05:08:47 +08:00
|
|
|
if (format == "xml") {
|
|
|
|
if (!validate) {
|
|
|
|
g_traceLog.formatter = Reference<ITraceLogFormatter>(new XmlTraceLogFormatter());
|
|
|
|
}
|
|
|
|
return true;
|
|
|
|
} else if (format == "json") {
|
|
|
|
if (!validate) {
|
|
|
|
g_traceLog.formatter = Reference<ITraceLogFormatter>(new JsonTraceLogFormatter());
|
|
|
|
}
|
2018-12-21 05:51:06 +08:00
|
|
|
return true;
|
|
|
|
} else {
|
2019-01-30 05:08:47 +08:00
|
|
|
if (!validate) {
|
|
|
|
g_traceLog.formatter = Reference<ITraceLogFormatter>(new XmlTraceLogFormatter());
|
|
|
|
}
|
2018-12-21 05:51:06 +08:00
|
|
|
return false;
|
|
|
|
}
|
|
|
|
}
|
2019-11-07 06:31:13 +08:00
|
|
|
|
|
|
|
template <bool validate>
|
|
|
|
bool traceClockSource(std::string& source) {
|
|
|
|
std::transform(source.begin(), source.end(), source.begin(), ::tolower);
|
|
|
|
if (source == "now") {
|
|
|
|
if (!validate) {
|
|
|
|
g_trace_clock.store(TRACE_CLOCK_NOW);
|
|
|
|
}
|
|
|
|
return true;
|
|
|
|
} else if (source == "realtime") {
|
|
|
|
if (!validate) {
|
|
|
|
g_trace_clock.store(TRACE_CLOCK_REALTIME);
|
|
|
|
}
|
|
|
|
return true;
|
|
|
|
} else {
|
|
|
|
return false;
|
|
|
|
}
|
|
|
|
}
|
2021-05-03 23:09:52 +08:00
|
|
|
|
|
|
|
std::string toString(ErrorKind errorKind) {
|
|
|
|
switch (errorKind) {
|
2021-08-28 08:07:47 +08:00
|
|
|
case ErrorKind::Unset:
|
|
|
|
return "Unset";
|
|
|
|
case ErrorKind::DiskIssue:
|
|
|
|
return "DiskIssue";
|
|
|
|
case ErrorKind::BugDetected:
|
|
|
|
return "BugDetected";
|
|
|
|
default:
|
|
|
|
UNSTOPPABLE_ASSERT(false);
|
|
|
|
return "";
|
2021-05-03 23:09:52 +08:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2019-01-30 05:08:47 +08:00
|
|
|
} // namespace
|
|
|
|
|
|
|
|
bool selectTraceFormatter(std::string format) {
|
|
|
|
ASSERT(!g_traceLog.isOpen());
|
|
|
|
bool recognized = traceFormatImpl</*validate*/ false>(format);
|
|
|
|
if (!recognized) {
|
|
|
|
TraceEvent(SevWarnAlways, "UnrecognizedTraceFormat").detail("format", format);
|
|
|
|
}
|
|
|
|
return recognized;
|
|
|
|
}
|
|
|
|
|
|
|
|
bool validateTraceFormat(std::string format) {
|
|
|
|
return traceFormatImpl</*validate*/ true>(format);
|
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2019-11-07 06:31:13 +08:00
|
|
|
bool selectTraceClockSource(std::string source) {
|
|
|
|
ASSERT(!g_traceLog.isOpen());
|
|
|
|
bool recognized = traceClockSource</*validate*/ false>(source);
|
|
|
|
if (!recognized) {
|
|
|
|
TraceEvent(SevWarnAlways, "UnrecognizedTraceClockSource").detail("source", source);
|
|
|
|
}
|
|
|
|
return recognized;
|
|
|
|
}
|
|
|
|
|
|
|
|
bool validateTraceClockSource(std::string source) {
|
|
|
|
return traceClockSource</*validate*/ true>(source);
|
|
|
|
}
|
|
|
|
|
2017-05-26 04:48:44 +08:00
|
|
|
ThreadFuture<Void> flushTraceFile() {
|
2019-01-03 08:42:00 +08:00
|
|
|
if (!g_traceLog.isOpen())
|
2017-05-26 04:48:44 +08:00
|
|
|
return Void();
|
2019-01-03 08:42:00 +08:00
|
|
|
return g_traceLog.flush();
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
void flushTraceFileVoid() {
|
2021-03-11 02:06:03 +08:00
|
|
|
if (g_network && g_network->isSimulated())
|
2017-05-26 04:48:44 +08:00
|
|
|
flushTraceFile();
|
|
|
|
else {
|
|
|
|
flushTraceFile().getBlocking();
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
void openTraceFile(const NetworkAddress& na,
|
|
|
|
uint64_t rollsize,
|
|
|
|
uint64_t maxLogsSize,
|
|
|
|
std::string directory,
|
|
|
|
std::string baseOfBase,
|
|
|
|
std::string logGroup,
|
2021-08-04 00:43:42 +08:00
|
|
|
std::string identifier,
|
|
|
|
std::string tracePartialFileSuffix) {
|
2021-03-11 02:06:03 +08:00
|
|
|
if (g_traceLog.isOpen())
|
2017-05-26 04:48:44 +08:00
|
|
|
return;
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (directory.empty())
|
2017-05-26 04:48:44 +08:00
|
|
|
directory = ".";
|
|
|
|
|
|
|
|
if (baseOfBase.empty())
|
|
|
|
baseOfBase = "trace";
|
|
|
|
|
2019-03-21 04:57:26 +08:00
|
|
|
std::string ip = na.ip.toString();
|
|
|
|
std::replace(ip.begin(), ip.end(), ':', '_'); // For IPv6, Windows doesn't accept ':' in filenames.
|
2020-03-27 02:24:53 +08:00
|
|
|
std::string baseName;
|
|
|
|
if (identifier.size() > 0) {
|
2020-04-01 02:02:02 +08:00
|
|
|
baseName = format("%s.%s.%s", baseOfBase.c_str(), ip.c_str(), identifier.c_str());
|
2020-03-27 02:24:53 +08:00
|
|
|
} else {
|
|
|
|
baseName = format("%s.%s.%d", baseOfBase.c_str(), ip.c_str(), na.port);
|
|
|
|
}
|
2021-03-11 02:06:03 +08:00
|
|
|
g_traceLog.open(directory,
|
|
|
|
baseName,
|
|
|
|
logGroup,
|
|
|
|
format("%lld", time(nullptr)),
|
|
|
|
rollsize,
|
|
|
|
maxLogsSize,
|
2021-08-04 00:43:42 +08:00
|
|
|
!g_network->isSimulated() ? na : Optional<NetworkAddress>(),
|
|
|
|
tracePartialFileSuffix);
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2019-06-25 17:47:35 +08:00
|
|
|
uncancellable(recurring(&flushTraceFile, FLOW_KNOBS->TRACE_FLUSH_INTERVAL, TaskPriority::FlushTrace));
|
2017-05-26 04:48:44 +08:00
|
|
|
g_traceBatch.dump();
|
|
|
|
}
|
|
|
|
|
|
|
|
void initTraceEventMetrics() {
|
2019-01-03 08:42:00 +08:00
|
|
|
g_traceLog.initMetrics();
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
void closeTraceFile() {
|
2019-01-03 08:42:00 +08:00
|
|
|
g_traceLog.close();
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
bool traceFileIsOpen() {
|
2019-01-03 08:42:00 +08:00
|
|
|
return g_traceLog.isOpen();
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2021-06-10 02:37:14 +08:00
|
|
|
void addTraceRole(std::string const& role) {
|
2019-01-03 08:42:00 +08:00
|
|
|
g_traceLog.addRole(role);
|
2018-09-06 06:06:14 +08:00
|
|
|
}
|
|
|
|
|
2021-06-10 02:37:14 +08:00
|
|
|
void removeTraceRole(std::string const& role) {
|
2019-01-03 08:42:00 +08:00
|
|
|
g_traceLog.removeRole(role);
|
2018-09-06 06:06:14 +08:00
|
|
|
}
|
|
|
|
|
2020-03-26 04:27:56 +08:00
|
|
|
void setTraceLogGroup(const std::string& logGroup) {
|
|
|
|
g_traceLog.setLogGroup(logGroup);
|
|
|
|
}
|
|
|
|
|
2021-12-11 07:03:14 +08:00
|
|
|
void addUniversalTraceField(const std::string& name, const std::string& value) {
|
|
|
|
g_traceLog.addUniversalTraceField(name, value);
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent::BaseTraceEvent() : initialized(true), enabled(false), logged(true) {}
|
|
|
|
BaseTraceEvent::BaseTraceEvent(Severity severity, const char* type, UID id)
|
|
|
|
: initialized(false), enabled(g_network == nullptr || FLOW_KNOBS->MIN_TRACE_SEVERITY <= severity), logged(false),
|
|
|
|
severity(severity), type(type), id(id) {}
|
2020-02-22 02:55:14 +08:00
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent::BaseTraceEvent(BaseTraceEvent&& ev) {
|
2020-02-22 02:55:14 +08:00
|
|
|
enabled = ev.enabled;
|
|
|
|
err = ev.err;
|
|
|
|
fields = std::move(ev.fields);
|
|
|
|
id = ev.id;
|
|
|
|
initialized = ev.initialized;
|
|
|
|
logged = ev.logged;
|
|
|
|
maxEventLength = ev.maxEventLength;
|
|
|
|
maxFieldLength = ev.maxFieldLength;
|
|
|
|
severity = ev.severity;
|
2020-11-27 15:24:47 +08:00
|
|
|
tmpEventMetric = std::move(ev.tmpEventMetric);
|
2020-02-22 02:55:14 +08:00
|
|
|
trackingKey = ev.trackingKey;
|
|
|
|
type = ev.type;
|
Clean up and rework the debugMutation API.
As a relatively unknown debugging tool for simulation tests, one could
have simulation print when a particular key is handled in various stages
of the commit process. This functionality was enabled by changing a 0
to a 1 in an #if, and changing a constant to the key in question.
As a proxy and storage server handle mutations, they call debugMutation
or debugKeyRange, which then checks against the mutation against the key
in question, and logs if they match. A mixture of printfs and
TraceEvents would then be emitted, and for this to actually be usable,
one also needs to comment out some particularly spammy debugKeyRange()
calls.
This PR reworks the API of debugMutation/debugKeyRange, pulls it out
into its own file, and trims what is logged by default into something
useful and understandable:
* debugMutation() now returns a TraceEvent, that one can add more details to before it is logged.
* Data distribution and storage server cleanup operations are no longer logged by default
2020-03-27 16:35:26 +08:00
|
|
|
timeIndex = ev.timeIndex;
|
2020-02-22 02:55:14 +08:00
|
|
|
|
2020-11-02 04:15:39 +08:00
|
|
|
for (int i = 0; i < 5; i++) {
|
|
|
|
eventCounts[i] = ev.eventCounts[i];
|
|
|
|
}
|
|
|
|
|
|
|
|
networkThread = ev.networkThread;
|
2020-02-22 02:55:14 +08:00
|
|
|
|
|
|
|
ev.initialized = true;
|
|
|
|
ev.enabled = false;
|
|
|
|
ev.logged = true;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& BaseTraceEvent::operator=(BaseTraceEvent&& ev) {
|
2020-11-02 04:15:39 +08:00
|
|
|
// Note: still broken if ev and this are the same memory address.
|
2020-02-22 02:55:14 +08:00
|
|
|
enabled = ev.enabled;
|
|
|
|
err = ev.err;
|
|
|
|
fields = std::move(ev.fields);
|
|
|
|
id = ev.id;
|
|
|
|
initialized = ev.initialized;
|
|
|
|
logged = ev.logged;
|
|
|
|
maxEventLength = ev.maxEventLength;
|
|
|
|
maxFieldLength = ev.maxFieldLength;
|
|
|
|
severity = ev.severity;
|
2020-11-27 15:24:47 +08:00
|
|
|
tmpEventMetric = std::move(ev.tmpEventMetric);
|
2020-02-22 02:55:14 +08:00
|
|
|
trackingKey = ev.trackingKey;
|
|
|
|
type = ev.type;
|
Clean up and rework the debugMutation API.
As a relatively unknown debugging tool for simulation tests, one could
have simulation print when a particular key is handled in various stages
of the commit process. This functionality was enabled by changing a 0
to a 1 in an #if, and changing a constant to the key in question.
As a proxy and storage server handle mutations, they call debugMutation
or debugKeyRange, which then checks against the mutation against the key
in question, and logs if they match. A mixture of printfs and
TraceEvents would then be emitted, and for this to actually be usable,
one also needs to comment out some particularly spammy debugKeyRange()
calls.
This PR reworks the API of debugMutation/debugKeyRange, pulls it out
into its own file, and trims what is logged by default into something
useful and understandable:
* debugMutation() now returns a TraceEvent, that one can add more details to before it is logged.
* Data distribution and storage server cleanup operations are no longer logged by default
2020-03-27 16:35:26 +08:00
|
|
|
timeIndex = ev.timeIndex;
|
2020-02-22 02:55:14 +08:00
|
|
|
|
2020-11-02 04:15:39 +08:00
|
|
|
for (int i = 0; i < 5; i++) {
|
|
|
|
eventCounts[i] = ev.eventCounts[i];
|
|
|
|
}
|
|
|
|
|
|
|
|
networkThread = ev.networkThread;
|
2020-02-22 02:55:14 +08:00
|
|
|
|
|
|
|
ev.initialized = true;
|
|
|
|
ev.enabled = false;
|
|
|
|
ev.logged = true;
|
|
|
|
|
|
|
|
return *this;
|
|
|
|
}
|
2020-01-30 13:42:30 +08:00
|
|
|
|
2020-11-05 14:39:56 +08:00
|
|
|
void retrieveTraceLogIssues(std::set<std::string>& out) {
|
|
|
|
return g_traceLog.retrieveTraceLogIssues(out);
|
2020-03-13 05:34:19 +08:00
|
|
|
}
|
|
|
|
|
2020-03-17 04:36:55 +08:00
|
|
|
Future<Void> pingTraceLogWriterThread() {
|
|
|
|
return g_traceLog.pingWriterThread();
|
2020-03-13 05:34:19 +08:00
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
TraceEvent::TraceEvent(const char* type, UID id) : BaseTraceEvent(SevInfo, type, id) {
|
2019-07-13 07:12:35 +08:00
|
|
|
setMaxFieldLength(0);
|
|
|
|
setMaxEventLength(0);
|
2019-05-07 08:41:32 +08:00
|
|
|
}
|
2022-02-25 04:25:52 +08:00
|
|
|
TraceEvent::TraceEvent(Severity severity, const char* type, UID id) : BaseTraceEvent(severity, type, id) {
|
2019-07-13 07:12:35 +08:00
|
|
|
setMaxFieldLength(0);
|
|
|
|
setMaxEventLength(0);
|
2019-05-07 08:41:32 +08:00
|
|
|
}
|
2022-02-25 04:25:52 +08:00
|
|
|
TraceEvent::TraceEvent(TraceInterval& interval, UID id) : BaseTraceEvent(interval.severity, interval.type, id) {
|
2019-07-13 07:12:35 +08:00
|
|
|
setMaxFieldLength(0);
|
|
|
|
setMaxEventLength(0);
|
|
|
|
|
2018-08-02 05:30:57 +08:00
|
|
|
init(interval);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
2021-03-11 02:06:03 +08:00
|
|
|
TraceEvent::TraceEvent(Severity severity, TraceInterval& interval, UID id)
|
2022-02-25 04:25:52 +08:00
|
|
|
: BaseTraceEvent(severity, interval.type, id) {
|
2019-07-13 07:12:35 +08:00
|
|
|
setMaxFieldLength(0);
|
|
|
|
setMaxEventLength(0);
|
|
|
|
|
2018-08-02 05:30:57 +08:00
|
|
|
init(interval);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
bool BaseTraceEvent::init(TraceInterval& interval) {
|
2018-08-02 05:30:57 +08:00
|
|
|
bool result = init();
|
2017-05-26 04:48:44 +08:00
|
|
|
switch (interval.count++) {
|
2021-03-11 02:06:03 +08:00
|
|
|
case 0: {
|
|
|
|
detail("BeginPair", interval.pairID);
|
|
|
|
break;
|
|
|
|
}
|
|
|
|
case 1: {
|
|
|
|
detail("EndPair", interval.pairID);
|
|
|
|
break;
|
|
|
|
}
|
|
|
|
default:
|
|
|
|
ASSERT(false);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
return result;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
bool BaseTraceEvent::init() {
|
2020-01-04 04:31:06 +08:00
|
|
|
ASSERT(!logged);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (initialized) {
|
2018-08-02 05:30:57 +08:00
|
|
|
return enabled;
|
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2018-08-02 05:30:57 +08:00
|
|
|
initialized = true;
|
|
|
|
ASSERT(*type != '\0');
|
2020-03-17 05:11:07 +08:00
|
|
|
|
|
|
|
++g_allocation_tracing_disabled;
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
enabled = enabled && (!g_network || severity >= FLOW_KNOBS->MIN_TRACE_SEVERITY);
|
2018-06-28 06:51:30 +08:00
|
|
|
|
|
|
|
// Backstop to throttle very spammy trace events
|
|
|
|
if (enabled && g_network && !g_network->isSimulated() && severity > SevDebug && isNetworkThread()) {
|
|
|
|
if (traceEventThrottlerCache->isAboveThreshold(StringRef((uint8_t*)type, strlen(type)))) {
|
|
|
|
enabled = false;
|
2021-03-11 02:06:03 +08:00
|
|
|
TraceEvent(SevWarnAlways, std::string(TRACE_EVENT_THROTTLE_STARTING_TYPE).append(type).c_str())
|
|
|
|
.suppressFor(5);
|
|
|
|
} else {
|
|
|
|
traceEventThrottlerCache->addAndExpire(
|
|
|
|
StringRef((uint8_t*)type, strlen(type)), 1, now() + FLOW_KNOBS->TRACE_EVENT_THROTTLER_SAMPLE_EXPIRY);
|
2018-06-28 06:51:30 +08:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (enabled) {
|
2020-11-27 15:24:47 +08:00
|
|
|
tmpEventMetric = std::make_unique<DynamicEventMetric>(MetricNameRef());
|
2018-03-28 23:21:22 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (err.isValid() && err.isInjectedFault() && severity == SevError) {
|
2018-08-02 05:30:57 +08:00
|
|
|
severity = SevWarnAlways;
|
|
|
|
}
|
|
|
|
|
2019-03-15 09:40:28 +08:00
|
|
|
detail("Severity", int(severity));
|
2021-05-03 23:09:52 +08:00
|
|
|
if (severity >= SevError) {
|
|
|
|
detail("ErrorKind", errorKind);
|
2021-08-28 08:07:47 +08:00
|
|
|
errorKindIndex = fields.size() - 1;
|
2021-05-03 23:09:52 +08:00
|
|
|
}
|
2020-02-22 05:57:04 +08:00
|
|
|
detail("Time", "0.000000");
|
2020-02-22 02:55:14 +08:00
|
|
|
timeIndex = fields.size() - 1;
|
2021-02-11 09:13:19 +08:00
|
|
|
if (FLOW_KNOBS && FLOW_KNOBS->TRACE_DATETIME_ENABLED) {
|
2020-10-22 08:57:27 +08:00
|
|
|
detail("DateTime", "");
|
|
|
|
}
|
2020-02-22 02:55:14 +08:00
|
|
|
|
2018-05-03 01:44:38 +08:00
|
|
|
detail("Type", type);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (g_network && g_network->isSimulated()) {
|
2018-05-03 01:44:38 +08:00
|
|
|
NetworkAddress local = g_network->getLocalAddress();
|
2019-02-28 18:37:21 +08:00
|
|
|
detail("Machine", formatIpPort(local.ip, local.port));
|
2018-05-03 01:44:38 +08:00
|
|
|
}
|
2018-08-02 05:30:57 +08:00
|
|
|
detail("ID", id);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (err.isValid()) {
|
2018-08-02 05:30:57 +08:00
|
|
|
if (err.isInjectedFault()) {
|
|
|
|
detail("ErrorIsInjectedFault", true);
|
|
|
|
}
|
|
|
|
detail("Error", err.name());
|
|
|
|
detail("ErrorDescription", err.what());
|
|
|
|
detail("ErrorCode", err.code());
|
|
|
|
}
|
2018-06-28 06:51:30 +08:00
|
|
|
} else {
|
|
|
|
tmpEventMetric = nullptr;
|
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2020-03-17 04:59:31 +08:00
|
|
|
--g_allocation_tracing_disabled;
|
2017-05-26 04:48:44 +08:00
|
|
|
return enabled;
|
|
|
|
}
|
|
|
|
|
2019-03-15 09:40:28 +08:00
|
|
|
TraceEvent& TraceEvent::errorImpl(class Error const& error, bool includeCancelled) {
|
2020-01-04 04:31:06 +08:00
|
|
|
ASSERT(!logged);
|
2019-03-15 09:40:28 +08:00
|
|
|
if (error.code() != error_code_actor_cancelled || includeCancelled) {
|
|
|
|
err = error;
|
|
|
|
if (initialized) {
|
|
|
|
if (error.isInjectedFault()) {
|
|
|
|
detail("ErrorIsInjectedFault", true);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (severity == SevError)
|
|
|
|
severity = SevWarnAlways;
|
2018-08-02 05:30:57 +08:00
|
|
|
}
|
2019-03-15 09:40:28 +08:00
|
|
|
detail("Error", error.name());
|
|
|
|
detail("ErrorDescription", error.what());
|
|
|
|
detail("ErrorCode", error.code());
|
|
|
|
}
|
2021-05-03 23:09:52 +08:00
|
|
|
if (err.isDiskError()) {
|
|
|
|
setErrorKind(ErrorKind::DiskIssue);
|
|
|
|
}
|
2019-03-15 09:40:28 +08:00
|
|
|
} else {
|
|
|
|
if (initialized) {
|
2021-03-11 02:06:03 +08:00
|
|
|
TraceEvent(g_network && g_network->isSimulated() ? SevError : SevWarnAlways,
|
|
|
|
std::string(TRACE_EVENT_INVALID_SUPPRESSION).append(type).c_str())
|
|
|
|
.suppressFor(5);
|
2017-05-26 04:48:44 +08:00
|
|
|
} else {
|
2019-03-15 09:40:28 +08:00
|
|
|
enabled = false;
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
}
|
|
|
|
return *this;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& BaseTraceEvent::detailImpl(std::string&& key, std::string&& value, bool writeEventMetricField) {
|
2018-08-02 05:30:57 +08:00
|
|
|
init();
|
2017-05-26 04:48:44 +08:00
|
|
|
if (enabled) {
|
2020-03-17 04:59:31 +08:00
|
|
|
++g_allocation_tracing_disabled;
|
2021-03-11 02:06:03 +08:00
|
|
|
if (maxFieldLength >= 0 && value.size() > maxFieldLength) {
|
2019-07-13 07:12:35 +08:00
|
|
|
value = value.substr(0, maxFieldLength) + "...";
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
2018-07-02 02:30:37 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (writeEventMetricField) {
|
2018-06-27 05:37:21 +08:00
|
|
|
tmpEventMetric->setField(key.c_str(), Standalone<StringRef>(StringRef(value)));
|
|
|
|
}
|
2018-05-03 01:44:38 +08:00
|
|
|
|
2018-06-27 05:37:21 +08:00
|
|
|
fields.addField(std::move(key), std::move(value));
|
2018-05-05 04:35:25 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (maxEventLength >= 0 && fields.sizeBytes() > maxEventLength) {
|
|
|
|
TraceEvent(g_network && g_network->isSimulated() ? SevError : SevWarnAlways, "TraceEventOverflow")
|
|
|
|
.setMaxEventLength(1000)
|
2022-03-05 04:23:16 +08:00
|
|
|
.detail("TraceFirstBytes", fields.toString().substr(0, 300));
|
2018-05-05 06:19:56 +08:00
|
|
|
enabled = false;
|
|
|
|
}
|
2020-03-17 04:59:31 +08:00
|
|
|
--g_allocation_tracing_disabled;
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
return *this;
|
|
|
|
}
|
2018-05-05 04:35:25 +08:00
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
void BaseTraceEvent::setField(const char* key, int64_t value) {
|
2020-03-17 04:59:31 +08:00
|
|
|
++g_allocation_tracing_disabled;
|
2019-03-15 09:40:28 +08:00
|
|
|
tmpEventMetric->setField(key, value);
|
2020-03-17 04:59:31 +08:00
|
|
|
--g_allocation_tracing_disabled;
|
2018-05-05 04:35:25 +08:00
|
|
|
}
|
2019-03-15 09:40:28 +08:00
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
void BaseTraceEvent::setField(const char* key, double value) {
|
2020-03-17 04:59:31 +08:00
|
|
|
++g_allocation_tracing_disabled;
|
2019-03-15 09:40:28 +08:00
|
|
|
tmpEventMetric->setField(key, value);
|
2020-03-17 04:59:31 +08:00
|
|
|
--g_allocation_tracing_disabled;
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
2019-03-15 09:40:28 +08:00
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
void BaseTraceEvent::setField(const char* key, const std::string& value) {
|
2020-03-17 04:59:31 +08:00
|
|
|
++g_allocation_tracing_disabled;
|
2019-03-15 09:40:28 +08:00
|
|
|
tmpEventMetric->setField(key, Standalone<StringRef>(value));
|
2020-03-17 04:59:31 +08:00
|
|
|
--g_allocation_tracing_disabled;
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
2019-03-15 09:40:28 +08:00
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& BaseTraceEvent::detailf(std::string key, const char* valueFormat, ...) {
|
2017-05-26 04:48:44 +08:00
|
|
|
if (enabled) {
|
|
|
|
va_list args;
|
|
|
|
va_start(args, valueFormat);
|
2018-05-05 04:35:25 +08:00
|
|
|
std::string value;
|
|
|
|
int result = vsformat(value, valueFormat, args);
|
2017-05-26 04:48:44 +08:00
|
|
|
va_end(args);
|
2018-05-05 04:35:25 +08:00
|
|
|
|
|
|
|
ASSERT(result >= 0);
|
2018-06-27 05:37:21 +08:00
|
|
|
detailImpl(std::move(key), std::move(value));
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
return *this;
|
|
|
|
}
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& BaseTraceEvent::detailfNoMetric(std::string&& key, const char* valueFormat, ...) {
|
2017-05-26 04:48:44 +08:00
|
|
|
if (enabled) {
|
|
|
|
va_list args;
|
|
|
|
va_start(args, valueFormat);
|
2018-05-05 04:35:25 +08:00
|
|
|
std::string value;
|
|
|
|
int result = vsformat(value, valueFormat, args);
|
2017-05-26 04:48:44 +08:00
|
|
|
va_end(args);
|
2018-05-05 04:35:25 +08:00
|
|
|
|
|
|
|
ASSERT(result >= 0);
|
2021-03-11 02:06:03 +08:00
|
|
|
detailImpl(std::move(key),
|
|
|
|
std::move(value),
|
|
|
|
false); // Do NOT write this detail to the event metric, caller of detailfNoMetric should do that
|
|
|
|
// itself with the appropriate value type
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
return *this;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& BaseTraceEvent::trackLatest(const std::string& trackingKey) {
|
2020-01-04 04:31:06 +08:00
|
|
|
ASSERT(!logged);
|
2017-05-26 04:48:44 +08:00
|
|
|
this->trackingKey = trackingKey;
|
2021-03-11 02:06:03 +08:00
|
|
|
ASSERT(this->trackingKey.size() != 0 && this->trackingKey[0] != '/' && this->trackingKey[0] != '\\');
|
2017-05-26 04:48:44 +08:00
|
|
|
return *this;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& TraceEvent::sample(double sampleRate, bool logSampleRate) {
|
2021-03-11 02:06:03 +08:00
|
|
|
if (enabled) {
|
|
|
|
if (initialized) {
|
|
|
|
TraceEvent(g_network && g_network->isSimulated() ? SevError : SevWarnAlways,
|
|
|
|
std::string(TRACE_EVENT_INVALID_SUPPRESSION).append(type).c_str())
|
|
|
|
.suppressFor(5);
|
2018-08-02 05:30:57 +08:00
|
|
|
return *this;
|
|
|
|
}
|
|
|
|
|
2019-05-11 05:01:52 +08:00
|
|
|
enabled = enabled && deterministicRandom()->random01() < sampleRate;
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (enabled && logSampleRate) {
|
2018-08-02 05:30:57 +08:00
|
|
|
detail("SampleRate", sampleRate);
|
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
return *this;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& TraceEvent::suppressFor(double duration, bool logSuppressedEventCount) {
|
2020-01-04 04:31:06 +08:00
|
|
|
ASSERT(!logged);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (enabled) {
|
|
|
|
if (initialized) {
|
|
|
|
TraceEvent(g_network && g_network->isSimulated() ? SevError : SevWarnAlways,
|
|
|
|
std::string(TRACE_EVENT_INVALID_SUPPRESSION).append(type).c_str())
|
|
|
|
.suppressFor(5);
|
2018-08-02 05:30:57 +08:00
|
|
|
return *this;
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
2018-08-02 05:30:57 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (g_network) {
|
|
|
|
if (isNetworkThread()) {
|
2018-08-02 05:30:57 +08:00
|
|
|
int64_t suppressedEventCount = suppressedEvents.checkAndInsertSuppression(type, duration);
|
|
|
|
enabled = enabled && suppressedEventCount >= 0;
|
2021-03-11 02:06:03 +08:00
|
|
|
if (enabled && logSuppressedEventCount) {
|
2018-08-02 05:30:57 +08:00
|
|
|
detail("SuppressedEventCount", suppressedEventCount);
|
|
|
|
}
|
2021-03-11 02:06:03 +08:00
|
|
|
} else {
|
2020-05-08 02:22:32 +08:00
|
|
|
TraceEvent(SevWarnAlways, "SuppressionFromNonNetworkThread").detail("Event", type);
|
2022-02-25 04:25:52 +08:00
|
|
|
// Choosing a detail name that is unlikely to collide with other names
|
|
|
|
detail("__InvalidSuppression__", "");
|
2018-08-02 05:30:57 +08:00
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
2022-02-25 04:25:52 +08:00
|
|
|
|
|
|
|
// we do not want any future calls on this trace event to disable it, because we have already counted it
|
|
|
|
// towards our suppression budget
|
|
|
|
init();
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
return *this;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& BaseTraceEvent::setErrorKind(ErrorKind errorKind) {
|
2021-05-04 01:59:44 +08:00
|
|
|
this->errorKind = errorKind;
|
|
|
|
return *this;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& BaseTraceEvent::setMaxFieldLength(int maxFieldLength) {
|
2020-01-04 04:31:06 +08:00
|
|
|
ASSERT(!logged);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (maxFieldLength == 0) {
|
2019-07-13 07:12:35 +08:00
|
|
|
this->maxFieldLength = FLOW_KNOBS ? FLOW_KNOBS->MAX_TRACE_FIELD_LENGTH : 495;
|
2021-03-11 02:06:03 +08:00
|
|
|
} else {
|
2019-07-13 07:12:35 +08:00
|
|
|
this->maxFieldLength = maxFieldLength;
|
|
|
|
}
|
|
|
|
|
|
|
|
return *this;
|
|
|
|
}
|
|
|
|
|
2021-07-01 03:45:50 +08:00
|
|
|
// A unique, per-thread ID. This is particularly important for multithreaded
|
|
|
|
// or multiversion client setups and for multithreaded storage engines.
|
|
|
|
thread_local uint64_t threadId = 0;
|
|
|
|
|
2021-12-11 07:03:14 +08:00
|
|
|
uint64_t getTraceThreadId() {
|
2021-07-01 03:45:50 +08:00
|
|
|
while (threadId == 0) {
|
|
|
|
threadId = deterministicRandom()->randomUInt64();
|
|
|
|
}
|
2021-12-11 07:03:14 +08:00
|
|
|
|
|
|
|
return threadId;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
void BaseTraceEvent::setThreadId() {
|
2021-12-11 07:03:14 +08:00
|
|
|
this->detail("ThreadID", getTraceThreadId());
|
2021-07-01 03:45:50 +08:00
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
int BaseTraceEvent::getMaxFieldLength() const {
|
2021-01-29 17:31:26 +08:00
|
|
|
return maxFieldLength;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& BaseTraceEvent::setMaxEventLength(int maxEventLength) {
|
2020-01-04 04:31:06 +08:00
|
|
|
ASSERT(!logged);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (maxEventLength == 0) {
|
2019-07-13 07:12:35 +08:00
|
|
|
this->maxEventLength = FLOW_KNOBS ? FLOW_KNOBS->MAX_TRACE_EVENT_LENGTH : 4000;
|
2021-03-11 02:06:03 +08:00
|
|
|
} else {
|
2019-07-13 07:12:35 +08:00
|
|
|
this->maxEventLength = maxEventLength;
|
|
|
|
}
|
|
|
|
|
|
|
|
return *this;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
int BaseTraceEvent::getMaxEventLength() const {
|
2021-01-29 17:31:26 +08:00
|
|
|
return maxEventLength;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& BaseTraceEvent::GetLastError() {
|
2017-05-26 04:48:44 +08:00
|
|
|
#ifdef _WIN32
|
|
|
|
return detailf("WinErrorCode", "%x", ::GetLastError());
|
|
|
|
#elif defined(__unixish__)
|
|
|
|
return detailf("UnixErrorCode", "%x", errno).detail("UnixError", strerror(errno));
|
|
|
|
#endif
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
unsigned long BaseTraceEvent::eventCounts[NUM_MAJOR_LEVELS_OF_EVENTS] = { 0, 0, 0, 0, 0 };
|
2017-12-16 10:20:33 +08:00
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
unsigned long BaseTraceEvent::CountEventsLoggedAt(Severity sev) {
|
2020-11-02 14:13:24 +08:00
|
|
|
ASSERT(sev <= SevMaxUsed);
|
2021-03-11 02:06:03 +08:00
|
|
|
return TraceEvent::eventCounts[sev / 10];
|
2017-12-16 10:20:33 +08:00
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent& BaseTraceEvent::backtrace(const std::string& prefix) {
|
2020-01-04 04:31:06 +08:00
|
|
|
ASSERT(!logged);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (this->severity == SevError || !enabled)
|
|
|
|
return *this; // We'll backtrace this later in ~TraceEvent
|
2018-06-27 05:37:21 +08:00
|
|
|
return detail(prefix + "Backtrace", platform::get_backtrace());
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
void BaseTraceEvent::log() {
|
2021-03-11 02:06:03 +08:00
|
|
|
if (!logged) {
|
2020-01-04 04:15:38 +08:00
|
|
|
init();
|
2020-03-17 04:59:31 +08:00
|
|
|
++g_allocation_tracing_disabled;
|
2020-01-04 04:15:38 +08:00
|
|
|
try {
|
|
|
|
if (enabled) {
|
2020-10-22 08:57:27 +08:00
|
|
|
double time = TraceEvent::getCurrentTime();
|
|
|
|
fields.mutate(timeIndex).second = format("%.6f", time);
|
2021-02-11 09:13:19 +08:00
|
|
|
if (FLOW_KNOBS && FLOW_KNOBS->TRACE_DATETIME_ENABLED) {
|
2020-10-22 08:57:27 +08:00
|
|
|
fields.mutate(timeIndex + 1).second = TraceEvent::printRealTime(time);
|
|
|
|
}
|
2020-02-22 05:57:04 +08:00
|
|
|
|
2021-07-01 03:45:50 +08:00
|
|
|
setThreadId();
|
|
|
|
|
2020-01-04 04:15:38 +08:00
|
|
|
if (this->severity == SevError) {
|
|
|
|
severity = SevInfo;
|
|
|
|
backtrace();
|
|
|
|
severity = SevError;
|
2021-05-03 23:09:52 +08:00
|
|
|
if (errorKindIndex != -1) {
|
|
|
|
fields.mutate(errorKindIndex).second = toString(errorKind);
|
|
|
|
}
|
2020-01-04 04:15:38 +08:00
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
if (isNetworkThread()) {
|
|
|
|
TraceEvent::eventCounts[severity / 10]++;
|
2020-01-04 04:15:38 +08:00
|
|
|
}
|
2019-05-11 04:15:06 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
g_traceLog.writeEvent(fields, trackingKey, severity > SevWarnAlways);
|
2018-03-28 23:21:22 +08:00
|
|
|
|
2020-01-04 04:15:38 +08:00
|
|
|
if (g_traceLog.isOpen()) {
|
|
|
|
// Log Metrics
|
2021-03-11 02:06:03 +08:00
|
|
|
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.get());
|
2020-01-04 04:15:38 +08:00
|
|
|
g_traceLog.log(severity, type, id, event_ts);
|
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
}
|
2021-03-11 02:06:03 +08:00
|
|
|
} catch (Error& e) {
|
2022-02-25 04:25:52 +08:00
|
|
|
TraceEvent(SevError, "TraceEventLoggingError").errorUnsuppressed(e);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
2020-11-27 15:24:47 +08:00
|
|
|
tmpEventMetric.reset();
|
2020-01-04 04:45:23 +08:00
|
|
|
logged = true;
|
2020-03-17 04:59:31 +08:00
|
|
|
--g_allocation_tracing_disabled;
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
2020-01-04 04:15:38 +08:00
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
BaseTraceEvent::~BaseTraceEvent() {
|
2020-01-04 04:15:38 +08:00
|
|
|
log();
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
thread_local bool BaseTraceEvent::networkThread = false;
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
void BaseTraceEvent::setNetworkThread() {
|
2021-03-11 02:06:03 +08:00
|
|
|
if (!networkThread) {
|
|
|
|
if (FLOW_KNOBS->ALLOCATION_TRACING_ENABLED) {
|
2020-03-17 06:37:06 +08:00
|
|
|
--g_allocation_tracing_disabled;
|
|
|
|
}
|
2020-03-17 04:59:31 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
traceEventThrottlerCache = new TransientThresholdMetricSample<Standalone<StringRef>>(
|
|
|
|
FLOW_KNOBS->TRACE_EVENT_METRIC_UNITS_PER_SAMPLE, FLOW_KNOBS->TRACE_EVENT_THROTTLER_MSG_LIMIT);
|
2020-03-17 06:37:06 +08:00
|
|
|
networkThread = true;
|
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
bool BaseTraceEvent::isNetworkThread() {
|
2017-05-26 04:48:44 +08:00
|
|
|
return networkThread;
|
|
|
|
}
|
|
|
|
|
2022-02-25 04:25:52 +08:00
|
|
|
double BaseTraceEvent::getCurrentTime() {
|
2021-03-11 02:06:03 +08:00
|
|
|
if (g_trace_clock.load() == TRACE_CLOCK_NOW) {
|
|
|
|
if (!isNetworkThread() || !g_network) {
|
2019-12-07 02:15:49 +08:00
|
|
|
return timer_monotonic();
|
2021-03-11 02:06:03 +08:00
|
|
|
} else {
|
2019-12-07 02:15:49 +08:00
|
|
|
return now();
|
|
|
|
}
|
2021-03-11 02:06:03 +08:00
|
|
|
} else {
|
2019-12-07 02:15:49 +08:00
|
|
|
return timer();
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2020-11-19 08:45:37 +08:00
|
|
|
// 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.
|
2022-02-25 04:25:52 +08:00
|
|
|
std::string BaseTraceEvent::printRealTime(double time) {
|
2020-11-19 08:45:37 +08:00
|
|
|
using Clock = std::chrono::system_clock;
|
|
|
|
time_t ts = Clock::to_time_t(Clock::time_point(
|
|
|
|
std::chrono::duration_cast<Clock::duration>(std::chrono::duration<double, std::ratio<1>>(time))));
|
|
|
|
if (g_network && g_network->isSimulated()) {
|
|
|
|
// The clock is simulated, so return the real time
|
|
|
|
ts = Clock::to_time_t(Clock::now());
|
2020-10-22 08:57:27 +08:00
|
|
|
}
|
2020-11-19 08:45:37 +08:00
|
|
|
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();
|
2020-10-22 08:57:27 +08:00
|
|
|
}
|
|
|
|
|
2017-05-26 04:48:44 +08:00
|
|
|
TraceInterval& TraceInterval::begin() {
|
2019-05-11 05:01:52 +08:00
|
|
|
pairID = nondeterministicRandom()->randomUniqueID();
|
2017-05-26 04:48:44 +08:00
|
|
|
count = 0;
|
|
|
|
return *this;
|
|
|
|
}
|
|
|
|
|
2020-04-02 11:38:48 +08:00
|
|
|
bool TraceBatch::dumpImmediately() {
|
|
|
|
return (g_network->isSimulated() || FLOW_KNOBS->AUTOMATIC_TRACE_DUMP);
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
void TraceBatch::addEvent(const char* name, uint64_t id, const char* location) {
|
|
|
|
if (FLOW_KNOBS->MIN_TRACE_SEVERITY > TRACE_BATCH_IMPLICIT_SEVERITY) {
|
2020-10-12 21:57:57 +08:00
|
|
|
return;
|
|
|
|
}
|
2020-04-02 11:38:48 +08:00
|
|
|
auto& eventInfo = eventBatch.emplace_back(EventInfo(TraceEvent::getCurrentTime(), name, id, location));
|
|
|
|
if (dumpImmediately())
|
2017-05-26 04:48:44 +08:00
|
|
|
dump();
|
2020-04-02 11:38:48 +08:00
|
|
|
else
|
|
|
|
g_traceLog.annotateEvent(eventInfo.fields);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
void TraceBatch::addAttach(const char* name, uint64_t id, uint64_t to) {
|
|
|
|
if (FLOW_KNOBS->MIN_TRACE_SEVERITY > TRACE_BATCH_IMPLICIT_SEVERITY) {
|
2020-10-12 21:57:57 +08:00
|
|
|
return;
|
|
|
|
}
|
2020-04-02 11:38:48 +08:00
|
|
|
auto& attachInfo = attachBatch.emplace_back(AttachInfo(TraceEvent::getCurrentTime(), name, id, to));
|
|
|
|
if (dumpImmediately())
|
2017-05-26 04:48:44 +08:00
|
|
|
dump();
|
2020-04-02 11:38:48 +08:00
|
|
|
else
|
|
|
|
g_traceLog.annotateEvent(attachInfo.fields);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
void TraceBatch::addBuggify(int activated, int line, std::string file) {
|
|
|
|
if (FLOW_KNOBS->MIN_TRACE_SEVERITY > TRACE_BATCH_IMPLICIT_SEVERITY) {
|
2020-10-12 21:57:57 +08:00
|
|
|
return;
|
|
|
|
}
|
2021-03-11 02:06:03 +08:00
|
|
|
if (g_network) {
|
2020-04-02 11:38:48 +08:00
|
|
|
auto& buggifyInfo = buggifyBatch.emplace_back(BuggifyInfo(TraceEvent::getCurrentTime(), activated, line, file));
|
|
|
|
if (dumpImmediately())
|
2017-05-26 04:48:44 +08:00
|
|
|
dump();
|
2020-04-02 11:38:48 +08:00
|
|
|
else
|
|
|
|
g_traceLog.annotateEvent(buggifyInfo.fields);
|
2017-05-26 04:48:44 +08:00
|
|
|
} else {
|
2020-04-02 11:38:48 +08:00
|
|
|
buggifyBatch.push_back(BuggifyInfo(0, activated, line, file));
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
void TraceBatch::dump() {
|
2020-10-12 21:57:57 +08:00
|
|
|
if (!g_traceLog.isOpen() || FLOW_KNOBS->MIN_TRACE_SEVERITY > TRACE_BATCH_IMPLICIT_SEVERITY)
|
2017-05-26 04:48:44 +08:00
|
|
|
return;
|
2018-05-03 01:44:38 +08:00
|
|
|
std::string machine;
|
2021-03-11 02:06:03 +08:00
|
|
|
if (g_network->isSimulated()) {
|
2018-05-03 01:44:38 +08:00
|
|
|
NetworkAddress local = g_network->getLocalAddress();
|
2019-02-28 18:37:21 +08:00
|
|
|
machine = formatIpPort(local.ip, local.port);
|
2018-05-03 01:44:38 +08:00
|
|
|
}
|
2017-05-26 04:48:44 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
for (int i = 0; i < attachBatch.size(); i++) {
|
|
|
|
if (g_network->isSimulated()) {
|
2018-05-03 01:44:38 +08:00
|
|
|
attachBatch[i].fields.addField("Machine", machine);
|
|
|
|
}
|
2019-01-03 08:42:00 +08:00
|
|
|
g_traceLog.writeEvent(attachBatch[i].fields, "", false);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
for (int i = 0; i < eventBatch.size(); i++) {
|
|
|
|
if (g_network->isSimulated()) {
|
2018-05-03 01:44:38 +08:00
|
|
|
eventBatch[i].fields.addField("Machine", machine);
|
|
|
|
}
|
2019-01-03 08:42:00 +08:00
|
|
|
g_traceLog.writeEvent(eventBatch[i].fields, "", false);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
for (int i = 0; i < buggifyBatch.size(); i++) {
|
|
|
|
if (g_network->isSimulated()) {
|
2018-05-03 01:44:38 +08:00
|
|
|
buggifyBatch[i].fields.addField("Machine", machine);
|
|
|
|
}
|
2019-01-03 08:42:00 +08:00
|
|
|
g_traceLog.writeEvent(buggifyBatch[i].fields, "", false);
|
2017-05-26 04:48:44 +08:00
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
onMainThreadVoid([]() { g_traceLog.flush(); }, nullptr);
|
2017-05-26 04:48:44 +08:00
|
|
|
eventBatch.clear();
|
|
|
|
attachBatch.clear();
|
|
|
|
buggifyBatch.clear();
|
|
|
|
}
|
2018-05-03 01:44:38 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
TraceBatch::EventInfo::EventInfo(double time, const char* name, uint64_t id, const char* location) {
|
2020-10-12 21:57:57 +08:00
|
|
|
fields.addField("Severity", format("%d", (int)TRACE_BATCH_IMPLICIT_SEVERITY));
|
2018-05-03 01:44:38 +08:00
|
|
|
fields.addField("Time", format("%.6f", time));
|
2021-02-11 09:13:19 +08:00
|
|
|
if (FLOW_KNOBS && FLOW_KNOBS->TRACE_DATETIME_ENABLED) {
|
2020-10-22 08:57:27 +08:00
|
|
|
fields.addField("DateTime", TraceEvent::printRealTime(time));
|
|
|
|
}
|
2018-05-03 01:44:38 +08:00
|
|
|
fields.addField("Type", name);
|
|
|
|
fields.addField("ID", format("%016" PRIx64, id));
|
|
|
|
fields.addField("Location", location);
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
TraceBatch::AttachInfo::AttachInfo(double time, const char* name, uint64_t id, uint64_t to) {
|
2020-10-12 21:57:57 +08:00
|
|
|
fields.addField("Severity", format("%d", (int)TRACE_BATCH_IMPLICIT_SEVERITY));
|
2018-05-03 01:44:38 +08:00
|
|
|
fields.addField("Time", format("%.6f", time));
|
2021-02-11 09:13:19 +08:00
|
|
|
if (FLOW_KNOBS && FLOW_KNOBS->TRACE_DATETIME_ENABLED) {
|
2020-10-22 08:57:27 +08:00
|
|
|
fields.addField("DateTime", TraceEvent::printRealTime(time));
|
|
|
|
}
|
2018-05-03 01:44:38 +08:00
|
|
|
fields.addField("Type", name);
|
|
|
|
fields.addField("ID", format("%016" PRIx64, id));
|
|
|
|
fields.addField("To", format("%016" PRIx64, to));
|
|
|
|
}
|
|
|
|
|
|
|
|
TraceBatch::BuggifyInfo::BuggifyInfo(double time, int activated, int line, std::string file) {
|
2020-10-12 21:57:57 +08:00
|
|
|
fields.addField("Severity", format("%d", (int)TRACE_BATCH_IMPLICIT_SEVERITY));
|
2018-05-03 01:44:38 +08:00
|
|
|
fields.addField("Time", format("%.6f", time));
|
2021-02-11 09:13:19 +08:00
|
|
|
if (FLOW_KNOBS && FLOW_KNOBS->TRACE_DATETIME_ENABLED) {
|
2020-10-22 08:57:27 +08:00
|
|
|
fields.addField("DateTime", TraceEvent::printRealTime(time));
|
|
|
|
}
|
2018-05-03 01:44:38 +08:00
|
|
|
fields.addField("Type", "BuggifySection");
|
|
|
|
fields.addField("Activated", format("%d", activated));
|
2018-06-27 05:37:21 +08:00
|
|
|
fields.addField("File", std::move(file));
|
2018-05-03 01:44:38 +08:00
|
|
|
fields.addField("Line", format("%d", line));
|
|
|
|
}
|
|
|
|
|
2020-04-10 05:09:00 +08:00
|
|
|
TraceEventFields::TraceEventFields() : bytes(0), annotated(false) {}
|
2018-06-01 04:27:35 +08:00
|
|
|
|
2018-06-27 05:37:21 +08:00
|
|
|
void TraceEventFields::addField(const std::string& key, const std::string& value) {
|
2018-06-01 04:27:35 +08:00
|
|
|
bytes += key.size() + value.size();
|
2021-05-03 23:09:52 +08:00
|
|
|
fields.emplace_back(key, value);
|
2018-05-03 01:44:38 +08:00
|
|
|
}
|
|
|
|
|
2018-06-27 05:37:21 +08:00
|
|
|
void TraceEventFields::addField(std::string&& key, std::string&& value) {
|
|
|
|
bytes += key.size() + value.size();
|
2021-05-03 23:09:52 +08:00
|
|
|
fields.emplace_back(std::move(key), std::move(value));
|
2018-06-27 05:37:21 +08:00
|
|
|
}
|
|
|
|
|
2018-05-03 01:44:38 +08:00
|
|
|
size_t TraceEventFields::size() const {
|
|
|
|
return fields.size();
|
2018-06-01 04:27:35 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
size_t TraceEventFields::sizeBytes() const {
|
|
|
|
return bytes;
|
2018-05-03 01:44:38 +08:00
|
|
|
}
|
|
|
|
|
|
|
|
TraceEventFields::FieldIterator TraceEventFields::begin() const {
|
|
|
|
return fields.cbegin();
|
|
|
|
}
|
|
|
|
|
|
|
|
TraceEventFields::FieldIterator TraceEventFields::end() const {
|
|
|
|
return fields.cend();
|
|
|
|
}
|
|
|
|
|
2020-04-10 05:09:00 +08:00
|
|
|
bool TraceEventFields::isAnnotated() const {
|
|
|
|
return annotated;
|
|
|
|
}
|
|
|
|
|
|
|
|
void TraceEventFields::setAnnotated() {
|
|
|
|
annotated = true;
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
const TraceEventFields::Field& TraceEventFields::operator[](int index) const {
|
2018-05-03 01:44:38 +08:00
|
|
|
ASSERT(index >= 0 && index < size());
|
|
|
|
return fields.at(index);
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
bool TraceEventFields::tryGetValue(std::string key, std::string& outValue) const {
|
|
|
|
for (auto itr = begin(); itr != end(); ++itr) {
|
|
|
|
if (itr->first == key) {
|
2018-05-03 01:44:38 +08:00
|
|
|
outValue = itr->second;
|
|
|
|
return true;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
return false;
|
|
|
|
}
|
|
|
|
|
|
|
|
std::string TraceEventFields::getValue(std::string key) const {
|
|
|
|
std::string value;
|
2021-03-11 02:06:03 +08:00
|
|
|
if (tryGetValue(key, value)) {
|
2018-05-03 01:44:38 +08:00
|
|
|
return value;
|
2021-03-11 02:06:03 +08:00
|
|
|
} else {
|
2019-03-01 01:53:16 +08:00
|
|
|
TraceEvent ev(SevWarn, "TraceEventFieldNotFound");
|
2019-05-21 06:12:28 +08:00
|
|
|
ev.suppressFor(1.0);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (tryGetValue("Type", value)) {
|
2019-03-01 01:53:16 +08:00
|
|
|
ev.detail("Event", value);
|
|
|
|
}
|
|
|
|
ev.detail("FieldName", key);
|
|
|
|
|
2018-05-03 01:44:38 +08:00
|
|
|
throw attribute_not_found();
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2020-02-22 02:55:14 +08:00
|
|
|
TraceEventFields::Field& TraceEventFields::mutate(int index) {
|
|
|
|
return fields.at(index);
|
|
|
|
}
|
|
|
|
|
2019-03-01 01:53:16 +08:00
|
|
|
namespace {
|
2021-03-11 02:06:03 +08:00
|
|
|
void parseNumericValue(std::string const& s, double& outValue, bool permissive = false) {
|
2019-03-01 01:53:16 +08:00
|
|
|
double d = 0;
|
|
|
|
int consumed = 0;
|
|
|
|
int r = sscanf(s.c_str(), "%lf%n", &d, &consumed);
|
|
|
|
if (r == 1 && (consumed == s.size() || permissive)) {
|
|
|
|
outValue = d;
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
|
|
|
throw attribute_not_found();
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
void parseNumericValue(std::string const& s, int& outValue, bool permissive = false) {
|
2019-03-01 01:53:16 +08:00
|
|
|
long long int iLong = 0;
|
|
|
|
int consumed = 0;
|
|
|
|
int r = sscanf(s.c_str(), "%lld%n", &iLong, &consumed);
|
|
|
|
if (r == 1 && (consumed == s.size() || permissive)) {
|
|
|
|
if (std::numeric_limits<int>::min() <= iLong && iLong <= std::numeric_limits<int>::max()) {
|
2021-03-11 02:06:03 +08:00
|
|
|
outValue = (int)iLong; // Downcast definitely safe
|
2019-03-01 01:53:16 +08:00
|
|
|
return;
|
2021-03-11 02:06:03 +08:00
|
|
|
} else {
|
2019-03-01 01:53:16 +08:00
|
|
|
throw attribute_too_large();
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
throw attribute_not_found();
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
void parseNumericValue(std::string const& s, int64_t& outValue, bool permissive = false) {
|
2019-03-01 01:53:16 +08:00
|
|
|
long long int i = 0;
|
|
|
|
int consumed = 0;
|
|
|
|
int r = sscanf(s.c_str(), "%lld%n", &i, &consumed);
|
|
|
|
if (r == 1 && (consumed == s.size() || permissive)) {
|
|
|
|
outValue = i;
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
|
|
|
throw attribute_not_found();
|
|
|
|
}
|
|
|
|
|
2022-02-05 07:04:30 +08:00
|
|
|
void parseNumericValue(std::string const& s, uint64_t& outValue, bool permissive = false) {
|
|
|
|
unsigned long long int i = 0;
|
|
|
|
int consumed = 0;
|
|
|
|
int r = sscanf(s.c_str(), "%llu%n", &i, &consumed);
|
|
|
|
if (r == 1 && (consumed == s.size() || permissive)) {
|
|
|
|
outValue = i;
|
|
|
|
return;
|
|
|
|
}
|
|
|
|
|
|
|
|
throw attribute_not_found();
|
|
|
|
}
|
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
template <class T>
|
2019-03-01 01:53:16 +08:00
|
|
|
T getNumericValue(TraceEventFields const& fields, std::string key, bool permissive) {
|
|
|
|
std::string field = fields.getValue(key);
|
|
|
|
|
|
|
|
try {
|
|
|
|
T value;
|
|
|
|
parseNumericValue(field, value, permissive);
|
|
|
|
return value;
|
2021-03-11 02:06:03 +08:00
|
|
|
} catch (Error& e) {
|
2019-03-01 01:53:16 +08:00
|
|
|
std::string type;
|
|
|
|
|
|
|
|
TraceEvent ev(SevWarn, "ErrorParsingNumericTraceEventField");
|
2019-03-02 06:06:47 +08:00
|
|
|
ev.error(e);
|
2021-03-11 02:06:03 +08:00
|
|
|
if (fields.tryGetValue("Type", type)) {
|
2019-03-01 01:53:16 +08:00
|
|
|
ev.detail("Event", type);
|
|
|
|
}
|
|
|
|
ev.detail("FieldName", key);
|
|
|
|
ev.detail("FieldValue", field);
|
|
|
|
|
|
|
|
throw;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
} // namespace
|
|
|
|
|
|
|
|
int TraceEventFields::getInt(std::string key, bool permissive) const {
|
|
|
|
return getNumericValue<int>(*this, key, permissive);
|
|
|
|
}
|
|
|
|
|
|
|
|
int64_t TraceEventFields::getInt64(std::string key, bool permissive) const {
|
|
|
|
return getNumericValue<int64_t>(*this, key, permissive);
|
|
|
|
}
|
|
|
|
|
2022-02-05 07:04:30 +08:00
|
|
|
uint64_t TraceEventFields::getUint64(std::string key, bool permissive) const {
|
|
|
|
return getNumericValue<uint64_t>(*this, key, permissive);
|
|
|
|
}
|
|
|
|
|
2019-03-01 01:53:16 +08:00
|
|
|
double TraceEventFields::getDouble(std::string key, bool permissive) const {
|
|
|
|
return getNumericValue<double>(*this, key, permissive);
|
|
|
|
}
|
|
|
|
|
2018-05-03 01:44:38 +08:00
|
|
|
std::string TraceEventFields::toString() const {
|
|
|
|
std::string str;
|
|
|
|
bool first = true;
|
2021-03-11 02:06:03 +08:00
|
|
|
for (auto itr = begin(); itr != end(); ++itr) {
|
|
|
|
if (!first) {
|
2018-05-03 01:44:38 +08:00
|
|
|
str += ", ";
|
|
|
|
}
|
|
|
|
first = false;
|
|
|
|
|
|
|
|
str += format("\"%s\"=\"%s\"", itr->first.c_str(), itr->second.c_str());
|
|
|
|
}
|
|
|
|
|
|
|
|
return str;
|
|
|
|
}
|
2018-06-09 04:24:30 +08:00
|
|
|
|
2021-03-11 02:06:03 +08:00
|
|
|
bool validateField(const char* key, bool allowUnderscores) {
|
|
|
|
if ((key[0] < 'A' || key[0] > 'Z') && key[0] != '_') {
|
2018-06-09 04:24:30 +08:00
|
|
|
return false;
|
|
|
|
}
|
|
|
|
|
|
|
|
const char* underscore = strchr(key, '_');
|
2021-03-11 02:06:03 +08:00
|
|
|
while (underscore) {
|
|
|
|
if (!allowUnderscores || ((underscore[1] < 'A' || underscore[1] > 'Z') && key[0] != '_' && key[0] != '\0')) {
|
2018-06-09 04:24:30 +08:00
|
|
|
return false;
|
|
|
|
}
|
2018-06-09 07:22:22 +08:00
|
|
|
|
2018-06-09 04:24:30 +08:00
|
|
|
underscore = strchr(&underscore[1], '_');
|
|
|
|
}
|
|
|
|
|
|
|
|
return true;
|
|
|
|
}
|
|
|
|
|
|
|
|
void TraceEventFields::validateFormat() const {
|
2021-03-11 02:06:03 +08:00
|
|
|
if (g_network && g_network->isSimulated()) {
|
|
|
|
for (Field field : fields) {
|
|
|
|
if (!validateField(field.first.c_str(), false)) {
|
|
|
|
fprintf(stderr,
|
|
|
|
"Trace event detail name `%s' is invalid in:\n\t%s\n",
|
|
|
|
field.first.c_str(),
|
|
|
|
toString().c_str());
|
2018-06-09 04:24:30 +08:00
|
|
|
}
|
2021-03-11 02:06:03 +08:00
|
|
|
if (field.first == "Type" && !validateField(field.second.c_str(), true)) {
|
2018-06-09 04:24:30 +08:00
|
|
|
fprintf(stderr, "Trace event detail Type `%s' is invalid\n", field.second.c_str());
|
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
2018-06-29 06:28:58 +08:00
|
|
|
}
|
2019-04-16 00:43:26 +08:00
|
|
|
|
|
|
|
std::string traceableStringToString(const char* value, size_t S) {
|
2021-03-11 02:06:03 +08:00
|
|
|
if (g_network) {
|
2020-02-22 08:28:03 +08:00
|
|
|
ASSERT_WE_THINK(S > 0 && value[S - 1] == '\0');
|
|
|
|
}
|
|
|
|
|
2019-04-16 00:43:26 +08:00
|
|
|
return std::string(value, S - 1); // Exclude trailing \0 byte
|
|
|
|
}
|