You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@doris.apache.org by mo...@apache.org on 2020/05/18 05:29:55 UTC
[incubator-doris] 01/01: Revert "Revert "[trace] Introduce trace
util to BE" (#3614)"
This is an automated email from the ASF dual-hosted git repository.
morningman pushed a commit to branch revert-3614-revert-3572-add_trace
in repository https://gitbox.apache.org/repos/asf/incubator-doris.git
commit 4d06b29789fa603891910947c4db7470d0771150
Author: Mingyu Chen <mo...@gmail.com>
AuthorDate: Mon May 18 13:29:47 2020 +0800
Revert "Revert "[trace] Introduce trace util to BE" (#3614)"
This reverts commit 69a63f6f53b38c6f4492b0a291e5aaf60edf1f02.
---
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: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org