Files
doris/be/test/util/trace_test.cpp
Mingyu Chen 7fb74db0a1 [Trace] Introduce trace util to BE
Ref https://github.com/apache/incubator-doris/issues/3566
Introduce trace utility from Kudu to BE. This utility has been widely used in Kudu,
Impala also import this trace utility.
This trace util is used for tracing each phases in a thread, and can be dumped to
string to see each phases' time cost and diagnose which phase cost more time.
This util store a Trace object as a threadlocal variable, we can add trace entries
which record the current file name, line number, user specified symbols and
timestamp to this object, and it's able to add some counters to this Trace
object. And then, it can be dumped to human readable string.
There are some helpful macros defined in trace.h, here is a simple example for
usage:
```
  scoped_refptr<Trace> t1(new Trace);            // New 2 traces
  scoped_refptr<Trace> t2(new Trace);
  t1->AddChildTrace("child_trace", t2.get());    // t1 add t2 as a child named "child_trace"

  TRACE_TO(t1, "step $0", 1);  // Explicitly trace to t1
  usleep(10);
  // ... do some work
  ADOPT_TRACE(t1.get());   // Explicitly adopt to trace to t1
  TRACE("step $0", 2);     // Implicitly trace to t1
  {
    // The time spent in this scope is added to counter t1.scope_time_cost
    TRACE_COUNTER_SCOPE_LATENCY_US("scope_time_cost");
    ADOPT_TRACE(t2.get());  // Adopt to trace to t2 for the duration of the current scope
    TRACE("sub start");     // Implicitly trace to t2
    usleep(10);
    // ... do some work
    TRACE("sub before loop");
    for (int i = 0; i < 10; ++i) {
      TRACE_COUNTER_INCREMENT("iterate_count", 1);  // Increase counter t2.iterate_count

      MicrosecondsInt64 start_time = GetMonoTimeMicros();
      usleep(10);
      // ... do some work
      MicrosecondsInt64 end_time = GetMonoTimeMicros();
      int64_t dur = end_time - start_time;
      // t2's simple histogram metric with name prefixed with "lbm_writes"
      const char* counter = BUCKETED_COUNTER_NAME("lbm_writes", dur);
      TRACE_COUNTER_INCREMENT(counter, 1);
    }
    TRACE("sub after loop");
  }
  TRACE("goodbye $0", "cruel world");     // Automatically restore to trace to t1
  std::cout << t1->DumpToString(Trace::INCLUDE_ALL) << std::endl;
```
output looks like:
```
0514 02:16:07.988054 (+     0us) trace_test.cpp:76] step 1
0514 02:16:07.988112 (+    58us) trace_test.cpp:80] step 2
0514 02:16:07.988863 (+   751us) trace_test.cpp:103] goodbye cruel world
Related trace 'child_trace':
0514 02:16:07.988120 (+     0us) trace_test.cpp:85] sub start
0514 02:16:07.988188 (+    68us) trace_test.cpp:88] sub before loop
0514 02:16:07.988850 (+   662us) trace_test.cpp:101] sub after loop
Metrics: {"scope_time_cost":744,"child_traces":[["child_trace",{"iterate_count":10,"lbm_writes_lt_1ms":10}]]}
```
Exclude the original source code, this patch
do the following work to adapt to Doris:
- Rename "kudu" namespace to "doris"
- Update some names to the existing function names in Doris, i.g. strings::internal::SubstituteArg::kNoArg -> strings::internal::SubstituteArg::NoArg
- Use doris::SpinLock instead of kudu::simple_spinlock which hasn't been imported
- Use manual malloc() and free() instead of kudu::Arena which hasn't been imported
- Use manual rapidjson::Writer instead of kudu::JsonWriter which hasn't been imported
- Remove all TRACE_EVENT related unit tests since TRACE_EVENT is not imported this time
- Update CMakeLists.txt

