From e066791e47764653e13c0270dfe4c064bec40fc1 Mon Sep 17 00:00:00 2001 From: Yingchun Lai <405403881@qq.com> Date: Tue, 12 May 2020 11:19:20 +0800 Subject: [PATCH 1/3] import original files --- be/src/util/trace.cpp | 259 ++++++++++ be/src/util/trace.h | 290 +++++++++++ be/src/util/trace_metrics.cpp | 74 +++ be/src/util/trace_metrics.h | 89 ++++ be/test/util/trace_test.cpp | 900 ++++++++++++++++++++++++++++++++++ 5 files changed, 1612 insertions(+) create mode 100644 be/src/util/trace.cpp create mode 100644 be/src/util/trace.h create mode 100644 be/src/util/trace_metrics.cpp create mode 100644 be/src/util/trace_metrics.h create mode 100644 be/test/util/trace_test.cpp diff --git a/be/src/util/trace.cpp b/be/src/util/trace.cpp new file mode 100644 index 0000000000..ac566601c5 --- /dev/null +++ b/be/src/util/trace.cpp @@ -0,0 +1,259 @@ +// 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 "kudu/util/trace.h" + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include + +#include "kudu/gutil/strings/substitute.h" +#include "kudu/gutil/walltime.h" +#include "kudu/util/jsonwriter.h" +#include "kudu/util/logging.h" +#include "kudu/util/memory/arena.h" + +using std::pair; +using std::string; +using std::vector; +using strings::internal::SubstituteArg; + +namespace kudu { + +__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); +} + +Trace::~Trace() { +} + +// 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); + } +}; + +// 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)); + 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 { + std::ostringstream s; + JsonWriter jw(&s, JsonWriter::COMPACT); + MetricsToJSON(&jw); + return s.str(); +} + +void Trace::MetricsToJSON(JsonWriter* 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); + 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 kudu diff --git a/be/src/util/trace.h b/be/src/util/trace.h new file mode 100644 index 0000000000..c30e241dbe --- /dev/null +++ b/be/src/util/trace.h @@ -0,0 +1,290 @@ +// 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 "kudu/gutil/macros.h" +#include "kudu/gutil/strings/stringpiece.h" +#include "kudu/gutil/strings/substitute.h" +#include "kudu/gutil/ref_counted.h" +#include "kudu/gutil/threading/thread_collision_warner.h" +#include "kudu/gutil/walltime.h" +#include "kudu/util/locks.h" +#include "kudu/util/trace_metrics.h" + +namespace kudu { +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) kudu::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 { \ + kudu::Trace* _trace = kudu::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 { \ + kudu::Trace* _trace = kudu::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) \ + ::kudu::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 kudu { + +class JsonWriter; +class ThreadSafeArena; +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::kNoArg, + const strings::internal::SubstituteArg& arg1 = + strings::internal::SubstituteArg::kNoArg, + const strings::internal::SubstituteArg& arg2 = + strings::internal::SubstituteArg::kNoArg, + const strings::internal::SubstituteArg& arg3 = + strings::internal::SubstituteArg::kNoArg, + const strings::internal::SubstituteArg& arg4 = + strings::internal::SubstituteArg::kNoArg, + const strings::internal::SubstituteArg& arg5 = + strings::internal::SubstituteArg::kNoArg, + const strings::internal::SubstituteArg& arg6 = + strings::internal::SubstituteArg::kNoArg, + const strings::internal::SubstituteArg& arg7 = + strings::internal::SubstituteArg::kNoArg, + const strings::internal::SubstituteArg& arg8 = + strings::internal::SubstituteArg::kNoArg, + const strings::internal::SubstituteArg& arg9 = + strings::internal::SubstituteArg::kNoArg); + + // 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 kudu::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(JsonWriter* jw) const; + + std::unique_ptr arena_; + + // Lock protecting the entries linked list. + mutable simple_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 kudu diff --git a/be/src/util/trace_metrics.cpp b/be/src/util/trace_metrics.cpp new file mode 100644 index 0000000000..565a6e8e46 --- /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 "kudu/util/trace_metrics.h" + +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include + +#include "kudu/util/debug/leakcheck_disabler.h" + +using std::string; + +namespace kudu { + +// Make glog's STL-compatible operators visible inside this namespace. +using ::operator<<; + +namespace { + +static simple_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 kudu diff --git a/be/src/util/trace_metrics.h b/be/src/util/trace_metrics.h new file mode 100644 index 0000000000..8c460bd2cf --- /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 "kudu/gutil/macros.h" +#include "kudu/gutil/map-util.h" +#include "kudu/util/locks.h" + +namespace kudu { + +// 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 simple_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 kudu diff --git a/be/test/util/trace_test.cpp b/be/test/util/trace_test.cpp new file mode 100644 index 0000000000..4e97c6328b --- /dev/null +++ b/be/test/util/trace_test.cpp @@ -0,0 +1,900 @@ +// 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 "kudu/util/trace.h" + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include +#include +#include + +#include "kudu/gutil/macros.h" +#include "kudu/gutil/port.h" +#include "kudu/gutil/ref_counted.h" +#include "kudu/gutil/walltime.h" +#include "kudu/util/atomic.h" +#include "kudu/util/countdown_latch.h" +#include "kudu/util/debug/trace_event.h" +#include "kudu/util/debug/trace_event_impl.h" +#include "kudu/util/debug/trace_event_synthetic_delay.h" +#include "kudu/util/debug/trace_logging.h" +#include "kudu/util/monotime.h" +#include "kudu/util/scoped_cleanup.h" +#include "kudu/util/status.h" +#include "kudu/util/stopwatch.h" +#include "kudu/util/test_macros.h" +#include "kudu/util/test_util.h" +#include "kudu/util/thread.h" +#include "kudu/util/trace_metrics.h" + +using kudu::debug::TraceLog; +using kudu::debug::TraceResultBuffer; +using kudu::debug::CategoryFilter; +using rapidjson::Document; +using rapidjson::Value; +using std::string; +using std::thread; +using std::vector; + +namespace kudu { + +class TraceTest : public KuduTest { +}; + +// 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.cc:XX] hello world, XXXXX\n" + "XXXX XX:XX:XX.XXXXXX trace-test.cc: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.cc:XXX] hello from traceA\n", + XOutDigits(traceA->DumpToString(Trace::NO_FLAGS))); + EXPECT_EQ("XXXX XX:XX:XX.XXXXXX trace-test.cc:XXX] 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.cc:XXX] hello from traceA\n" + "Related trace 'child':\n" + "XXXX XX:XX:XX.XXXXXX trace-test.cc:XXX] hello from traceB\n", + XOutDigits(traceA->DumpToString(Trace::NO_FLAGS))); +} + +static void GenerateTraceEvents(int thread_id, + int num_events) { + for (int i = 0; i < num_events; i++) { + TRACE_EVENT1("test", "foo", "thread_id", thread_id); + } +} + +// Parse the dumped trace data and return the number of events +// found within, including only those with the "test" category. +int ParseAndReturnEventCount(const string& trace_json) { + Document d; + d.Parse<0>(trace_json.c_str()); + CHECK(d.IsObject()) << "bad json: " << trace_json; + const Value& events_json = d["traceEvents"]; + CHECK(events_json.IsArray()) << "bad json: " << trace_json; + + // Count how many of our events were seen. We have to filter out + // the metadata events. + int seen_real_events = 0; + for (int i = 0; i < events_json.Size(); i++) { + if (events_json[i]["cat"].GetString() == string("test")) { + seen_real_events++; + } + } + + return seen_real_events; +} + +TEST_F(TraceTest, TestChromeTracing) { + const int kNumThreads = 4; + const int kEventsPerThread = AllowSlowTests() ? 1000000 : 10000; + + TraceLog* tl = TraceLog::GetInstance(); + tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_CONTINUOUSLY); + + vector > threads(kNumThreads); + + Stopwatch s; + s.start(); + for (int i = 0; i < kNumThreads; i++) { + CHECK_OK(Thread::CreateWithFlags( + "test", "gen-traces", + [i, kEventsPerThread]() { GenerateTraceEvents(i, kEventsPerThread); }, + Thread::NO_STACK_WATCHDOG, &threads[i])); + } + + for (int i = 0; i < kNumThreads; i++) { + threads[i]->Join(); + } + tl->SetDisabled(); + + int total_events = kNumThreads * kEventsPerThread; + double elapsed = s.elapsed().wall_seconds(); + + LOG(INFO) << "Trace performance: " << static_cast(total_events / elapsed) << " traces/sec"; + + string trace_json = TraceResultBuffer::FlushTraceLogToString(); + + // Verify that the JSON contains events. It won't have exactly + // kEventsPerThread * kNumThreads because the trace buffer isn't large enough + // for that. + ASSERT_GE(ParseAndReturnEventCount(trace_json), 100); +} + +// Test that, if a thread exits before filling a full trace buffer, we still +// see its results. This is a regression test for a bug in the earlier integration +// of Chromium tracing into Kudu. +TEST_F(TraceTest, TestTraceFromExitedThread) { + TraceLog* tl = TraceLog::GetInstance(); + tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_CONTINUOUSLY); + + // Generate 10 trace events in a separate thread. + int kNumEvents = 10; + scoped_refptr t; + CHECK_OK(Thread::CreateWithFlags( + "test", "gen-traces", [kNumEvents]() { GenerateTraceEvents(1, kNumEvents); }, + Thread::NO_STACK_WATCHDOG, &t)); + t->Join(); + tl->SetDisabled(); + string trace_json = TraceResultBuffer::FlushTraceLogToString(); + LOG(INFO) << trace_json; + + // Verify that the buffer contains 10 trace events + ASSERT_EQ(10, ParseAndReturnEventCount(trace_json)); +} + +static void GenerateWideSpan() { + TRACE_EVENT0("test", "GenerateWideSpan"); + for (int i = 0; i < 1000; i++) { + TRACE_EVENT0("test", "InnerLoop"); + } +} + +// Test creating a trace event which contains many other trace events. +// This ensures that we can go back and update a TraceEvent which fell in +// a different trace chunk. +TEST_F(TraceTest, TestWideSpan) { + TraceLog* tl = TraceLog::GetInstance(); + tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_CONTINUOUSLY); + + scoped_refptr t; + CHECK_OK(Thread::CreateWithFlags( + "test", "gen-traces", &GenerateWideSpan, + Thread::NO_STACK_WATCHDOG, &t)); + t->Join(); + tl->SetDisabled(); + + string trace_json = TraceResultBuffer::FlushTraceLogToString(); + ASSERT_EQ(1001, ParseAndReturnEventCount(trace_json)); +} + +// Regression test for KUDU-753: faulty JSON escaping when dealing with +// single quote characters. +TEST_F(TraceTest, TestJsonEncodingString) { + TraceLog* tl = TraceLog::GetInstance(); + tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_CONTINUOUSLY); + { + TRACE_EVENT1("test", "test", "arg", "this is a test with \"'\"' and characters\nand new lines"); + } + tl->SetDisabled(); + string trace_json = TraceResultBuffer::FlushTraceLogToString(); + ASSERT_EQ(1, ParseAndReturnEventCount(trace_json)); +} + +// Generate trace events continuously until 'latch' fires. +// Increment *num_events_generated for each event generated. +void GenerateTracesUntilLatch(AtomicInt* num_events_generated, + CountDownLatch* latch) { + while (latch->count()) { + { + // This goes in its own scope so that the event is fully generated (with + // both its START and END times) before we do the counter increment below. + TRACE_EVENT0("test", "GenerateTracesUntilLatch"); + } + num_events_generated->Increment(); + } +} + +// Test starting and stopping tracing while a thread is running. +// This is a regression test for bugs in earlier versions of the imported +// trace code. +TEST_F(TraceTest, TestStartAndStopCollection) { + TraceLog* tl = TraceLog::GetInstance(); + + CountDownLatch latch(1); + AtomicInt num_events_generated(0); + scoped_refptr t; + CHECK_OK(Thread::CreateWithFlags( + "test", "gen-traces", + [&]() { GenerateTracesUntilLatch(&num_events_generated, &latch); }, + Thread::NO_STACK_WATCHDOG, &t)); + + const int num_flushes = AllowSlowTests() ? 50 : 3; + for (int i = 0; i < num_flushes; i++) { + tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_CONTINUOUSLY); + + const int64_t num_events_before = num_events_generated.Load(); + SleepFor(MonoDelta::FromMilliseconds(10)); + const int64_t num_events_after = num_events_generated.Load(); + tl->SetDisabled(); + + string trace_json = TraceResultBuffer::FlushTraceLogToString(); + // We might under-count the number of events, since we only measure the sleep, + // and tracing is enabled before and disabled after we start counting. + // We might also over-count by at most 1, because we could enable tracing + // right in between creating a trace event and incrementing the counter. + // But, we should never over-count by more than 1. + int expected_events_lowerbound = num_events_after - num_events_before - 1; + int captured_events = ParseAndReturnEventCount(trace_json); + ASSERT_GE(captured_events, expected_events_lowerbound); + } + + latch.CountDown(); + t->Join(); +} + +TEST_F(TraceTest, TestChromeSampling) { + TraceLog* tl = TraceLog::GetInstance(); + tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), + TraceLog::RECORDING_MODE, + static_cast(TraceLog::RECORD_CONTINUOUSLY | + TraceLog::ENABLE_SAMPLING)); + + for (int i = 0; i < 100; i++) { + switch (i % 3) { + case 0: + TRACE_EVENT_SET_SAMPLING_STATE("test", "state-0"); + break; + case 1: + TRACE_EVENT_SET_SAMPLING_STATE("test", "state-1"); + break; + case 2: + TRACE_EVENT_SET_SAMPLING_STATE("test", "state-2"); + break; + } + SleepFor(MonoDelta::FromMilliseconds(1)); + } + tl->SetDisabled(); + string trace_json = TraceResultBuffer::FlushTraceLogToString(); + ASSERT_GT(ParseAndReturnEventCount(trace_json), 0); +} + +class TraceEventCallbackTest : public KuduTest { + public: + virtual void SetUp() OVERRIDE { + KuduTest::SetUp(); + ASSERT_EQ(nullptr, s_instance); + s_instance = this; + } + virtual void TearDown() OVERRIDE { + TraceLog::GetInstance()->SetDisabled(); + + // Flush the buffer so that one test doesn't end up leaving any + // extra results for the next test. + TraceResultBuffer::FlushTraceLogToString(); + + ASSERT_TRUE(!!s_instance); + s_instance = nullptr; + KuduTest::TearDown(); + + } + + protected: + void EndTraceAndFlush() { + TraceLog::GetInstance()->SetDisabled(); + string trace_json = TraceResultBuffer::FlushTraceLogToString(); + trace_doc_.Parse<0>(trace_json.c_str()); + LOG(INFO) << trace_json; + ASSERT_TRUE(trace_doc_.IsObject()); + trace_parsed_ = trace_doc_["traceEvents"]; + ASSERT_TRUE(trace_parsed_.IsArray()); + } + + void DropTracedMetadataRecords() { + // NB: rapidjson has move-semantics, like auto_ptr. + Value old_trace_parsed; + old_trace_parsed = trace_parsed_; + trace_parsed_.SetArray(); + size_t old_trace_parsed_size = old_trace_parsed.Size(); + + for (size_t i = 0; i < old_trace_parsed_size; i++) { + Value value; + value = old_trace_parsed[i]; + if (value.GetType() != rapidjson::kObjectType) { + trace_parsed_.PushBack(value, trace_doc_.GetAllocator()); + continue; + } + string tmp; + if (value.HasMember("ph") && strcmp(value["ph"].GetString(), "M") == 0) { + continue; + } + + trace_parsed_.PushBack(value, trace_doc_.GetAllocator()); + } + } + + // Search through the given array for any dictionary which has a key + // or value which has 'string_to_match' as a substring. + // Returns the matching dictionary, or NULL. + static const Value* FindTraceEntry( + const Value& trace_parsed, + const char* string_to_match) { + // Scan all items + size_t trace_parsed_count = trace_parsed.Size(); + for (size_t i = 0; i < trace_parsed_count; i++) { + const Value& value = trace_parsed[i]; + if (value.GetType() != rapidjson::kObjectType) { + continue; + } + + for (Value::ConstMemberIterator it = value.MemberBegin(); + it != value.MemberEnd(); + ++it) { + if (it->name.IsString() && strstr(it->name.GetString(), string_to_match) != nullptr) { + return &value; + } + if (it->value.IsString() && strstr(it->value.GetString(), string_to_match) != nullptr) { + return &value; + } + } + } + return nullptr; + } + + // For TraceEventCallbackAndRecordingX tests. + void VerifyCallbackAndRecordedEvents(size_t expected_callback_count, + size_t expected_recorded_count) { + // Callback events. + EXPECT_EQ(expected_callback_count, collected_events_names_.size()); + for (size_t i = 0; i < collected_events_names_.size(); ++i) { + EXPECT_EQ("callback", collected_events_categories_[i]); + EXPECT_EQ("yes", collected_events_names_[i]); + } + + // Recorded events. + EXPECT_EQ(expected_recorded_count, trace_parsed_.Size()); + EXPECT_TRUE(FindTraceEntry(trace_parsed_, "recording")); + EXPECT_FALSE(FindTraceEntry(trace_parsed_, "callback")); + EXPECT_TRUE(FindTraceEntry(trace_parsed_, "yes")); + EXPECT_FALSE(FindTraceEntry(trace_parsed_, "no")); + } + + void VerifyCollectedEvent(size_t i, + unsigned phase, + const string& category, + const string& name) { + EXPECT_EQ(phase, collected_events_phases_[i]); + EXPECT_EQ(category, collected_events_categories_[i]); + EXPECT_EQ(name, collected_events_names_[i]); + } + + Document trace_doc_; + Value trace_parsed_; + + vector collected_events_categories_; + vector collected_events_names_; + vector collected_events_phases_; + vector collected_events_timestamps_; + + static TraceEventCallbackTest* s_instance; + static void Callback(MicrosecondsInt64 timestamp, + char phase, + const unsigned char* category_group_enabled, + const char* name, + uint64_t id, + int num_args, + const char* const arg_names[], + const unsigned char arg_types[], + const uint64_t arg_values[], + unsigned char flags) { + s_instance->collected_events_phases_.push_back(phase); + s_instance->collected_events_categories_.emplace_back( + TraceLog::GetCategoryGroupName(category_group_enabled)); + s_instance->collected_events_names_.emplace_back(name); + s_instance->collected_events_timestamps_.push_back(timestamp); + } +}; + +TraceEventCallbackTest* TraceEventCallbackTest::s_instance; + +TEST_F(TraceEventCallbackTest, TraceEventCallback) { + TRACE_EVENT_INSTANT0("all", "before enable", TRACE_EVENT_SCOPE_THREAD); + TraceLog::GetInstance()->SetEventCallbackEnabled( + CategoryFilter("*"), Callback); + TRACE_EVENT_INSTANT0("all", "event1", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("all", "event2", TRACE_EVENT_SCOPE_GLOBAL); + { + TRACE_EVENT0("all", "duration"); + TRACE_EVENT_INSTANT0("all", "event3", TRACE_EVENT_SCOPE_GLOBAL); + } + TraceLog::GetInstance()->SetEventCallbackDisabled(); + TRACE_EVENT_INSTANT0("all", "after callback removed", + TRACE_EVENT_SCOPE_GLOBAL); + ASSERT_EQ(5u, collected_events_names_.size()); + EXPECT_EQ("event1", collected_events_names_[0]); + EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[0]); + EXPECT_EQ("event2", collected_events_names_[1]); + EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[1]); + EXPECT_EQ("duration", collected_events_names_[2]); + EXPECT_EQ(TRACE_EVENT_PHASE_BEGIN, collected_events_phases_[2]); + EXPECT_EQ("event3", collected_events_names_[3]); + EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[3]); + EXPECT_EQ("duration", collected_events_names_[4]); + EXPECT_EQ(TRACE_EVENT_PHASE_END, collected_events_phases_[4]); + for (size_t i = 1; i < collected_events_timestamps_.size(); i++) { + EXPECT_LE(collected_events_timestamps_[i - 1], + collected_events_timestamps_[i]); + } +} + +TEST_F(TraceEventCallbackTest, TraceEventCallbackWhileFull) { + TraceLog::GetInstance()->SetEnabled( + CategoryFilter("*"), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_UNTIL_FULL); + do { + TRACE_EVENT_INSTANT0("all", "badger badger", TRACE_EVENT_SCOPE_GLOBAL); + } while (!TraceLog::GetInstance()->BufferIsFull()); + TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("*"), + Callback); + TRACE_EVENT_INSTANT0("all", "a snake", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEventCallbackDisabled(); + ASSERT_EQ(1u, collected_events_names_.size()); + EXPECT_EQ("a snake", collected_events_names_[0]); +} + +// 1: Enable callback, enable recording, disable callback, disable recording. +TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording1) { + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"), + Callback); + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEnabled( + CategoryFilter("recording"), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_UNTIL_FULL); + TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEventCallbackDisabled(); + TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + EndTraceAndFlush(); + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + + DropTracedMetadataRecords(); + NO_FATALS(); + VerifyCallbackAndRecordedEvents(2, 2); +} + +// 2: Enable callback, enable recording, disable recording, disable callback. +TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording2) { + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"), + Callback); + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEnabled( + CategoryFilter("recording"), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_UNTIL_FULL); + TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); + EndTraceAndFlush(); + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEventCallbackDisabled(); + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + + DropTracedMetadataRecords(); + VerifyCallbackAndRecordedEvents(3, 1); +} + +// 3: Enable recording, enable callback, disable callback, disable recording. +TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording3) { + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEnabled( + CategoryFilter("recording"), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_UNTIL_FULL); + TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"), + Callback); + TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEventCallbackDisabled(); + TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + EndTraceAndFlush(); + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + + DropTracedMetadataRecords(); + VerifyCallbackAndRecordedEvents(1, 3); +} + +// 4: Enable recording, enable callback, disable recording, disable callback. +TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording4) { + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEnabled( + CategoryFilter("recording"), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_UNTIL_FULL); + TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"), + Callback); + TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); + EndTraceAndFlush(); + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); + TraceLog::GetInstance()->SetEventCallbackDisabled(); + TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); + TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); + + DropTracedMetadataRecords(); + VerifyCallbackAndRecordedEvents(2, 2); +} + +TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecordingDuration) { + TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("*"), + Callback); + { + TRACE_EVENT0("callback", "duration1"); + TraceLog::GetInstance()->SetEnabled( + CategoryFilter("*"), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_UNTIL_FULL); + TRACE_EVENT0("callback", "duration2"); + EndTraceAndFlush(); + TRACE_EVENT0("callback", "duration3"); + } + TraceLog::GetInstance()->SetEventCallbackDisabled(); + + ASSERT_EQ(6u, collected_events_names_.size()); + VerifyCollectedEvent(0, TRACE_EVENT_PHASE_BEGIN, "callback", "duration1"); + VerifyCollectedEvent(1, TRACE_EVENT_PHASE_BEGIN, "callback", "duration2"); + VerifyCollectedEvent(2, TRACE_EVENT_PHASE_BEGIN, "callback", "duration3"); + VerifyCollectedEvent(3, TRACE_EVENT_PHASE_END, "callback", "duration3"); + VerifyCollectedEvent(4, TRACE_EVENT_PHASE_END, "callback", "duration2"); + VerifyCollectedEvent(5, TRACE_EVENT_PHASE_END, "callback", "duration1"); +} + +//////////////////////////////////////////////////////////// +// Tests for synthetic delay +// (from chromium-base/debug/trace_event_synthetic_delay_unittest.cc) +//////////////////////////////////////////////////////////// + +namespace { + +const int kTargetDurationMs = 100; +// Allow some leeway in timings to make it possible to run these tests with a +// wall clock time source too. +const int kShortDurationMs = 10; + +} // namespace + +namespace debug { + +class TraceEventSyntheticDelayTest : public KuduTest, + public TraceEventSyntheticDelayClock { + public: + TraceEventSyntheticDelayTest() { + now_ = MonoTime::Min(); + } + + virtual ~TraceEventSyntheticDelayTest() { + ResetTraceEventSyntheticDelays(); + } + + // TraceEventSyntheticDelayClock implementation. + virtual MonoTime Now() OVERRIDE { + AdvanceTime(MonoDelta::FromMilliseconds(kShortDurationMs / 10)); + return now_; + } + + TraceEventSyntheticDelay* ConfigureDelay(const char* name) { + TraceEventSyntheticDelay* delay = TraceEventSyntheticDelay::Lookup(name); + delay->SetClock(this); + delay->SetTargetDuration( + MonoDelta::FromMilliseconds(kTargetDurationMs)); + return delay; + } + + void AdvanceTime(MonoDelta delta) { now_ += delta; } + + int TestFunction() { + MonoTime start = Now(); + { TRACE_EVENT_SYNTHETIC_DELAY("test.Delay"); } + MonoTime end = Now(); + return (end - start).ToMilliseconds(); + } + + int AsyncTestFunctionBegin() { + MonoTime start = Now(); + { TRACE_EVENT_SYNTHETIC_DELAY_BEGIN("test.AsyncDelay"); } + MonoTime end = Now(); + return (end - start).ToMilliseconds(); + } + + int AsyncTestFunctionEnd() { + MonoTime start = Now(); + { TRACE_EVENT_SYNTHETIC_DELAY_END("test.AsyncDelay"); } + MonoTime end = Now(); + return (end - start).ToMilliseconds(); + } + + private: + MonoTime now_; + + DISALLOW_COPY_AND_ASSIGN(TraceEventSyntheticDelayTest); +}; + +TEST_F(TraceEventSyntheticDelayTest, StaticDelay) { + TraceEventSyntheticDelay* delay = ConfigureDelay("test.Delay"); + delay->SetMode(TraceEventSyntheticDelay::STATIC); + EXPECT_GE(TestFunction(), kTargetDurationMs); +} + +TEST_F(TraceEventSyntheticDelayTest, OneShotDelay) { + TraceEventSyntheticDelay* delay = ConfigureDelay("test.Delay"); + delay->SetMode(TraceEventSyntheticDelay::ONE_SHOT); + EXPECT_GE(TestFunction(), kTargetDurationMs); + EXPECT_LT(TestFunction(), kShortDurationMs); + + delay->SetTargetDuration( + MonoDelta::FromMilliseconds(kTargetDurationMs)); + EXPECT_GE(TestFunction(), kTargetDurationMs); +} + +TEST_F(TraceEventSyntheticDelayTest, AlternatingDelay) { + TraceEventSyntheticDelay* delay = ConfigureDelay("test.Delay"); + delay->SetMode(TraceEventSyntheticDelay::ALTERNATING); + EXPECT_GE(TestFunction(), kTargetDurationMs); + EXPECT_LT(TestFunction(), kShortDurationMs); + EXPECT_GE(TestFunction(), kTargetDurationMs); + EXPECT_LT(TestFunction(), kShortDurationMs); +} + +TEST_F(TraceEventSyntheticDelayTest, AsyncDelay) { + ConfigureDelay("test.AsyncDelay"); + EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); + EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2); +} + +TEST_F(TraceEventSyntheticDelayTest, AsyncDelayExceeded) { + ConfigureDelay("test.AsyncDelay"); + EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); + AdvanceTime(MonoDelta::FromMilliseconds(kTargetDurationMs)); + EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs); +} + +TEST_F(TraceEventSyntheticDelayTest, AsyncDelayNoActivation) { + ConfigureDelay("test.AsyncDelay"); + EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs); +} + +TEST_F(TraceEventSyntheticDelayTest, AsyncDelayNested) { + ConfigureDelay("test.AsyncDelay"); + EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); + EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); + EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs); + EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2); +} + +TEST_F(TraceEventSyntheticDelayTest, AsyncDelayUnbalanced) { + ConfigureDelay("test.AsyncDelay"); + EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); + EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2); + EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs); + + EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); + EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2); +} + +TEST_F(TraceEventSyntheticDelayTest, ResetDelays) { + ConfigureDelay("test.Delay"); + ResetTraceEventSyntheticDelays(); + EXPECT_LT(TestFunction(), kShortDurationMs); +} + +TEST_F(TraceEventSyntheticDelayTest, BeginParallel) { + TraceEventSyntheticDelay* delay = ConfigureDelay("test.AsyncDelay"); + MonoTime end_times[2]; + MonoTime start_time = Now(); + + delay->BeginParallel(&end_times[0]); + EXPECT_FALSE(!end_times[0].Initialized()); + + delay->BeginParallel(&end_times[1]); + EXPECT_FALSE(!end_times[1].Initialized()); + + delay->EndParallel(end_times[0]); + EXPECT_GE((Now() - start_time).ToMilliseconds(), kTargetDurationMs); + + start_time = Now(); + delay->EndParallel(end_times[1]); + EXPECT_LT((Now() - start_time).ToMilliseconds(), kShortDurationMs); +} + +TEST_F(TraceTest, TestVLogTrace) { + for (FLAGS_v = 0; FLAGS_v <= 1; FLAGS_v++) { + TraceLog* tl = TraceLog::GetInstance(); + tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_CONTINUOUSLY); + VLOG_AND_TRACE("test", 1) << "hello world"; + tl->SetDisabled(); + string trace_json = TraceResultBuffer::FlushTraceLogToString(); + ASSERT_STR_CONTAINS(trace_json, "hello world"); + ASSERT_STR_CONTAINS(trace_json, "trace-test.cc"); + } +} + +namespace { +string FunctionWithSideEffect(bool* b) { + *b = true; + return "function-result"; +} +} // anonymous namespace + +// Test that, if tracing is not enabled, a VLOG_AND_TRACE doesn't evaluate its +// arguments. +TEST_F(TraceTest, TestVLogTraceLazyEvaluation) { + FLAGS_v = 0; + bool function_run = false; + VLOG_AND_TRACE("test", 1) << FunctionWithSideEffect(&function_run); + ASSERT_FALSE(function_run); + + // If we enable verbose logging, we should run the side effect even though + // trace logging is disabled. + FLAGS_v = 1; + VLOG_AND_TRACE("test", 1) << FunctionWithSideEffect(&function_run); + ASSERT_TRUE(function_run); +} + +TEST_F(TraceTest, TestVLogAndEchoToConsole) { + TraceLog* tl = TraceLog::GetInstance(); + tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), + TraceLog::RECORDING_MODE, + TraceLog::ECHO_TO_CONSOLE); + FLAGS_v = 1; + VLOG_AND_TRACE("test", 1) << "hello world"; + tl->SetDisabled(); +} + +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); +} + +// Regression test for KUDU-2075: using tracing from vanilla threads +// should work fine, even if some pthread_self identifiers have been +// reused. +TEST_F(TraceTest, TestTraceFromVanillaThreads) { + TraceLog::GetInstance()->SetEnabled( + CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), + TraceLog::RECORDING_MODE, + TraceLog::RECORD_CONTINUOUSLY); + SCOPED_CLEANUP({ TraceLog::GetInstance()->SetDisabled(); }); + + // Do several passes to make it more likely that the thread identifiers + // will get reused. + for (int pass = 0; pass < 10; pass++) { + vector threads; + for (int i = 0; i < 100; i++) { + threads.emplace_back([i] { + GenerateTraceEvents(i, 1); + }); + } + for (auto& t : threads) { + t.join(); + } + } +} +} // namespace debug +} // namespace kudu From 840672391218d6dfe12a82c873404cd4aa57c423 Mon Sep 17 00:00:00 2001 From: Yingchun Lai <405403881@qq.com> Date: Tue, 12 May 2020 11:19:20 +0800 Subject: [PATCH 2/3] adapt to Doris --- be/src/common/logconfig.cpp | 20 + be/src/util/CMakeLists.txt | 2 + be/src/util/logging.h | 4 + be/src/util/trace.cpp | 57 +-- be/src/util/trace.h | 63 +-- be/src/util/trace_metrics.cpp | 12 +- be/src/util/trace_metrics.h | 18 +- be/test/util/CMakeLists.txt | 1 + be/test/util/trace_test.cpp | 802 +--------------------------------- 9 files changed, 130 insertions(+), 849 deletions(-) diff --git a/be/src/common/logconfig.cpp b/be/src/common/logconfig.cpp index bb5a18314b..fe054f14f5 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 index ac566601c5..f104f90e31 100644 --- a/be/src/util/trace.cpp +++ b/be/src/util/trace.cpp @@ -15,7 +15,7 @@ // specific language governing permissions and limitations // under the License. -#include "kudu/util/trace.h" +#include "util/trace.h" #include #include @@ -28,33 +28,30 @@ #include #include +#include -#include "kudu/gutil/strings/substitute.h" -#include "kudu/gutil/walltime.h" -#include "kudu/util/jsonwriter.h" -#include "kudu/util/logging.h" -#include "kudu/util/memory/arena.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 kudu { +namespace doris { __thread Trace* Trace::threadlocal_trace_; Trace::Trace() - : arena_(new ThreadSafeArena(1024)), + : // 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); -} - -Trace::~Trace() { + // arena_->SetMaxBufferSize(4096); } // Struct which precedes each entry in the trace. @@ -74,6 +71,14 @@ struct TraceEntry { } }; +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. @@ -107,7 +112,8 @@ void Trace::SubstituteAndTrace(const char* file_path, 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(arena_->AllocateBytes(size)); + uint8_t* dst = reinterpret_cast(malloc(size)); TraceEntry* entry = reinterpret_cast(dst); entry->timestamp_micros = GetCurrentTimeMicros(); entry->message_len = msg_len; @@ -117,7 +123,7 @@ TraceEntry* Trace::NewEntry(int msg_len, const char* file_path, int line_number) } void Trace::AddEntry(TraceEntry* entry) { - std::lock_guard l(lock_); + std::lock_guard l(lock_); entry->next = nullptr; if (entries_tail_ != nullptr) { @@ -137,7 +143,7 @@ void Trace::Dump(std::ostream* out, int flags) const { vector entries; vector>> child_traces; { - std::lock_guard l(lock_); + std::lock_guard l(lock_); for (TraceEntry* cur = entries_head_; cur != nullptr; cur = cur->next) { @@ -194,13 +200,14 @@ string Trace::DumpToString(int flags) const { } string Trace::MetricsAsJSON() const { - std::ostringstream s; - JsonWriter jw(&s, JsonWriter::COMPACT); + // TODO(yingchun): simplily implement here, we could import JsonWriter in the future. + rapidjson::StringBuffer buf; + rapidjson::Writer jw(buf); MetricsToJSON(&jw); - return s.str(); + return buf.GetString(); } -void Trace::MetricsToJSON(JsonWriter* jw) const { +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; @@ -210,12 +217,12 @@ void Trace::MetricsToJSON(JsonWriter* jw) const { jw->StartObject(); for (const auto& e : counters) { - jw->String(e.first); + jw->String(e.first.c_str()); jw->Int64(e.second); } vector>> child_traces; { - std::lock_guard l(lock_); + std::lock_guard l(lock_); child_traces = child_traces_; } @@ -244,16 +251,16 @@ void Trace::DumpCurrentTrace() { } void Trace::AddChildTrace(StringPiece label, Trace* child_trace) { - CHECK(arena_->RelocateStringPiece(label, &label)); + //CHECK(arena_->RelocateStringPiece(label, &label)); - std::lock_guard l(lock_); + 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_); + std::lock_guard l(lock_); return child_traces_; } -} // namespace kudu +} // namespace doris diff --git a/be/src/util/trace.h b/be/src/util/trace.h index c30e241dbe..397dbb5ac8 100644 --- a/be/src/util/trace.h +++ b/be/src/util/trace.h @@ -22,16 +22,18 @@ #include #include -#include "kudu/gutil/macros.h" -#include "kudu/gutil/strings/stringpiece.h" -#include "kudu/gutil/strings/substitute.h" -#include "kudu/gutil/ref_counted.h" -#include "kudu/gutil/threading/thread_collision_warner.h" -#include "kudu/gutil/walltime.h" -#include "kudu/util/locks.h" -#include "kudu/util/trace_metrics.h" +#include -namespace kudu { +#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; } @@ -39,7 +41,7 @@ class Trace; // scope. The old current Trace is restored when the scope is exited. // // 't' should be a Trace* pointer. -#define ADOPT_TRACE(t) kudu::ScopedAdoptTrace _adopt_trace(t); +#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. @@ -47,7 +49,7 @@ class Trace; // TRACE("Acquired timestamp $0", timestamp); #define TRACE(format, substitutions...) \ do { \ - kudu::Trace* _trace = kudu::Trace::CurrentTrace(); \ + doris::Trace* _trace = doris::Trace::CurrentTrace(); \ if (_trace) { \ _trace->SubstituteAndTrace(__FILE__, __LINE__, (format), \ ##substitutions); \ @@ -77,7 +79,7 @@ class Trace; // parameters. #define TRACE_COUNTER_INCREMENT(counter_name, val) \ do { \ - kudu::Trace* _trace = kudu::Trace::CurrentTrace(); \ + doris::Trace* _trace = doris::Trace::CurrentTrace(); \ if (_trace) { \ _trace->metrics()->Increment(counter_name, val); \ } \ @@ -94,7 +96,7 @@ class Trace; // will result in a trace metric indicating the number of microseconds spent // in invocations of DoFoo(). #define TRACE_COUNTER_SCOPE_LATENCY_US(counter_name) \ - ::kudu::ScopedTraceLatencyCounter _scoped_latency(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. @@ -111,10 +113,8 @@ class Trace; } \ }() -namespace kudu { +namespace doris { -class JsonWriter; -class ThreadSafeArena; struct TraceEntry; // A trace for a request or other process. This supports collecting trace entries @@ -138,25 +138,25 @@ class Trace : public RefCountedThreadSafe { void SubstituteAndTrace(const char* filepath, int line_number, StringPiece format, const strings::internal::SubstituteArg& arg0 = - strings::internal::SubstituteArg::kNoArg, + strings::internal::SubstituteArg::NoArg, const strings::internal::SubstituteArg& arg1 = - strings::internal::SubstituteArg::kNoArg, + strings::internal::SubstituteArg::NoArg, const strings::internal::SubstituteArg& arg2 = - strings::internal::SubstituteArg::kNoArg, + strings::internal::SubstituteArg::NoArg, const strings::internal::SubstituteArg& arg3 = - strings::internal::SubstituteArg::kNoArg, + strings::internal::SubstituteArg::NoArg, const strings::internal::SubstituteArg& arg4 = - strings::internal::SubstituteArg::kNoArg, + strings::internal::SubstituteArg::NoArg, const strings::internal::SubstituteArg& arg5 = - strings::internal::SubstituteArg::kNoArg, + strings::internal::SubstituteArg::NoArg, const strings::internal::SubstituteArg& arg6 = - strings::internal::SubstituteArg::kNoArg, + strings::internal::SubstituteArg::NoArg, const strings::internal::SubstituteArg& arg7 = - strings::internal::SubstituteArg::kNoArg, + strings::internal::SubstituteArg::NoArg, const strings::internal::SubstituteArg& arg8 = - strings::internal::SubstituteArg::kNoArg, + strings::internal::SubstituteArg::NoArg, const strings::internal::SubstituteArg& arg9 = - strings::internal::SubstituteArg::kNoArg); + strings::internal::SubstituteArg::NoArg); // Dump the trace buffer to the given output stream. // @@ -194,7 +194,7 @@ class Trace : public RefCountedThreadSafe { // Simple function to dump the current trace to stderr, if one is // available. This is meant for usage when debugging in gdb via - // 'call kudu::Trace::DumpCurrentTrace();'. + // 'call doris::Trace::DumpCurrentTrace();'. static void DumpCurrentTrace(); TraceMetrics* metrics() { @@ -221,12 +221,13 @@ class Trace : public RefCountedThreadSafe { // Add the entry to the linked list of entries. void AddEntry(TraceEntry* entry); - void MetricsToJSON(JsonWriter* jw) const; + void MetricsToJSON(rapidjson::Writer* jw) const; - std::unique_ptr arena_; + // 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 simple_spinlock lock_; + 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_) @@ -287,4 +288,4 @@ class ScopedTraceLatencyCounter { DISALLOW_COPY_AND_ASSIGN(ScopedTraceLatencyCounter); }; -} // namespace kudu +} // namespace doris diff --git a/be/src/util/trace_metrics.cpp b/be/src/util/trace_metrics.cpp index 565a6e8e46..07be09f857 100644 --- a/be/src/util/trace_metrics.cpp +++ b/be/src/util/trace_metrics.cpp @@ -15,7 +15,7 @@ // specific language governing permissions and limitations // under the License. -#include "kudu/util/trace_metrics.h" +#include "util/trace_metrics.h" #include #include @@ -29,18 +29,18 @@ #include #include -#include "kudu/util/debug/leakcheck_disabler.h" +#include "util/debug/leakcheck_disabler.h" using std::string; -namespace kudu { +namespace doris { // Make glog's STL-compatible operators visible inside this namespace. using ::operator<<; namespace { -static simple_spinlock g_intern_map_lock; +static SpinLock g_intern_map_lock; typedef std::map InternMap; static InternMap* g_intern_map; @@ -51,7 +51,7 @@ const char* TraceMetrics::InternName(const string& name) { << "not printable: " << name; debug::ScopedLeakCheckDisabler no_leakcheck; - std::lock_guard l(g_intern_map_lock); + std::lock_guard l(g_intern_map_lock); if (g_intern_map == nullptr) { g_intern_map = new InternMap(); } @@ -71,4 +71,4 @@ const char* TraceMetrics::InternName(const string& name) { return dup; } -} // namespace kudu +} // namespace doris diff --git a/be/src/util/trace_metrics.h b/be/src/util/trace_metrics.h index 8c460bd2cf..7c3f440820 100644 --- a/be/src/util/trace_metrics.h +++ b/be/src/util/trace_metrics.h @@ -21,11 +21,11 @@ #include #include -#include "kudu/gutil/macros.h" -#include "kudu/gutil/map-util.h" -#include "kudu/util/locks.h" +#include "gutil/macros.h" +#include "gutil/map-util.h" +#include "util/spinlock.h" -namespace kudu { +namespace doris { // A simple map of constant string names to integer counters. // @@ -65,25 +65,25 @@ class TraceMetrics { int64_t GetMetric(const char* name) const; private: - mutable simple_spinlock lock_; + 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_); + std::lock_guard l(lock_); counters_[name] += amount; } inline std::map TraceMetrics::Get() const { - std::unique_lock l(lock_); + std::unique_lock l(lock_); return counters_; } inline int64_t TraceMetrics::GetMetric(const char* name) const { - std::lock_guard l(lock_); + std::lock_guard l(lock_); return FindWithDefault(counters_, name, 0); } -} // namespace kudu +} // 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 index 4e97c6328b..0d5a9540eb 100644 --- a/be/test/util/trace_test.cpp +++ b/be/test/util/trace_test.cpp @@ -15,7 +15,7 @@ // specific language governing permissions and limitations // under the License. -#include "kudu/util/trace.h" +#include "util/trace.h" #include #include @@ -32,37 +32,26 @@ #include #include -#include "kudu/gutil/macros.h" -#include "kudu/gutil/port.h" -#include "kudu/gutil/ref_counted.h" -#include "kudu/gutil/walltime.h" -#include "kudu/util/atomic.h" -#include "kudu/util/countdown_latch.h" -#include "kudu/util/debug/trace_event.h" -#include "kudu/util/debug/trace_event_impl.h" -#include "kudu/util/debug/trace_event_synthetic_delay.h" -#include "kudu/util/debug/trace_logging.h" -#include "kudu/util/monotime.h" -#include "kudu/util/scoped_cleanup.h" -#include "kudu/util/status.h" -#include "kudu/util/stopwatch.h" -#include "kudu/util/test_macros.h" -#include "kudu/util/test_util.h" -#include "kudu/util/thread.h" -#include "kudu/util/trace_metrics.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 kudu::debug::TraceLog; -using kudu::debug::TraceResultBuffer; -using kudu::debug::CategoryFilter; using rapidjson::Document; using rapidjson::Value; using std::string; using std::thread; using std::vector; -namespace kudu { +namespace doris { -class TraceTest : public KuduTest { +class TraceTest : public ::testing::Test { }; // Replace all digits in 's' with the character 'X'. @@ -85,8 +74,8 @@ TEST_F(TraceTest, TestBasic) { 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.cc:XX] hello world, XXXXX\n" - "XXXX XX:XX:XX.XXXXXX trace-test.cc:XX] goodbye cruel world, XXXXX\n", + 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); } @@ -107,9 +96,9 @@ TEST_F(TraceTest, TestAttach) { EXPECT_TRUE(Trace::CurrentTrace() == nullptr); TRACE("this goes nowhere"); - EXPECT_EQ("XXXX XX:XX:XX.XXXXXX trace-test.cc:XXX] hello from traceA\n", + 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.cc:XXX] hello from traceB\n", + EXPECT_EQ("XXXX XX:XX:XX.XXXXXX trace_test.cpp:XX] hello from traceB\n", XOutDigits(traceB->DumpToString(Trace::NO_FLAGS))); } @@ -123,736 +112,12 @@ TEST_F(TraceTest, TestChildTrace) { ADOPT_TRACE(traceB.get()); TRACE("hello from traceB"); } - EXPECT_EQ("XXXX XX:XX:XX.XXXXXX trace-test.cc:XXX] hello from traceA\n" + 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.cc:XXX] hello from traceB\n", + "XXXX XX:XX:XX.XXXXXX trace_test.cpp:XXX] hello from traceB\n", XOutDigits(traceA->DumpToString(Trace::NO_FLAGS))); } -static void GenerateTraceEvents(int thread_id, - int num_events) { - for (int i = 0; i < num_events; i++) { - TRACE_EVENT1("test", "foo", "thread_id", thread_id); - } -} - -// Parse the dumped trace data and return the number of events -// found within, including only those with the "test" category. -int ParseAndReturnEventCount(const string& trace_json) { - Document d; - d.Parse<0>(trace_json.c_str()); - CHECK(d.IsObject()) << "bad json: " << trace_json; - const Value& events_json = d["traceEvents"]; - CHECK(events_json.IsArray()) << "bad json: " << trace_json; - - // Count how many of our events were seen. We have to filter out - // the metadata events. - int seen_real_events = 0; - for (int i = 0; i < events_json.Size(); i++) { - if (events_json[i]["cat"].GetString() == string("test")) { - seen_real_events++; - } - } - - return seen_real_events; -} - -TEST_F(TraceTest, TestChromeTracing) { - const int kNumThreads = 4; - const int kEventsPerThread = AllowSlowTests() ? 1000000 : 10000; - - TraceLog* tl = TraceLog::GetInstance(); - tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_CONTINUOUSLY); - - vector > threads(kNumThreads); - - Stopwatch s; - s.start(); - for (int i = 0; i < kNumThreads; i++) { - CHECK_OK(Thread::CreateWithFlags( - "test", "gen-traces", - [i, kEventsPerThread]() { GenerateTraceEvents(i, kEventsPerThread); }, - Thread::NO_STACK_WATCHDOG, &threads[i])); - } - - for (int i = 0; i < kNumThreads; i++) { - threads[i]->Join(); - } - tl->SetDisabled(); - - int total_events = kNumThreads * kEventsPerThread; - double elapsed = s.elapsed().wall_seconds(); - - LOG(INFO) << "Trace performance: " << static_cast(total_events / elapsed) << " traces/sec"; - - string trace_json = TraceResultBuffer::FlushTraceLogToString(); - - // Verify that the JSON contains events. It won't have exactly - // kEventsPerThread * kNumThreads because the trace buffer isn't large enough - // for that. - ASSERT_GE(ParseAndReturnEventCount(trace_json), 100); -} - -// Test that, if a thread exits before filling a full trace buffer, we still -// see its results. This is a regression test for a bug in the earlier integration -// of Chromium tracing into Kudu. -TEST_F(TraceTest, TestTraceFromExitedThread) { - TraceLog* tl = TraceLog::GetInstance(); - tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_CONTINUOUSLY); - - // Generate 10 trace events in a separate thread. - int kNumEvents = 10; - scoped_refptr t; - CHECK_OK(Thread::CreateWithFlags( - "test", "gen-traces", [kNumEvents]() { GenerateTraceEvents(1, kNumEvents); }, - Thread::NO_STACK_WATCHDOG, &t)); - t->Join(); - tl->SetDisabled(); - string trace_json = TraceResultBuffer::FlushTraceLogToString(); - LOG(INFO) << trace_json; - - // Verify that the buffer contains 10 trace events - ASSERT_EQ(10, ParseAndReturnEventCount(trace_json)); -} - -static void GenerateWideSpan() { - TRACE_EVENT0("test", "GenerateWideSpan"); - for (int i = 0; i < 1000; i++) { - TRACE_EVENT0("test", "InnerLoop"); - } -} - -// Test creating a trace event which contains many other trace events. -// This ensures that we can go back and update a TraceEvent which fell in -// a different trace chunk. -TEST_F(TraceTest, TestWideSpan) { - TraceLog* tl = TraceLog::GetInstance(); - tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_CONTINUOUSLY); - - scoped_refptr t; - CHECK_OK(Thread::CreateWithFlags( - "test", "gen-traces", &GenerateWideSpan, - Thread::NO_STACK_WATCHDOG, &t)); - t->Join(); - tl->SetDisabled(); - - string trace_json = TraceResultBuffer::FlushTraceLogToString(); - ASSERT_EQ(1001, ParseAndReturnEventCount(trace_json)); -} - -// Regression test for KUDU-753: faulty JSON escaping when dealing with -// single quote characters. -TEST_F(TraceTest, TestJsonEncodingString) { - TraceLog* tl = TraceLog::GetInstance(); - tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_CONTINUOUSLY); - { - TRACE_EVENT1("test", "test", "arg", "this is a test with \"'\"' and characters\nand new lines"); - } - tl->SetDisabled(); - string trace_json = TraceResultBuffer::FlushTraceLogToString(); - ASSERT_EQ(1, ParseAndReturnEventCount(trace_json)); -} - -// Generate trace events continuously until 'latch' fires. -// Increment *num_events_generated for each event generated. -void GenerateTracesUntilLatch(AtomicInt* num_events_generated, - CountDownLatch* latch) { - while (latch->count()) { - { - // This goes in its own scope so that the event is fully generated (with - // both its START and END times) before we do the counter increment below. - TRACE_EVENT0("test", "GenerateTracesUntilLatch"); - } - num_events_generated->Increment(); - } -} - -// Test starting and stopping tracing while a thread is running. -// This is a regression test for bugs in earlier versions of the imported -// trace code. -TEST_F(TraceTest, TestStartAndStopCollection) { - TraceLog* tl = TraceLog::GetInstance(); - - CountDownLatch latch(1); - AtomicInt num_events_generated(0); - scoped_refptr t; - CHECK_OK(Thread::CreateWithFlags( - "test", "gen-traces", - [&]() { GenerateTracesUntilLatch(&num_events_generated, &latch); }, - Thread::NO_STACK_WATCHDOG, &t)); - - const int num_flushes = AllowSlowTests() ? 50 : 3; - for (int i = 0; i < num_flushes; i++) { - tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_CONTINUOUSLY); - - const int64_t num_events_before = num_events_generated.Load(); - SleepFor(MonoDelta::FromMilliseconds(10)); - const int64_t num_events_after = num_events_generated.Load(); - tl->SetDisabled(); - - string trace_json = TraceResultBuffer::FlushTraceLogToString(); - // We might under-count the number of events, since we only measure the sleep, - // and tracing is enabled before and disabled after we start counting. - // We might also over-count by at most 1, because we could enable tracing - // right in between creating a trace event and incrementing the counter. - // But, we should never over-count by more than 1. - int expected_events_lowerbound = num_events_after - num_events_before - 1; - int captured_events = ParseAndReturnEventCount(trace_json); - ASSERT_GE(captured_events, expected_events_lowerbound); - } - - latch.CountDown(); - t->Join(); -} - -TEST_F(TraceTest, TestChromeSampling) { - TraceLog* tl = TraceLog::GetInstance(); - tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), - TraceLog::RECORDING_MODE, - static_cast(TraceLog::RECORD_CONTINUOUSLY | - TraceLog::ENABLE_SAMPLING)); - - for (int i = 0; i < 100; i++) { - switch (i % 3) { - case 0: - TRACE_EVENT_SET_SAMPLING_STATE("test", "state-0"); - break; - case 1: - TRACE_EVENT_SET_SAMPLING_STATE("test", "state-1"); - break; - case 2: - TRACE_EVENT_SET_SAMPLING_STATE("test", "state-2"); - break; - } - SleepFor(MonoDelta::FromMilliseconds(1)); - } - tl->SetDisabled(); - string trace_json = TraceResultBuffer::FlushTraceLogToString(); - ASSERT_GT(ParseAndReturnEventCount(trace_json), 0); -} - -class TraceEventCallbackTest : public KuduTest { - public: - virtual void SetUp() OVERRIDE { - KuduTest::SetUp(); - ASSERT_EQ(nullptr, s_instance); - s_instance = this; - } - virtual void TearDown() OVERRIDE { - TraceLog::GetInstance()->SetDisabled(); - - // Flush the buffer so that one test doesn't end up leaving any - // extra results for the next test. - TraceResultBuffer::FlushTraceLogToString(); - - ASSERT_TRUE(!!s_instance); - s_instance = nullptr; - KuduTest::TearDown(); - - } - - protected: - void EndTraceAndFlush() { - TraceLog::GetInstance()->SetDisabled(); - string trace_json = TraceResultBuffer::FlushTraceLogToString(); - trace_doc_.Parse<0>(trace_json.c_str()); - LOG(INFO) << trace_json; - ASSERT_TRUE(trace_doc_.IsObject()); - trace_parsed_ = trace_doc_["traceEvents"]; - ASSERT_TRUE(trace_parsed_.IsArray()); - } - - void DropTracedMetadataRecords() { - // NB: rapidjson has move-semantics, like auto_ptr. - Value old_trace_parsed; - old_trace_parsed = trace_parsed_; - trace_parsed_.SetArray(); - size_t old_trace_parsed_size = old_trace_parsed.Size(); - - for (size_t i = 0; i < old_trace_parsed_size; i++) { - Value value; - value = old_trace_parsed[i]; - if (value.GetType() != rapidjson::kObjectType) { - trace_parsed_.PushBack(value, trace_doc_.GetAllocator()); - continue; - } - string tmp; - if (value.HasMember("ph") && strcmp(value["ph"].GetString(), "M") == 0) { - continue; - } - - trace_parsed_.PushBack(value, trace_doc_.GetAllocator()); - } - } - - // Search through the given array for any dictionary which has a key - // or value which has 'string_to_match' as a substring. - // Returns the matching dictionary, or NULL. - static const Value* FindTraceEntry( - const Value& trace_parsed, - const char* string_to_match) { - // Scan all items - size_t trace_parsed_count = trace_parsed.Size(); - for (size_t i = 0; i < trace_parsed_count; i++) { - const Value& value = trace_parsed[i]; - if (value.GetType() != rapidjson::kObjectType) { - continue; - } - - for (Value::ConstMemberIterator it = value.MemberBegin(); - it != value.MemberEnd(); - ++it) { - if (it->name.IsString() && strstr(it->name.GetString(), string_to_match) != nullptr) { - return &value; - } - if (it->value.IsString() && strstr(it->value.GetString(), string_to_match) != nullptr) { - return &value; - } - } - } - return nullptr; - } - - // For TraceEventCallbackAndRecordingX tests. - void VerifyCallbackAndRecordedEvents(size_t expected_callback_count, - size_t expected_recorded_count) { - // Callback events. - EXPECT_EQ(expected_callback_count, collected_events_names_.size()); - for (size_t i = 0; i < collected_events_names_.size(); ++i) { - EXPECT_EQ("callback", collected_events_categories_[i]); - EXPECT_EQ("yes", collected_events_names_[i]); - } - - // Recorded events. - EXPECT_EQ(expected_recorded_count, trace_parsed_.Size()); - EXPECT_TRUE(FindTraceEntry(trace_parsed_, "recording")); - EXPECT_FALSE(FindTraceEntry(trace_parsed_, "callback")); - EXPECT_TRUE(FindTraceEntry(trace_parsed_, "yes")); - EXPECT_FALSE(FindTraceEntry(trace_parsed_, "no")); - } - - void VerifyCollectedEvent(size_t i, - unsigned phase, - const string& category, - const string& name) { - EXPECT_EQ(phase, collected_events_phases_[i]); - EXPECT_EQ(category, collected_events_categories_[i]); - EXPECT_EQ(name, collected_events_names_[i]); - } - - Document trace_doc_; - Value trace_parsed_; - - vector collected_events_categories_; - vector collected_events_names_; - vector collected_events_phases_; - vector collected_events_timestamps_; - - static TraceEventCallbackTest* s_instance; - static void Callback(MicrosecondsInt64 timestamp, - char phase, - const unsigned char* category_group_enabled, - const char* name, - uint64_t id, - int num_args, - const char* const arg_names[], - const unsigned char arg_types[], - const uint64_t arg_values[], - unsigned char flags) { - s_instance->collected_events_phases_.push_back(phase); - s_instance->collected_events_categories_.emplace_back( - TraceLog::GetCategoryGroupName(category_group_enabled)); - s_instance->collected_events_names_.emplace_back(name); - s_instance->collected_events_timestamps_.push_back(timestamp); - } -}; - -TraceEventCallbackTest* TraceEventCallbackTest::s_instance; - -TEST_F(TraceEventCallbackTest, TraceEventCallback) { - TRACE_EVENT_INSTANT0("all", "before enable", TRACE_EVENT_SCOPE_THREAD); - TraceLog::GetInstance()->SetEventCallbackEnabled( - CategoryFilter("*"), Callback); - TRACE_EVENT_INSTANT0("all", "event1", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("all", "event2", TRACE_EVENT_SCOPE_GLOBAL); - { - TRACE_EVENT0("all", "duration"); - TRACE_EVENT_INSTANT0("all", "event3", TRACE_EVENT_SCOPE_GLOBAL); - } - TraceLog::GetInstance()->SetEventCallbackDisabled(); - TRACE_EVENT_INSTANT0("all", "after callback removed", - TRACE_EVENT_SCOPE_GLOBAL); - ASSERT_EQ(5u, collected_events_names_.size()); - EXPECT_EQ("event1", collected_events_names_[0]); - EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[0]); - EXPECT_EQ("event2", collected_events_names_[1]); - EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[1]); - EXPECT_EQ("duration", collected_events_names_[2]); - EXPECT_EQ(TRACE_EVENT_PHASE_BEGIN, collected_events_phases_[2]); - EXPECT_EQ("event3", collected_events_names_[3]); - EXPECT_EQ(TRACE_EVENT_PHASE_INSTANT, collected_events_phases_[3]); - EXPECT_EQ("duration", collected_events_names_[4]); - EXPECT_EQ(TRACE_EVENT_PHASE_END, collected_events_phases_[4]); - for (size_t i = 1; i < collected_events_timestamps_.size(); i++) { - EXPECT_LE(collected_events_timestamps_[i - 1], - collected_events_timestamps_[i]); - } -} - -TEST_F(TraceEventCallbackTest, TraceEventCallbackWhileFull) { - TraceLog::GetInstance()->SetEnabled( - CategoryFilter("*"), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_UNTIL_FULL); - do { - TRACE_EVENT_INSTANT0("all", "badger badger", TRACE_EVENT_SCOPE_GLOBAL); - } while (!TraceLog::GetInstance()->BufferIsFull()); - TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("*"), - Callback); - TRACE_EVENT_INSTANT0("all", "a snake", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEventCallbackDisabled(); - ASSERT_EQ(1u, collected_events_names_.size()); - EXPECT_EQ("a snake", collected_events_names_[0]); -} - -// 1: Enable callback, enable recording, disable callback, disable recording. -TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording1) { - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"), - Callback); - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEnabled( - CategoryFilter("recording"), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_UNTIL_FULL); - TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEventCallbackDisabled(); - TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - EndTraceAndFlush(); - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - - DropTracedMetadataRecords(); - NO_FATALS(); - VerifyCallbackAndRecordedEvents(2, 2); -} - -// 2: Enable callback, enable recording, disable recording, disable callback. -TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording2) { - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"), - Callback); - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEnabled( - CategoryFilter("recording"), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_UNTIL_FULL); - TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); - EndTraceAndFlush(); - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEventCallbackDisabled(); - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - - DropTracedMetadataRecords(); - VerifyCallbackAndRecordedEvents(3, 1); -} - -// 3: Enable recording, enable callback, disable callback, disable recording. -TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording3) { - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEnabled( - CategoryFilter("recording"), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_UNTIL_FULL); - TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"), - Callback); - TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEventCallbackDisabled(); - TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - EndTraceAndFlush(); - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - - DropTracedMetadataRecords(); - VerifyCallbackAndRecordedEvents(1, 3); -} - -// 4: Enable recording, enable callback, disable recording, disable callback. -TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecording4) { - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEnabled( - CategoryFilter("recording"), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_UNTIL_FULL); - TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("callback"), - Callback); - TRACE_EVENT_INSTANT0("recording", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); - EndTraceAndFlush(); - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "yes", TRACE_EVENT_SCOPE_GLOBAL); - TraceLog::GetInstance()->SetEventCallbackDisabled(); - TRACE_EVENT_INSTANT0("recording", "no", TRACE_EVENT_SCOPE_GLOBAL); - TRACE_EVENT_INSTANT0("callback", "no", TRACE_EVENT_SCOPE_GLOBAL); - - DropTracedMetadataRecords(); - VerifyCallbackAndRecordedEvents(2, 2); -} - -TEST_F(TraceEventCallbackTest, TraceEventCallbackAndRecordingDuration) { - TraceLog::GetInstance()->SetEventCallbackEnabled(CategoryFilter("*"), - Callback); - { - TRACE_EVENT0("callback", "duration1"); - TraceLog::GetInstance()->SetEnabled( - CategoryFilter("*"), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_UNTIL_FULL); - TRACE_EVENT0("callback", "duration2"); - EndTraceAndFlush(); - TRACE_EVENT0("callback", "duration3"); - } - TraceLog::GetInstance()->SetEventCallbackDisabled(); - - ASSERT_EQ(6u, collected_events_names_.size()); - VerifyCollectedEvent(0, TRACE_EVENT_PHASE_BEGIN, "callback", "duration1"); - VerifyCollectedEvent(1, TRACE_EVENT_PHASE_BEGIN, "callback", "duration2"); - VerifyCollectedEvent(2, TRACE_EVENT_PHASE_BEGIN, "callback", "duration3"); - VerifyCollectedEvent(3, TRACE_EVENT_PHASE_END, "callback", "duration3"); - VerifyCollectedEvent(4, TRACE_EVENT_PHASE_END, "callback", "duration2"); - VerifyCollectedEvent(5, TRACE_EVENT_PHASE_END, "callback", "duration1"); -} - -//////////////////////////////////////////////////////////// -// Tests for synthetic delay -// (from chromium-base/debug/trace_event_synthetic_delay_unittest.cc) -//////////////////////////////////////////////////////////// - -namespace { - -const int kTargetDurationMs = 100; -// Allow some leeway in timings to make it possible to run these tests with a -// wall clock time source too. -const int kShortDurationMs = 10; - -} // namespace - -namespace debug { - -class TraceEventSyntheticDelayTest : public KuduTest, - public TraceEventSyntheticDelayClock { - public: - TraceEventSyntheticDelayTest() { - now_ = MonoTime::Min(); - } - - virtual ~TraceEventSyntheticDelayTest() { - ResetTraceEventSyntheticDelays(); - } - - // TraceEventSyntheticDelayClock implementation. - virtual MonoTime Now() OVERRIDE { - AdvanceTime(MonoDelta::FromMilliseconds(kShortDurationMs / 10)); - return now_; - } - - TraceEventSyntheticDelay* ConfigureDelay(const char* name) { - TraceEventSyntheticDelay* delay = TraceEventSyntheticDelay::Lookup(name); - delay->SetClock(this); - delay->SetTargetDuration( - MonoDelta::FromMilliseconds(kTargetDurationMs)); - return delay; - } - - void AdvanceTime(MonoDelta delta) { now_ += delta; } - - int TestFunction() { - MonoTime start = Now(); - { TRACE_EVENT_SYNTHETIC_DELAY("test.Delay"); } - MonoTime end = Now(); - return (end - start).ToMilliseconds(); - } - - int AsyncTestFunctionBegin() { - MonoTime start = Now(); - { TRACE_EVENT_SYNTHETIC_DELAY_BEGIN("test.AsyncDelay"); } - MonoTime end = Now(); - return (end - start).ToMilliseconds(); - } - - int AsyncTestFunctionEnd() { - MonoTime start = Now(); - { TRACE_EVENT_SYNTHETIC_DELAY_END("test.AsyncDelay"); } - MonoTime end = Now(); - return (end - start).ToMilliseconds(); - } - - private: - MonoTime now_; - - DISALLOW_COPY_AND_ASSIGN(TraceEventSyntheticDelayTest); -}; - -TEST_F(TraceEventSyntheticDelayTest, StaticDelay) { - TraceEventSyntheticDelay* delay = ConfigureDelay("test.Delay"); - delay->SetMode(TraceEventSyntheticDelay::STATIC); - EXPECT_GE(TestFunction(), kTargetDurationMs); -} - -TEST_F(TraceEventSyntheticDelayTest, OneShotDelay) { - TraceEventSyntheticDelay* delay = ConfigureDelay("test.Delay"); - delay->SetMode(TraceEventSyntheticDelay::ONE_SHOT); - EXPECT_GE(TestFunction(), kTargetDurationMs); - EXPECT_LT(TestFunction(), kShortDurationMs); - - delay->SetTargetDuration( - MonoDelta::FromMilliseconds(kTargetDurationMs)); - EXPECT_GE(TestFunction(), kTargetDurationMs); -} - -TEST_F(TraceEventSyntheticDelayTest, AlternatingDelay) { - TraceEventSyntheticDelay* delay = ConfigureDelay("test.Delay"); - delay->SetMode(TraceEventSyntheticDelay::ALTERNATING); - EXPECT_GE(TestFunction(), kTargetDurationMs); - EXPECT_LT(TestFunction(), kShortDurationMs); - EXPECT_GE(TestFunction(), kTargetDurationMs); - EXPECT_LT(TestFunction(), kShortDurationMs); -} - -TEST_F(TraceEventSyntheticDelayTest, AsyncDelay) { - ConfigureDelay("test.AsyncDelay"); - EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); - EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2); -} - -TEST_F(TraceEventSyntheticDelayTest, AsyncDelayExceeded) { - ConfigureDelay("test.AsyncDelay"); - EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); - AdvanceTime(MonoDelta::FromMilliseconds(kTargetDurationMs)); - EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs); -} - -TEST_F(TraceEventSyntheticDelayTest, AsyncDelayNoActivation) { - ConfigureDelay("test.AsyncDelay"); - EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs); -} - -TEST_F(TraceEventSyntheticDelayTest, AsyncDelayNested) { - ConfigureDelay("test.AsyncDelay"); - EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); - EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); - EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs); - EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2); -} - -TEST_F(TraceEventSyntheticDelayTest, AsyncDelayUnbalanced) { - ConfigureDelay("test.AsyncDelay"); - EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); - EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2); - EXPECT_LT(AsyncTestFunctionEnd(), kShortDurationMs); - - EXPECT_LT(AsyncTestFunctionBegin(), kShortDurationMs); - EXPECT_GE(AsyncTestFunctionEnd(), kTargetDurationMs / 2); -} - -TEST_F(TraceEventSyntheticDelayTest, ResetDelays) { - ConfigureDelay("test.Delay"); - ResetTraceEventSyntheticDelays(); - EXPECT_LT(TestFunction(), kShortDurationMs); -} - -TEST_F(TraceEventSyntheticDelayTest, BeginParallel) { - TraceEventSyntheticDelay* delay = ConfigureDelay("test.AsyncDelay"); - MonoTime end_times[2]; - MonoTime start_time = Now(); - - delay->BeginParallel(&end_times[0]); - EXPECT_FALSE(!end_times[0].Initialized()); - - delay->BeginParallel(&end_times[1]); - EXPECT_FALSE(!end_times[1].Initialized()); - - delay->EndParallel(end_times[0]); - EXPECT_GE((Now() - start_time).ToMilliseconds(), kTargetDurationMs); - - start_time = Now(); - delay->EndParallel(end_times[1]); - EXPECT_LT((Now() - start_time).ToMilliseconds(), kShortDurationMs); -} - -TEST_F(TraceTest, TestVLogTrace) { - for (FLAGS_v = 0; FLAGS_v <= 1; FLAGS_v++) { - TraceLog* tl = TraceLog::GetInstance(); - tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_CONTINUOUSLY); - VLOG_AND_TRACE("test", 1) << "hello world"; - tl->SetDisabled(); - string trace_json = TraceResultBuffer::FlushTraceLogToString(); - ASSERT_STR_CONTAINS(trace_json, "hello world"); - ASSERT_STR_CONTAINS(trace_json, "trace-test.cc"); - } -} - -namespace { -string FunctionWithSideEffect(bool* b) { - *b = true; - return "function-result"; -} -} // anonymous namespace - -// Test that, if tracing is not enabled, a VLOG_AND_TRACE doesn't evaluate its -// arguments. -TEST_F(TraceTest, TestVLogTraceLazyEvaluation) { - FLAGS_v = 0; - bool function_run = false; - VLOG_AND_TRACE("test", 1) << FunctionWithSideEffect(&function_run); - ASSERT_FALSE(function_run); - - // If we enable verbose logging, we should run the side effect even though - // trace logging is disabled. - FLAGS_v = 1; - VLOG_AND_TRACE("test", 1) << FunctionWithSideEffect(&function_run); - ASSERT_TRUE(function_run); -} - -TEST_F(TraceTest, TestVLogAndEchoToConsole) { - TraceLog* tl = TraceLog::GetInstance(); - tl->SetEnabled(CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), - TraceLog::RECORDING_MODE, - TraceLog::ECHO_TO_CONSOLE); - FLAGS_v = 1; - VLOG_AND_TRACE("test", 1) << "hello world"; - tl->SetDisabled(); -} - TEST_F(TraceTest, TestTraceMetrics) { scoped_refptr trace(new Trace); trace->metrics()->Increment("foo", 10); @@ -872,29 +137,10 @@ TEST_F(TraceTest, TestTraceMetrics) { EXPECT_GE(m["test_scope_us"], 80 * 1000); } -// Regression test for KUDU-2075: using tracing from vanilla threads -// should work fine, even if some pthread_self identifiers have been -// reused. -TEST_F(TraceTest, TestTraceFromVanillaThreads) { - TraceLog::GetInstance()->SetEnabled( - CategoryFilter(CategoryFilter::kDefaultCategoryFilterString), - TraceLog::RECORDING_MODE, - TraceLog::RECORD_CONTINUOUSLY); - SCOPED_CLEANUP({ TraceLog::GetInstance()->SetDisabled(); }); +} // namespace doris - // Do several passes to make it more likely that the thread identifiers - // will get reused. - for (int pass = 0; pass < 10; pass++) { - vector threads; - for (int i = 0; i < 100; i++) { - threads.emplace_back([i] { - GenerateTraceEvents(i, 1); - }); - } - for (auto& t : threads) { - t.join(); - } - } +int main(int argc, char** argv) { + ::testing::InitGoogleTest(&argc, argv); + return RUN_ALL_TESTS(); } -} // namespace debug -} // namespace kudu + From 9fc2554e6c2aee01980d86b142597050446ab211 Mon Sep 17 00:00:00 2001 From: Yingchun Lai <405403881@qq.com> Date: Thu, 14 May 2020 14:45:22 +0000 Subject: [PATCH 3/3] indentation --- be/src/common/logconfig.cpp | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/be/src/common/logconfig.cpp b/be/src/common/logconfig.cpp index fe054f14f5..72d3b7bc0c 100644 --- a/be/src/common/logconfig.cpp +++ b/be/src/common/logconfig.cpp @@ -154,18 +154,18 @@ void shutdown_logging() { } 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); + 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); + 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