diff --git a/be/src/common/logconfig.cpp b/be/src/common/logconfig.cpp index bb5a18314b..72d3b7bc0c 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 #include #include #include #include + #include #include + #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 ce380d4441..f3e952fa9f 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 4a977368c3..ab9e0063d0 100644 --- a/be/src/util/logging.h +++ b/be/src/util/logging.h @@ -20,6 +20,7 @@ #include #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 0000000000..f104f90e31 --- /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 +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include + +#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(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(arena_->AllocateBytes(size)); + uint8_t* dst = reinterpret_cast(malloc(size)); + TraceEntry* entry = reinterpret_cast(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 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 entries; + vector>> child_traces; + { + std::lock_guard 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(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 jw(buf); + MetricsToJSON(&jw); + return buf.GetString(); +} + +void Trace::MetricsToJSON(rapidjson::Writer* 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 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>> child_traces; + { + std::lock_guard 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 l(lock_); + scoped_refptr ptr(child_trace); + child_traces_.emplace_back(label, ptr); +} + +std::vector>> Trace::ChildTraces() const { + std::lock_guard 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 0000000000..397dbb5ac8 --- /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 +#include +#include +#include +#include + +#include + +#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 { + 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>> 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(); + + // 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* jw) const; + + // TODO(yingchun): now we didn't import Arena, instead, we use manual malloc() and free(). + // std::unique_ptr 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>> 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 0000000000..07be09f857 --- /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 +#include +#include +#include +#include +#include +#include +#include + +#include +#include + +#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 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 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 0000000000..7c3f440820 --- /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 +#include +#include +#include + +#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 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 counters_; + + DISALLOW_COPY_AND_ASSIGN(TraceMetrics); +}; + +inline void TraceMetrics::Increment(const char* name, int64_t amount) { + std::lock_guard l(lock_); + counters_[name] += amount; +} + +inline std::map TraceMetrics::Get() const { + std::unique_lock l(lock_); + return counters_; +} + +inline int64_t TraceMetrics::GetMetric(const char* name) const { + std::lock_guard l(lock_); + return FindWithDefault(counters_, name, 0); +} + +} // namespace doris diff --git a/be/test/util/CMakeLists.txt b/be/test/util/CMakeLists.txt index fd9d9db3db..882921e590 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 0000000000..0d5a9540eb --- /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 +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include +#include +#include + +#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 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 traceA(new Trace); + scoped_refptr 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 traceA(new Trace); + scoped_refptr 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(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(); +} +