database/doris
2
0
Fork 0
Code Issues Pull Requests Actions 3 Packages Projects Releases Wiki Activity

[trace] Introduce trace util to BE

Browse Source 
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
This commit is contained in:
Mingyu Chen
2020-05-18 11:10:25 +08:00
committed by GitHub
parent 2f3b7b5b8e 9fc2554e6c
commit bb7ae97845
9 changed files with 893 additions and 0 deletions
Download Patch File Download Diff File Expand all files Collapse all files

20
be/src/common/logconfig.cpp
View File

@ -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

2
be/src/util/CMakeLists.txt
View File

@ -93,6 +93,8 @@ set(UTIL_FILES
condition_variable.cpp
thread.cpp
threadpool.cpp
trace.cpp
trace_metrics.cpp
)
if (WITH_MYSQL)

4
be/src/util/logging.h
View File

@ -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

266
be/src/util/trace.cpp Normal file
View File

@ -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

291
be/src/util/trace.h Normal file
View File

@ -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

74
be/src/util/trace_metrics.cpp Normal file
View File

@ -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

89
be/src/util/trace_metrics.h Normal file
View File

@ -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

1
be/test/util/CMakeLists.txt
View File

@ -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)

146
be/test/util/trace_test.cpp Normal file
View File

@ -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();
}