[incubator-doris] 01/01: [trace] Introduce trace util to BE

[mo...@apache.org]

This is an automated email from the ASF dual-hosted git repository.

morningman pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/incubator-doris.git

commit bb7ae9784597c12fed263edd5241e9678b6d98d8
Merge: 2f3b7b5 9fc2554
Author: Mingyu Chen <mo...@gmail.com>
AuthorDate: Mon May 18 11:10:25 2020 +0800

    [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

 be/src/common/logconfig.cpp   |  20 +++
 be/src/util/CMakeLists.txt    |   2 +
 be/src/util/logging.h         |   4 +
 be/src/util/trace.cpp         | 266 ++++++++++++++++++++++++++++++++++++++
 be/src/util/trace.h           | 291 ++++++++++++++++++++++++++++++++++++++++++
 be/src/util/trace_metrics.cpp |  74 +++++++++++
 be/src/util/trace_metrics.h   |  89 +++++++++++++
 be/test/util/CMakeLists.txt   |   1 +
 be/test/util/trace_test.cpp   | 146 +++++++++++++++++++++
 9 files changed, 893 insertions(+)


---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@doris.apache.org
For additional commands, e-mail: commits-help@doris.apache.org