doris/be/src/util/trace.h

// 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 <rapidjson/writer.h>

#include <iosfwd>
#include <memory>
#include <string>
#include <utility>

#include "gutil/macros.h"
#include "gutil/ref_counted.h"
#include "gutil/strings/stringpiece.h"
#include "gutil/strings/substitute.h"
#include "gutil/threading/thread_collision_warner.h"
#include "util/spinlock.h"
#include "util/time.h"
#include "util/trace_metrics.h"

namespace doris {
class Trace;
}

// Adopt a Trace on the current thread for the duration of the current
// scope. The old current Trace is restored when the scope is exited.
//
// 't' should be a Trace* pointer.
#define ADOPT_TRACE(t) doris::ScopedAdoptTrace _adopt_trace(t);

// Issue a trace message, if tracing is enabled in the current thread.
// See Trace::SubstituteAndTrace for arguments.
// Example:
//  TRACE("Acquired timestamp $0", timestamp);
#define TRACE(format, substitutions...)                                                \
    do {                                                                               \
        doris::Trace* _trace = doris::Trace::CurrentTrace();                           \
        if (_trace) {                                                                  \
            _trace->SubstituteAndTrace(__FILE__, __LINE__, (format), ##substitutions); \
        }                                                                              \
    } while (0)

// Like the above, but takes the trace pointer as an explicit argument.
#define TRACE_TO(trace, format, substitutions...) \
    (trace)->SubstituteAndTrace(__FILE__, __LINE__, (format), ##substitutions)

// Increment a counter associated with the current trace.
//
// Each trace contains a map of counters which can be used to keep
// request-specific statistics. It is significantly faster to increment
// a trace counter compared to logging a message. Additionally, having
// slightly more structured information makes it easier to aggregate
// and show information back to operators.
//
// NOTE: the 'counter_name' MUST be a string which stays alive forever.
// Typically, this is a compile-time constant. If something other than
// a constant is required, use TraceMetric::InternName() in order to
// create a string which will last for the process lifetime. Of course,
// these strings will never be cleaned up, so it's important to use this
// judiciously.
//
// If no trace is active, this does nothing and does not evaluate its
// parameters.
#define TRACE_COUNTER_INCREMENT(counter_name, val)           \
    do {                                                     \
        doris::Trace* _trace = doris::Trace::CurrentTrace(); \
        if (_trace) {                                        \
            _trace->metrics()->Increment(counter_name, val); \
        }                                                    \
    } while (0)

// Increment a counter for the amount of wall time spent in the current
// scope. For example:
//
//  void DoFoo() {
//    TRACE_COUNTER_SCOPE_LATENCY_US("foo_us");
//    ... do expensive Foo thing
//  }
//
//  will result in a trace metric indicating the number of microseconds spent
//  in invocations of DoFoo().
#define TRACE_COUNTER_SCOPE_LATENCY_US(counter_name) \
    ::doris::ScopedTraceLatencyCounter _scoped_latency(counter_name)

// Construct a constant C string counter name which acts as a sort of
// coarse-grained histogram for trace metrics.
#define BUCKETED_COUNTER_NAME(prefix, duration_us) \
    []() {                                         \
        if (duration_us >= 100 * 1000) {           \
            return prefix "_gt_100_ms";            \
        } else if (duration_us >= 10 * 1000) {     \
            return prefix "_10-100_ms";            \
        } else if (duration_us >= 1000) {          \
            return prefix "_1-10_ms";              \
        } else {                                   \
            return prefix "_lt_1ms";               \
        }                                          \
    }()

namespace doris {

struct TraceEntry;

// A trace for a request or other process. This supports collecting trace entries
// from a number of threads, and later dumping the results to a stream.
//
// Callers should generally not add trace messages directly using the public
// methods of this class. Rather, the TRACE(...) macros defined above should
// be used such that file/line numbers are automatically included, etc.
//
// This class is thread-safe.
class Trace : public RefCountedThreadSafe<Trace> {
public:
    Trace();

    // Logs a message into the trace buffer.
    //
    // See strings::Substitute for details.
    //
    // N.B.: the file path passed here is not copied, so should be a static
    // constant (eg __FILE__).
    void SubstituteAndTrace(
            const char* filepath, int line_number, StringPiece format,
            const strings::internal::SubstituteArg& arg0 = strings::internal::SubstituteArg::NoArg,
            const strings::internal::SubstituteArg& arg1 = strings::internal::SubstituteArg::NoArg,
            const strings::internal::SubstituteArg& arg2 = strings::internal::SubstituteArg::NoArg,
            const strings::internal::SubstituteArg& arg3 = strings::internal::SubstituteArg::NoArg,
            const strings::internal::SubstituteArg& arg4 = strings::internal::SubstituteArg::NoArg,
            const strings::internal::SubstituteArg& arg5 = strings::internal::SubstituteArg::NoArg,
            const strings::internal::SubstituteArg& arg6 = strings::internal::SubstituteArg::NoArg,
            const strings::internal::SubstituteArg& arg7 = strings::internal::SubstituteArg::NoArg,
            const strings::internal::SubstituteArg& arg8 = strings::internal::SubstituteArg::NoArg,
            const strings::internal::SubstituteArg& arg9 = strings::internal::SubstituteArg::NoArg);

    // Dump the trace buffer to the given output stream.
    //
    enum {
        NO_FLAGS = 0,

        // If set, calculate and print the difference between successive trace messages.
        INCLUDE_TIME_DELTAS = 1 << 0,
        // If set, include a 'Metrics' line showing any attached trace metrics.
        INCLUDE_METRICS = 1 << 1,

        INCLUDE_ALL = INCLUDE_TIME_DELTAS | INCLUDE_METRICS
    };
    void Dump(std::ostream* out, int flags) const;

    // Dump the trace buffer as a string.
    std::string DumpToString(int flags = INCLUDE_ALL) const;

    std::string MetricsAsJSON() const;

    // Attaches the given trace which will get appended at the end when Dumping.
    //
    // The 'label' does not necessarily have to be unique, and is used to identify
    // the child trace when dumped. The contents of the StringPiece are copied
    // into this trace's arena.
    void AddChildTrace(StringPiece label, Trace* child_trace);

    // Return a copy of the current set of related "child" traces.
    std::vector<std::pair<StringPiece, scoped_refptr<Trace>>> ChildTraces() const;

    // Return the current trace attached to this thread, if there is one.
    static Trace* CurrentTrace() { return threadlocal_trace_; }

    // Simple function to dump the current trace to stderr, if one is
    // available. This is meant for usage when debugging in gdb via
    // 'call doris::Trace::DumpCurrentTrace();'.
    static void DumpCurrentTrace();

    TraceMetrics* metrics() { return &metrics_; }
    const TraceMetrics& metrics() const { return metrics_; }

private:
    friend class ScopedAdoptTrace;
    friend class RefCountedThreadSafe<Trace>;
    ~Trace();

    // The current trace for this thread. Threads should only set this using
    // using ScopedAdoptTrace, which handles reference counting the underlying
    // object.
    static __thread Trace* threadlocal_trace_;

    // Allocate a new entry from the arena, with enough space to hold a
    // message of length 'len'.
    TraceEntry* NewEntry(int len, const char* file_path, int line_number);

    // Add the entry to the linked list of entries.
    void AddEntry(TraceEntry* entry);

    void MetricsToJSON(rapidjson::Writer<rapidjson::StringBuffer>* jw) const;

    // TODO(yingchun): now we didn't import Arena, instead, we use manual malloc() and free().
    // std::unique_ptr<ThreadSafeArena> arena_;

    // Lock protecting the entries linked list.
    mutable SpinLock lock_;
    // The head of the linked list of entries (allocated inside arena_)
    TraceEntry* entries_head_;
    // The tail of the linked list of entries (allocated inside arena_)
    TraceEntry* entries_tail_;

    std::vector<std::pair<StringPiece, scoped_refptr<Trace>>> child_traces_;

    TraceMetrics metrics_;

    DISALLOW_COPY_AND_ASSIGN(Trace);
};

// Adopt a Trace object into the current thread for the duration
// of this object.
// This should only be used on the stack (and thus created and destroyed
// on the same thread)
class ScopedAdoptTrace {
public:
    explicit ScopedAdoptTrace(Trace* t) : old_trace_(Trace::threadlocal_trace_) {
        Trace::threadlocal_trace_ = t;
        if (t) {
            t->AddRef();
        }
        DFAKE_SCOPED_LOCK_THREAD_LOCKED(ctor_dtor_);
    }

    ~ScopedAdoptTrace() {
        if (Trace::threadlocal_trace_) {
            Trace::threadlocal_trace_->Release();
        }
        Trace::threadlocal_trace_ = old_trace_;
        DFAKE_SCOPED_LOCK_THREAD_LOCKED(ctor_dtor_);
    }

private:
    DFAKE_MUTEX(ctor_dtor_);
    Trace* old_trace_;

    DISALLOW_COPY_AND_ASSIGN(ScopedAdoptTrace);
};

// Implementation for TRACE_COUNTER_SCOPE_LATENCY_US(...) macro above.
class ScopedTraceLatencyCounter {
public:
    explicit ScopedTraceLatencyCounter(const char* counter)
            : counter_(counter), start_time_(GetCurrentTimeMicros()) {}

    ~ScopedTraceLatencyCounter() {
        TRACE_COUNTER_INCREMENT(counter_, GetCurrentTimeMicros() - start_time_);
    }

private:
    const char* const counter_;
    int64_t start_time_;
    DISALLOW_COPY_AND_ASSIGN(ScopedTraceLatencyCounter);
};

} // namespace doris