This is an automated email from the ASF dual-hosted git repository.
morningman pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-doris.git
The following commit(s) were added to refs/heads/master by this push:
new 7fb74db [Trace] Introduce trace util to BE
7fb74db is described below
commit 7fb74db0a1ab004137999cf179598c5aca222bc6
Author: Mingyu Chen <[email protected]>
AuthorDate: Mon May 18 14:55:11 2020 +0800
[Trace] Introduce trace util to BE
Ref https://github.com/apache/incubator-doris/issues/3566
Introduce trace utility from Kudu to BE. This utility has been widely used
in Kudu,
Impala also import this trace utility.
This trace util is used for tracing each phases in a thread, and can be
dumped to
string to see each phases' time cost and diagnose which phase cost more
time.
This util store a Trace object as a threadlocal variable, we can add trace
entries
which record the current file name, line number, user specified symbols and
timestamp to this object, and it's able to add some counters to this Trace
object. And then, it can be dumped to human readable string.
There are some helpful macros defined in trace.h, here is a simple example
for
usage:
```
scoped_refptr<Trace> t1(new Trace); // New 2 traces
scoped_refptr<Trace> t2(new Trace);
t1->AddChildTrace("child_trace", t2.get()); // t1 add t2 as a child
named "child_trace"
TRACE_TO(t1, "step $0", 1); // Explicitly trace to t1
usleep(10);
// ... do some work
ADOPT_TRACE(t1.get()); // Explicitly adopt to trace to t1
TRACE("step $0", 2); // Implicitly trace to t1
{
// The time spent in this scope is added to counter t1.scope_time_cost
TRACE_COUNTER_SCOPE_LATENCY_US("scope_time_cost");
ADOPT_TRACE(t2.get()); // Adopt to trace to t2 for the duration of the
current scope
TRACE("sub start"); // Implicitly trace to t2
usleep(10);
// ... do some work
TRACE("sub before loop");
for (int i = 0; i < 10; ++i) {
TRACE_COUNTER_INCREMENT("iterate_count", 1); // Increase counter
t2.iterate_count
MicrosecondsInt64 start_time = GetMonoTimeMicros();
usleep(10);
// ... do some work
MicrosecondsInt64 end_time = GetMonoTimeMicros();
int64_t dur = end_time - start_time;
// t2's simple histogram metric with name prefixed with "lbm_writes"
const char* counter = BUCKETED_COUNTER_NAME("lbm_writes", dur);
TRACE_COUNTER_INCREMENT(counter, 1);
}
TRACE("sub after loop");
}
TRACE("goodbye $0", "cruel world"); // Automatically restore to trace
to t1
std::cout << t1->DumpToString(Trace::INCLUDE_ALL) << std::endl;
```
output looks like:
```
0514 02:16:07.988054 (+ 0us) trace_test.cpp:76] step 1
0514 02:16:07.988112 (+ 58us) trace_test.cpp:80] step 2
0514 02:16:07.988863 (+ 751us) trace_test.cpp:103] goodbye cruel world
Related trace 'child_trace':
0514 02:16:07.988120 (+ 0us) trace_test.cpp:85] sub start
0514 02:16:07.988188 (+ 68us) trace_test.cpp:88] sub before loop
0514 02:16:07.988850 (+ 662us) trace_test.cpp:101] sub after loop
Metrics:
{"scope_time_cost":744,"child_traces":[["child_trace",{"iterate_count":10,"lbm_writes_lt_1ms":10}]]}
```
Exclude the original source code, this patch
do the following work to adapt to Doris:
- Rename "kudu" namespace to "doris"
- Update some names to the existing function names in Doris, i.g.
strings::internal::SubstituteArg::kNoArg ->
strings::internal::SubstituteArg::NoArg
- Use doris::SpinLock instead of kudu::simple_spinlock which hasn't been
imported
- Use manual malloc() and free() instead of kudu::Arena which hasn't been
imported
- Use manual rapidjson::Writer instead of kudu::JsonWriter which hasn't
been imported
- Remove all TRACE_EVENT related unit tests since TRACE_EVENT is not
imported this time
- Update CMakeLists.txt
NOTICE(#3622):
This is a "revert of revert pull request".
This pr is mainly used to synthesize the PRs whose commits were
scattered and submitted due to the wrong merge method into a complete
single commit.
---
be/src/common/logconfig.cpp | 20 +++
be/src/util/CMakeLists.txt | 2 +
be/src/util/logging.h | 4 +
be/src/util/trace.cpp | 266 ++++++++++++++++++++++++++++++++++++++
be/src/util/trace.h | 291 ++++++++++++++++++++++++++++++++++++++++++
be/src/util/trace_metrics.cpp | 74 +++++++++++
be/src/util/trace_metrics.h | 89 +++++++++++++
be/test/util/CMakeLists.txt | 1 +
be/test/util/trace_test.cpp | 146 +++++++++++++++++++++
9 files changed, 893 insertions(+)
diff --git a/be/src/common/logconfig.cpp b/be/src/common/logconfig.cpp
index bb5a183..72d3b7b 100644
--- a/be/src/common/logconfig.cpp
+++ b/be/src/common/logconfig.cpp
@@ -15,14 +15,19 @@
// specific language governing permissions and limitations
// under the License.
+#include "util/logging.h"
+
#include <iostream>
#include <cerrno>
#include <cstring>
#include <cstdlib>
#include <mutex>
+
#include <glog/logging.h>
#include <glog/vlog_is_on.h>
+
#include "common/config.h"
+#include "gutil/stringprintf.h"
namespace doris {
@@ -148,4 +153,19 @@ void shutdown_logging() {
google::ShutdownGoogleLogging();
}
+std::string FormatTimestampForLog(MicrosecondsInt64 micros_since_epoch) {
+ time_t secs_since_epoch = micros_since_epoch / 1000000;
+ int usecs = micros_since_epoch % 1000000;
+ struct tm tm_time;
+ localtime_r(&secs_since_epoch, &tm_time);
+
+ return StringPrintf("%02d%02d %02d:%02d:%02d.%06d",
+ 1 + tm_time.tm_mon,
+ tm_time.tm_mday,
+ tm_time.tm_hour,
+ tm_time.tm_min,
+ tm_time.tm_sec,
+ usecs);
+}
+
} // namespace doris
diff --git a/be/src/util/CMakeLists.txt b/be/src/util/CMakeLists.txt
index ce380d4..f3e952f 100644
--- a/be/src/util/CMakeLists.txt
+++ b/be/src/util/CMakeLists.txt
@@ -93,6 +93,8 @@ set(UTIL_FILES
condition_variable.cpp
thread.cpp
threadpool.cpp
+ trace.cpp
+ trace_metrics.cpp
)
if (WITH_MYSQL)
diff --git a/be/src/util/logging.h b/be/src/util/logging.h
index 4a97736..ab9e006 100644
--- a/be/src/util/logging.h
+++ b/be/src/util/logging.h
@@ -20,6 +20,7 @@
#include <string>
#include "common/logging.h"
+#include "gutil/walltime.h"
namespace doris {
@@ -31,6 +32,9 @@ bool init_glog(const char* basename, bool
install_signal_handler = false);
// flushed. May only be called once.
void shutdown_logging();
+// Format a timestamp in the same format as used by GLog.
+std::string FormatTimestampForLog(MicrosecondsInt64 micros_since_epoch);
+
}
#endif // DORIS_BE_SRC_COMMON_UTIL_LOGGING_H
diff --git a/be/src/util/trace.cpp b/be/src/util/trace.cpp
new file mode 100644
index 0000000..f104f90
--- /dev/null
+++ b/be/src/util/trace.cpp
@@ -0,0 +1,266 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you 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
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// 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.
+
+#include "util/trace.h"
+
+#include <cstdint>
+#include <cstring>
+#include <iomanip>
+#include <iostream>
+#include <map>
+#include <mutex>
+#include <string>
+#include <utility>
+#include <vector>
+
+#include <glog/logging.h>
+#include <rapidjson/rapidjson.h>
+
+#include "gutil/strings/substitute.h"
+#include "gutil/walltime.h"
+#include "util/logging.h"
+//#include "util/memory/arena.h"
+
+using std::pair;
+using std::string;
+using std::vector;
+using strings::internal::SubstituteArg;
+
+namespace doris {
+
+__thread Trace* Trace::threadlocal_trace_;
+
+Trace::Trace()
+ : // arena_(new ThreadSafeArena(1024)),
+ entries_head_(nullptr),
+ entries_tail_(nullptr) {
+ // We expect small allocations from our Arena so no need to have
+ // a large arena component. Small allocations are more likely to
+ // come out of thread cache and be fast.
+ // arena_->SetMaxBufferSize(4096);
+}
+
+// Struct which precedes each entry in the trace.
+struct TraceEntry {
+ MicrosecondsInt64 timestamp_micros;
+
+ // The source file and line number which generated the trace message.
+ const char* file_path;
+ int line_number;
+
+ uint32_t message_len;
+ TraceEntry* next;
+
+ // The actual trace message follows the entry header.
+ char* message() {
+ return reinterpret_cast<char*>(this) + sizeof(*this);
+ }
+};
+
+Trace::~Trace() {
+ while (entries_head_ != nullptr) {
+ TraceEntry* tmp = entries_head_;
+ entries_head_ = entries_head_->next;
+ free(tmp);
+ }
+}
+
+// Get the part of filepath after the last path separator.
+// (Doesn't modify filepath, contrary to basename() in libgen.h.)
+// Borrowed from glog.
+static const char* const_basename(const char* filepath) {
+ const char* base = strrchr(filepath, '/');
+#ifdef OS_WINDOWS // Look for either path separator in Windows
+ if (!base)
+ base = strrchr(filepath, '\\');
+#endif
+ return base ? (base+1) : filepath;
+}
+
+
+void Trace::SubstituteAndTrace(const char* file_path,
+ int line_number,
+ StringPiece format,
+ const SubstituteArg& arg0, const SubstituteArg&
arg1,
+ const SubstituteArg& arg2, const SubstituteArg&
arg3,
+ const SubstituteArg& arg4, const SubstituteArg&
arg5,
+ const SubstituteArg& arg6, const SubstituteArg&
arg7,
+ const SubstituteArg& arg8, const SubstituteArg&
arg9) {
+ const SubstituteArg* const args_array[] = {
+ &arg0, &arg1, &arg2, &arg3, &arg4, &arg5, &arg6, &arg7, &arg8, &arg9,
nullptr
+ };
+
+ int msg_len = strings::internal::SubstitutedSize(format, args_array);
+ TraceEntry* entry = NewEntry(msg_len, file_path, line_number);
+ SubstituteToBuffer(format, args_array, entry->message());
+ AddEntry(entry);
+}
+
+TraceEntry* Trace::NewEntry(int msg_len, const char* file_path, int
line_number) {
+ int size = sizeof(TraceEntry) + msg_len;
+ //uint8_t* dst = reinterpret_cast<uint8_t*>(arena_->AllocateBytes(size));
+ uint8_t* dst = reinterpret_cast<uint8_t*>(malloc(size));
+ TraceEntry* entry = reinterpret_cast<TraceEntry*>(dst);
+ entry->timestamp_micros = GetCurrentTimeMicros();
+ entry->message_len = msg_len;
+ entry->file_path = file_path;
+ entry->line_number = line_number;
+ return entry;
+}
+
+void Trace::AddEntry(TraceEntry* entry) {
+ std::lock_guard<SpinLock> l(lock_);
+ entry->next = nullptr;
+
+ if (entries_tail_ != nullptr) {
+ entries_tail_->next = entry;
+ } else {
+ DCHECK(entries_head_ == nullptr);
+ entries_head_ = entry;
+ }
+ entries_tail_ = entry;
+}
+
+void Trace::Dump(std::ostream* out, int flags) const {
+ // Gather a copy of the list of entries under the lock. This is fast
+ // enough that we aren't worried about stalling concurrent tracers
+ // (whereas doing the logging itself while holding the lock might be
+ // too slow, if the output stream is a file, for example).
+ vector<TraceEntry*> entries;
+ vector<pair<StringPiece, scoped_refptr<Trace>>> child_traces;
+ {
+ std::lock_guard<SpinLock> l(lock_);
+ for (TraceEntry* cur = entries_head_;
+ cur != nullptr;
+ cur = cur->next) {
+ entries.push_back(cur);
+ }
+
+ child_traces = child_traces_;
+ }
+
+ // Save original flags.
+ std::ios::fmtflags save_flags(out->flags());
+
+ int64_t prev_usecs = 0;
+ for (TraceEntry* e : entries) {
+ // Log format borrowed from glog/logging.cc
+ int64_t usecs_since_prev = 0;
+ if (prev_usecs != 0) {
+ usecs_since_prev = e->timestamp_micros - prev_usecs;
+ }
+ prev_usecs = e->timestamp_micros;
+
+ using std::setw;
+ *out << FormatTimestampForLog(e->timestamp_micros);
+ *out << ' ';
+ if (flags & INCLUDE_TIME_DELTAS) {
+ out->fill(' ');
+ *out << "(+" << setw(6) << usecs_since_prev << "us) ";
+ }
+ *out << const_basename(e->file_path) << ':' << e->line_number
+ << "] ";
+ out->write(reinterpret_cast<char*>(e) + sizeof(TraceEntry),
+ e->message_len);
+ *out << std::endl;
+ }
+
+ for (const auto& entry : child_traces) {
+ const auto& t = entry.second;
+ *out << "Related trace '" << entry.first << "':" << std::endl;
+ *out << t->DumpToString(flags & (~INCLUDE_METRICS));
+ }
+
+ if (flags & INCLUDE_METRICS) {
+ *out << "Metrics: " << MetricsAsJSON();
+ }
+
+ // Restore stream flags.
+ out->flags(save_flags);
+}
+
+string Trace::DumpToString(int flags) const {
+ std::ostringstream s;
+ Dump(&s, flags);
+ return s.str();
+}
+
+string Trace::MetricsAsJSON() const {
+ // TODO(yingchun): simplily implement here, we could import JsonWriter in
the future.
+ rapidjson::StringBuffer buf;
+ rapidjson::Writer<rapidjson::StringBuffer> jw(buf);
+ MetricsToJSON(&jw);
+ return buf.GetString();
+}
+
+void Trace::MetricsToJSON(rapidjson::Writer<rapidjson::StringBuffer>* jw)
const {
+ // Convert into a map with 'std::string' keys instead of 'const char*'
+ // keys, so that the results are in a consistent (sorted) order.
+ std::map<string, int64_t> counters;
+ for (const auto& entry : metrics_.Get()) {
+ counters[entry.first] = entry.second;
+ }
+
+ jw->StartObject();
+ for (const auto& e : counters) {
+ jw->String(e.first.c_str());
+ jw->Int64(e.second);
+ }
+ vector<pair<StringPiece, scoped_refptr<Trace>>> child_traces;
+ {
+ std::lock_guard<SpinLock> l(lock_);
+ child_traces = child_traces_;
+ }
+
+ if (!child_traces.empty()) {
+ jw->String("child_traces");
+ jw->StartArray();
+
+ for (const auto& e : child_traces) {
+ jw->StartArray();
+ jw->String(e.first.data(), e.first.size());
+ e.second->MetricsToJSON(jw);
+ jw->EndArray();
+ }
+ jw->EndArray();
+ }
+ jw->EndObject();
+}
+
+void Trace::DumpCurrentTrace() {
+ Trace* t = CurrentTrace();
+ if (t == nullptr) {
+ LOG(INFO) << "No trace is currently active.";
+ return;
+ }
+ t->Dump(&std::cerr, true);
+}
+
+void Trace::AddChildTrace(StringPiece label, Trace* child_trace) {
+ //CHECK(arena_->RelocateStringPiece(label, &label));
+
+ std::lock_guard<SpinLock> l(lock_);
+ scoped_refptr<Trace> ptr(child_trace);
+ child_traces_.emplace_back(label, ptr);
+}
+
+std::vector<std::pair<StringPiece, scoped_refptr<Trace>>> Trace::ChildTraces()
const {
+ std::lock_guard<SpinLock> l(lock_);
+ return child_traces_;
+}
+
+} // namespace doris
diff --git a/be/src/util/trace.h b/be/src/util/trace.h
new file mode 100644
index 0000000..397dbb5
--- /dev/null
+++ b/be/src/util/trace.h
@@ -0,0 +1,291 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you 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
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// 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.
+#pragma once
+
+#include <iosfwd>
+#include <memory>
+#include <string>
+#include <utility>
+#include <vector>
+
+#include <rapidjson/writer.h>
+
+#include "gutil/macros.h"
+#include "gutil/strings/stringpiece.h"
+#include "gutil/strings/substitute.h"
+#include "gutil/ref_counted.h"
+#include "gutil/threading/thread_collision_warner.h"
+#include "gutil/walltime.h"
+#include "util/spinlock.h"
+#include "util/trace_metrics.h"
+
+namespace doris {
+class Trace;
+}
+
+// Adopt a Trace on the current thread for the duration of the current
+// scope. The old current Trace is restored when the scope is exited.
+//
+// 't' should be a Trace* pointer.
+#define ADOPT_TRACE(t) doris::ScopedAdoptTrace _adopt_trace(t);
+
+// Issue a trace message, if tracing is enabled in the current thread.
+// See Trace::SubstituteAndTrace for arguments.
+// Example:
+// TRACE("Acquired timestamp $0", timestamp);
+#define TRACE(format, substitutions...) \
+ do { \
+ doris::Trace* _trace = doris::Trace::CurrentTrace(); \
+ if (_trace) { \
+ _trace->SubstituteAndTrace(__FILE__, __LINE__, (format), \
+ ##substitutions); \
+ } \
+ } while (0)
+
+// Like the above, but takes the trace pointer as an explicit argument.
+#define TRACE_TO(trace, format, substitutions...) \
+ (trace)->SubstituteAndTrace(__FILE__, __LINE__, (format), ##substitutions)
+
+// Increment a counter associated with the current trace.
+//
+// Each trace contains a map of counters which can be used to keep
+// request-specific statistics. It is significantly faster to increment
+// a trace counter compared to logging a message. Additionally, having
+// slightly more structured information makes it easier to aggregate
+// and show information back to operators.
+//
+// NOTE: the 'counter_name' MUST be a string which stays alive forever.
+// Typically, this is a compile-time constant. If something other than
+// a constant is required, use TraceMetric::InternName() in order to
+// create a string which will last for the process lifetime. Of course,
+// these strings will never be cleaned up, so it's important to use this
+// judiciously.
+//
+// If no trace is active, this does nothing and does not evaluate its
+// parameters.
+#define TRACE_COUNTER_INCREMENT(counter_name, val) \
+ do { \
+ doris::Trace* _trace = doris::Trace::CurrentTrace(); \
+ if (_trace) { \
+ _trace->metrics()->Increment(counter_name, val); \
+ } \
+ } while (0)
+
+// Increment a counter for the amount of wall time spent in the current
+// scope. For example:
+//
+// void DoFoo() {
+// TRACE_COUNTER_SCOPE_LATENCY_US("foo_us");
+// ... do expensive Foo thing
+// }
+//
+// will result in a trace metric indicating the number of microseconds spent
+// in invocations of DoFoo().
+#define TRACE_COUNTER_SCOPE_LATENCY_US(counter_name) \
+ ::doris::ScopedTraceLatencyCounter _scoped_latency(counter_name)
+
+// Construct a constant C string counter name which acts as a sort of
+// coarse-grained histogram for trace metrics.
+#define BUCKETED_COUNTER_NAME(prefix, duration_us) \
+ [=]() { \
+ if (duration_us >= 100 * 1000) { \
+ return prefix "_gt_100_ms"; \
+ } else if (duration_us >= 10 * 1000) { \
+ return prefix "_10-100_ms"; \
+ } else if (duration_us >= 1000) { \
+ return prefix "_1-10_ms"; \
+ } else { \
+ return prefix "_lt_1ms"; \
+ } \
+ }()
+
+namespace doris {
+
+struct TraceEntry;
+
+// A trace for a request or other process. This supports collecting trace
entries
+// from a number of threads, and later dumping the results to a stream.
+//
+// Callers should generally not add trace messages directly using the public
+// methods of this class. Rather, the TRACE(...) macros defined above should
+// be used such that file/line numbers are automatically included, etc.
+//
+// This class is thread-safe.
+class Trace : public RefCountedThreadSafe<Trace> {
+ public:
+ Trace();
+
+ // Logs a message into the trace buffer.
+ //
+ // See strings::Substitute for details.
+ //
+ // N.B.: the file path passed here is not copied, so should be a static
+ // constant (eg __FILE__).
+ void SubstituteAndTrace(const char* filepath, int line_number,
+ StringPiece format,
+ const strings::internal::SubstituteArg& arg0 =
+ strings::internal::SubstituteArg::NoArg,
+ const strings::internal::SubstituteArg& arg1 =
+ strings::internal::SubstituteArg::NoArg,
+ const strings::internal::SubstituteArg& arg2 =
+ strings::internal::SubstituteArg::NoArg,
+ const strings::internal::SubstituteArg& arg3 =
+ strings::internal::SubstituteArg::NoArg,
+ const strings::internal::SubstituteArg& arg4 =
+ strings::internal::SubstituteArg::NoArg,
+ const strings::internal::SubstituteArg& arg5 =
+ strings::internal::SubstituteArg::NoArg,
+ const strings::internal::SubstituteArg& arg6 =
+ strings::internal::SubstituteArg::NoArg,
+ const strings::internal::SubstituteArg& arg7 =
+ strings::internal::SubstituteArg::NoArg,
+ const strings::internal::SubstituteArg& arg8 =
+ strings::internal::SubstituteArg::NoArg,
+ const strings::internal::SubstituteArg& arg9 =
+ strings::internal::SubstituteArg::NoArg);
+
+ // Dump the trace buffer to the given output stream.
+ //
+ enum {
+ NO_FLAGS = 0,
+
+ // If set, calculate and print the difference between successive trace
messages.
+ INCLUDE_TIME_DELTAS = 1 << 0,
+ // If set, include a 'Metrics' line showing any attached trace metrics.
+ INCLUDE_METRICS = 1 << 1,
+
+ INCLUDE_ALL = INCLUDE_TIME_DELTAS | INCLUDE_METRICS
+ };
+ void Dump(std::ostream* out, int flags) const;
+
+ // Dump the trace buffer as a string.
+ std::string DumpToString(int flags = INCLUDE_ALL) const;
+
+ std::string MetricsAsJSON() const;
+
+ // Attaches the given trace which will get appended at the end when Dumping.
+ //
+ // The 'label' does not necessarily have to be unique, and is used to
identify
+ // the child trace when dumped. The contents of the StringPiece are copied
+ // into this trace's arena.
+ void AddChildTrace(StringPiece label, Trace* child_trace);
+
+ // Return a copy of the current set of related "child" traces.
+ std::vector<std::pair<StringPiece, scoped_refptr<Trace>>> ChildTraces()
const;
+
+ // Return the current trace attached to this thread, if there is one.
+ static Trace* CurrentTrace() {
+ return threadlocal_trace_;
+ }
+
+ // Simple function to dump the current trace to stderr, if one is
+ // available. This is meant for usage when debugging in gdb via
+ // 'call doris::Trace::DumpCurrentTrace();'.
+ static void DumpCurrentTrace();
+
+ TraceMetrics* metrics() {
+ return &metrics_;
+ }
+ const TraceMetrics& metrics() const {
+ return metrics_;
+ }
+
+ private:
+ friend class ScopedAdoptTrace;
+ friend class RefCountedThreadSafe<Trace>;
+ ~Trace();
+
+ // The current trace for this thread. Threads should only set this using
+ // using ScopedAdoptTrace, which handles reference counting the underlying
+ // object.
+ static __thread Trace* threadlocal_trace_;
+
+ // Allocate a new entry from the arena, with enough space to hold a
+ // message of length 'len'.
+ TraceEntry* NewEntry(int len, const char* file_path, int line_number);
+
+ // Add the entry to the linked list of entries.
+ void AddEntry(TraceEntry* entry);
+
+ void MetricsToJSON(rapidjson::Writer<rapidjson::StringBuffer>* jw) const;
+
+ // TODO(yingchun): now we didn't import Arena, instead, we use manual
malloc() and free().
+ // std::unique_ptr<ThreadSafeArena> arena_;
+
+ // Lock protecting the entries linked list.
+ mutable SpinLock lock_;
+ // The head of the linked list of entries (allocated inside arena_)
+ TraceEntry* entries_head_;
+ // The tail of the linked list of entries (allocated inside arena_)
+ TraceEntry* entries_tail_;
+
+ std::vector<std::pair<StringPiece, scoped_refptr<Trace>>> child_traces_;
+
+ TraceMetrics metrics_;
+
+ DISALLOW_COPY_AND_ASSIGN(Trace);
+};
+
+// Adopt a Trace object into the current thread for the duration
+// of this object.
+// This should only be used on the stack (and thus created and destroyed
+// on the same thread)
+class ScopedAdoptTrace {
+ public:
+ explicit ScopedAdoptTrace(Trace* t) :
+ old_trace_(Trace::threadlocal_trace_) {
+ Trace::threadlocal_trace_ = t;
+ if (t) {
+ t->AddRef();
+ }
+ DFAKE_SCOPED_LOCK_THREAD_LOCKED(ctor_dtor_);
+ }
+
+ ~ScopedAdoptTrace() {
+ if (Trace::threadlocal_trace_) {
+ Trace::threadlocal_trace_->Release();
+ }
+ Trace::threadlocal_trace_ = old_trace_;
+ DFAKE_SCOPED_LOCK_THREAD_LOCKED(ctor_dtor_);
+ }
+
+ private:
+ DFAKE_MUTEX(ctor_dtor_);
+ Trace* old_trace_;
+
+ DISALLOW_COPY_AND_ASSIGN(ScopedAdoptTrace);
+};
+
+// Implementation for TRACE_COUNTER_SCOPE_LATENCY_US(...) macro above.
+class ScopedTraceLatencyCounter {
+ public:
+ explicit ScopedTraceLatencyCounter(const char* counter)
+ : counter_(counter),
+ start_time_(GetCurrentTimeMicros()) {
+ }
+
+ ~ScopedTraceLatencyCounter() {
+ TRACE_COUNTER_INCREMENT(counter_, GetCurrentTimeMicros() - start_time_);
+ }
+
+ private:
+ const char* const counter_;
+ MicrosecondsInt64 start_time_;
+ DISALLOW_COPY_AND_ASSIGN(ScopedTraceLatencyCounter);
+};
+
+} // namespace doris
diff --git a/be/src/util/trace_metrics.cpp b/be/src/util/trace_metrics.cpp
new file mode 100644
index 0000000..07be09f
--- /dev/null
+++ b/be/src/util/trace_metrics.cpp
@@ -0,0 +1,74 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you 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
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// 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.
+
+#include "util/trace_metrics.h"
+
+#include <algorithm>
+#include <cctype>
+#include <cstring>
+#include <map>
+#include <mutex>
+#include <ostream>
+#include <string>
+#include <utility>
+
+#include <glog/logging.h>
+#include <glog/stl_logging.h>
+
+#include "util/debug/leakcheck_disabler.h"
+
+using std::string;
+
+namespace doris {
+
+// Make glog's STL-compatible operators visible inside this namespace.
+using ::operator<<;
+
+namespace {
+
+static SpinLock g_intern_map_lock;
+typedef std::map<string, const char*> InternMap;
+static InternMap* g_intern_map;
+
+} // anonymous namespace
+
+const char* TraceMetrics::InternName(const string& name) {
+ DCHECK(std::all_of(name.begin(), name.end(), [] (char c) { return
isprint(c); } ))
+ << "not printable: " << name;
+
+ debug::ScopedLeakCheckDisabler no_leakcheck;
+ std::lock_guard<SpinLock> l(g_intern_map_lock);
+ if (g_intern_map == nullptr) {
+ g_intern_map = new InternMap();
+ }
+
+ InternMap::iterator it = g_intern_map->find(name);
+ if (it != g_intern_map->end()) {
+ return it->second;
+ }
+
+ const char* dup = strdup(name.c_str());
+ (*g_intern_map)[name] = dup;
+
+ // We don't expect this map to grow large.
+ DCHECK_LT(g_intern_map->size(), 100) <<
+ "Too many interned strings: " << *g_intern_map;
+
+ return dup;
+}
+
+} // namespace doris
diff --git a/be/src/util/trace_metrics.h b/be/src/util/trace_metrics.h
new file mode 100644
index 0000000..7c3f440
--- /dev/null
+++ b/be/src/util/trace_metrics.h
@@ -0,0 +1,89 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you 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
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// 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.
+#pragma once
+
+#include <cstdint>
+#include <map>
+#include <mutex>
+#include <string>
+
+#include "gutil/macros.h"
+#include "gutil/map-util.h"
+#include "util/spinlock.h"
+
+namespace doris {
+
+// A simple map of constant string names to integer counters.
+//
+// Typically, the TRACE_COUNTER_INCREMENT(...) macro defined in
+// trace.h is used to increment a counter within this map.
+//
+// This currently is just a thin wrapper around a spinlocked map,
+// but if it becomes noticeable in the CPU profile, various optimizations
+// are plausible.
+class TraceMetrics {
+ public:
+ TraceMetrics() {}
+ ~TraceMetrics() {}
+
+ // Internalize the given string by duplicating it into a process-wide
+ // pool. If this string has already been interned, returns a pointer
+ // to a previous instance. Otherwise, copies it into the pool.
+ //
+ // The resulting strings are purposefully leaked, so this should only
+ // be used in cases where the number of unique strings that will be
+ // passed is relatively low (i.e. not user-specified).
+ //
+ // Because 'name' is exposed back to operators, it must be a printable
+ // ASCII string.
+ static const char* InternName(const std::string& name);
+
+ // Increment the given counter.
+ void Increment(const char* name, int64_t amount);
+
+ // Return a copy of the current counter map.
+ std::map<const char*, int64_t> Get() const;
+
+ // Return metric's current value.
+ //
+ // NOTE: the 'name' MUST be the same const char* which is used for
+ // insertion. This is because we do pointer-wise comparison internally.
+ int64_t GetMetric(const char* name) const;
+
+ private:
+ mutable SpinLock lock_;
+ std::map<const char*, int64_t> counters_;
+
+ DISALLOW_COPY_AND_ASSIGN(TraceMetrics);
+};
+
+inline void TraceMetrics::Increment(const char* name, int64_t amount) {
+ std::lock_guard<SpinLock> l(lock_);
+ counters_[name] += amount;
+}
+
+inline std::map<const char*, int64_t> TraceMetrics::Get() const {
+ std::unique_lock<SpinLock> l(lock_);
+ return counters_;
+}
+
+inline int64_t TraceMetrics::GetMetric(const char* name) const {
+ std::lock_guard<SpinLock> l(lock_);
+ return FindWithDefault(counters_, name, 0);
+}
+
+} // namespace doris
diff --git a/be/test/util/CMakeLists.txt b/be/test/util/CMakeLists.txt
index fd9d9db..882921e 100644
--- a/be/test/util/CMakeLists.txt
+++ b/be/test/util/CMakeLists.txt
@@ -63,3 +63,4 @@ ADD_BE_TEST(monotime_test)
ADD_BE_TEST(scoped_cleanup_test)
ADD_BE_TEST(thread_test)
ADD_BE_TEST(threadpool_test)
+ADD_BE_TEST(trace_test)
diff --git a/be/test/util/trace_test.cpp b/be/test/util/trace_test.cpp
new file mode 100644
index 0000000..0d5a954
--- /dev/null
+++ b/be/test/util/trace_test.cpp
@@ -0,0 +1,146 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you 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
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// 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.
+
+#include "util/trace.h"
+
+#include <cctype>
+#include <cstdint>
+#include <cstring>
+#include <functional>
+#include <map>
+#include <ostream>
+#include <string>
+#include <thread>
+#include <vector>
+
+#include <glog/logging.h>
+#include <gtest/gtest.h>
+#include <rapidjson/document.h>
+#include <rapidjson/rapidjson.h>
+
+#include "gutil/macros.h"
+#include "gutil/port.h"
+#include "gutil/ref_counted.h"
+#include "gutil/walltime.h"
+#include "util/countdown_latch.h"
+#include "util/monotime.h"
+#include "util/scoped_cleanup.h"
+#include "util/stopwatch.hpp"
+#include "util/thread.h"
+#include "util/trace_metrics.h"
+
+using rapidjson::Document;
+using rapidjson::Value;
+using std::string;
+using std::thread;
+using std::vector;
+
+namespace doris {
+
+class TraceTest : public ::testing::Test {
+};
+
+// Replace all digits in 's' with the character 'X'.
+static string XOutDigits(const string& s) {
+ string ret;
+ ret.reserve(s.size());
+ for (char c : s) {
+ if (isdigit(c)) {
+ ret.push_back('X');
+ } else {
+ ret.push_back(c);
+ }
+ }
+ return ret;
+}
+
+TEST_F(TraceTest, TestBasic) {
+ scoped_refptr<Trace> t(new Trace);
+ TRACE_TO(t, "hello $0, $1", "world", 12345);
+ TRACE_TO(t, "goodbye $0, $1", "cruel world", 54321);
+
+ string result = XOutDigits(t->DumpToString(Trace::NO_FLAGS));
+ ASSERT_EQ("XXXX XX:XX:XX.XXXXXX trace_test.cpp:XX] hello world, XXXXX\n"
+ "XXXX XX:XX:XX.XXXXXX trace_test.cpp:XX] goodbye cruel world,
XXXXX\n",
+ result);
+}
+
+TEST_F(TraceTest, TestAttach) {
+ scoped_refptr<Trace> traceA(new Trace);
+ scoped_refptr<Trace> traceB(new Trace);
+ {
+ ADOPT_TRACE(traceA.get());
+ EXPECT_EQ(traceA.get(), Trace::CurrentTrace());
+ {
+ ADOPT_TRACE(traceB.get());
+ EXPECT_EQ(traceB.get(), Trace::CurrentTrace());
+ TRACE("hello from traceB");
+ }
+ EXPECT_EQ(traceA.get(), Trace::CurrentTrace());
+ TRACE("hello from traceA");
+ }
+ EXPECT_TRUE(Trace::CurrentTrace() == nullptr);
+ TRACE("this goes nowhere");
+
+ EXPECT_EQ("XXXX XX:XX:XX.XXXXXX trace_test.cpp:XX] hello from traceA\n",
+ XOutDigits(traceA->DumpToString(Trace::NO_FLAGS)));
+ EXPECT_EQ("XXXX XX:XX:XX.XXXXXX trace_test.cpp:XX] hello from traceB\n",
+ XOutDigits(traceB->DumpToString(Trace::NO_FLAGS)));
+}
+
+TEST_F(TraceTest, TestChildTrace) {
+ scoped_refptr<Trace> traceA(new Trace);
+ scoped_refptr<Trace> traceB(new Trace);
+ ADOPT_TRACE(traceA.get());
+ traceA->AddChildTrace("child", traceB.get());
+ TRACE("hello from traceA");
+ {
+ ADOPT_TRACE(traceB.get());
+ TRACE("hello from traceB");
+ }
+ EXPECT_EQ("XXXX XX:XX:XX.XXXXXX trace_test.cpp:XXX] hello from traceA\n"
+ "Related trace 'child':\n"
+ "XXXX XX:XX:XX.XXXXXX trace_test.cpp:XXX] hello from traceB\n",
+ XOutDigits(traceA->DumpToString(Trace::NO_FLAGS)));
+}
+
+TEST_F(TraceTest, TestTraceMetrics) {
+ scoped_refptr<Trace> trace(new Trace);
+ trace->metrics()->Increment("foo", 10);
+ trace->metrics()->Increment("bar", 10);
+ for (int i = 0; i < 1000; i++) {
+ trace->metrics()->Increment("baz", i);
+ }
+ EXPECT_EQ("{\"bar\":10,\"baz\":499500,\"foo\":10}",
+ trace->MetricsAsJSON());
+
+ {
+ ADOPT_TRACE(trace.get());
+ TRACE_COUNTER_SCOPE_LATENCY_US("test_scope_us");
+ SleepFor(MonoDelta::FromMilliseconds(100));
+ }
+ auto m = trace->metrics()->Get();
+ EXPECT_GE(m["test_scope_us"], 80 * 1000);
+}
+
+} // namespace doris
+
+int main(int argc, char** argv) {
+ ::testing::InitGoogleTest(&argc, argv);
+ return RUN_ALL_TESTS();
+}
+
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