NOTICE(#3622):
This is a "revert of revert pull request".
This pr is mainly used to synthesize the PRs whose commits were
scattered and submitted due to the wrong merge method into a complete single commit.
2020-05-18 14:55:11 +08:00

147 lines
4.2 KiB
C++

// Licensed to the Apache Software Foundation (ASF) under one
// or more contributor license agreements. See the NOTICE file
// distributed with this work for additional information
// regarding copyright ownership. The ASF licenses this file
// to you under the Apache License, Version 2.0 (the
// "License"); you may not use this file except in compliance
// with the License. You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing,
// software distributed under the License is distributed on an
// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
// KIND, either express or implied. See the License for the
// specific language governing permissions and limitations
// under the License.
#include "util/trace.h"
#include <cctype>
#include <cstdint>
#include <cstring>
#include <functional>
#include <map>
#include <ostream>
#include <string>
#include <thread>
#include <vector>
#include <glog/logging.h>
#include <gtest/gtest.h>
#include <rapidjson/document.h>
#include <rapidjson/rapidjson.h>
#include "gutil/macros.h"
#include "gutil/port.h"
#include "gutil/ref_counted.h"
#include "gutil/walltime.h"
#include "util/countdown_latch.h"
#include "util/monotime.h"
#include "util/scoped_cleanup.h"
#include "util/stopwatch.hpp"
#include "util/thread.h"
#include "util/trace_metrics.h"
using rapidjson::Document;
using rapidjson::Value;
using std::string;
using std::thread;
using std::vector;
namespace doris {
class TraceTest : public ::testing::Test {
};
// Replace all digits in 's' with the character 'X'.
static string XOutDigits(const string& s) {
string ret;
ret.reserve(s.size());
for (char c : s) {
if (isdigit(c)) {
ret.push_back('X');
} else {
ret.push_back(c);
}
}
return ret;
}
TEST_F(TraceTest, TestBasic) {
scoped_refptr<Trace> t(new Trace);
TRACE_TO(t, "hello $0, $1", "world", 12345);
TRACE_TO(t, "goodbye $0, $1", "cruel world", 54321);
string result = XOutDigits(t->DumpToString(Trace::NO_FLAGS));
ASSERT_EQ("XXXX XX:XX:XX.XXXXXX trace_test.cpp:XX] hello world, XXXXX\n"
"XXXX XX:XX:XX.XXXXXX trace_test.cpp:XX] goodbye cruel world, XXXXX\n",
result);
}
TEST_F(TraceTest, TestAttach) {
scoped_refptr<Trace> traceA(new Trace);
scoped_refptr<Trace> traceB(new Trace);
{
ADOPT_TRACE(traceA.get());
EXPECT_EQ(traceA.get(), Trace::CurrentTrace());
{
ADOPT_TRACE(traceB.get());
EXPECT_EQ(traceB.get(), Trace::CurrentTrace());
TRACE("hello from traceB");
}
EXPECT_EQ(traceA.get(), Trace::CurrentTrace());
TRACE("hello from traceA");
}
EXPECT_TRUE(Trace::CurrentTrace() == nullptr);
TRACE("this goes nowhere");
EXPECT_EQ("XXXX XX:XX:XX.XXXXXX trace_test.cpp:XX] hello from traceA\n",
XOutDigits(traceA->DumpToString(Trace::NO_FLAGS)));
EXPECT_EQ("XXXX XX:XX:XX.XXXXXX trace_test.cpp:XX] hello from traceB\n",
XOutDigits(traceB->DumpToString(Trace::NO_FLAGS)));
}
TEST_F(TraceTest, TestChildTrace) {
scoped_refptr<Trace> traceA(new Trace);
scoped_refptr<Trace> traceB(new Trace);
ADOPT_TRACE(traceA.get());
traceA->AddChildTrace("child", traceB.get());
TRACE("hello from traceA");
{
ADOPT_TRACE(traceB.get());
TRACE("hello from traceB");
}
EXPECT_EQ("XXXX XX:XX:XX.XXXXXX trace_test.cpp:XXX] hello from traceA\n"
"Related trace 'child':\n"
"XXXX XX:XX:XX.XXXXXX trace_test.cpp:XXX] hello from traceB\n",
XOutDigits(traceA->DumpToString(Trace::NO_FLAGS)));
}
TEST_F(TraceTest, TestTraceMetrics) {
scoped_refptr<Trace> trace(new Trace);
trace->metrics()->Increment("foo", 10);
trace->metrics()->Increment("bar", 10);
for (int i = 0; i < 1000; i++) {
trace->metrics()->Increment("baz", i);
}
EXPECT_EQ("{\"bar\":10,\"baz\":499500,\"foo\":10}",
trace->MetricsAsJSON());
{
ADOPT_TRACE(trace.get());
TRACE_COUNTER_SCOPE_LATENCY_US("test_scope_us");
SleepFor(MonoDelta::FromMilliseconds(100));
}
auto m = trace->metrics()->Get();
EXPECT_GE(m["test_scope_us"], 80 * 1000);
}
} // namespace doris
int main(int argc, char** argv) {
::testing::InitGoogleTest(&argc, argv);
return RUN_ALL_TESTS();
}