feat(utils): add latency trace tool (#510)

src/utils/latency_tracer.cpp

@@ -0,0 +1,93 @@
+// 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 "latency_tracer.h"
+
+#include <dsn/service_api_c.h>
+#include <dsn/dist/fmt_logging.h>
+#include <dsn/utility/flags.h>
+
+namespace dsn {
+namespace utils {
+
+DSN_DEFINE_bool("replication", enable_latency_tracer, false, "whether enable the latency tracer");
+
+latency_tracer::latency_tracer(const std::string &name) : _name(name), _start_time(dsn_now_ns()) {}
+
+void latency_tracer::add_point(const std::string &stage_name)
+{
+    if (!FLAGS_enable_latency_tracer) {
+        return;
+    }
+
+    uint64_t ts = dsn_now_ns();
+    utils::auto_write_lock write(_lock);
+    _points[ts] = stage_name;
+}
+
+void latency_tracer::set_sub_tracer(const std::shared_ptr<latency_tracer> &tracer)
+{
+    _sub_tracer = tracer;
+}
+
+void latency_tracer::dump_trace_points(int threshold)
+{
+    std::string traces;
+    dump_trace_points(threshold, traces);
+}
+
+void latency_tracer::dump_trace_points(int threshold, /*out*/ std::string &traces)
+{
+    if (threshold < 0 || !FLAGS_enable_latency_tracer) {
+        return;
+    }
+
+    if (_points.empty()) {
+        return;
+    }
+
+    utils::auto_read_lock read(_lock);
+
+    uint64_t time_used = _points.rbegin()->first - _start_time;
+
+    if (time_used < threshold) {
+        return;
+    }
+
+    traces.append(fmt::format("\t***************[TRACE:{}]***************\n", _name));
+    uint64_t previous_time = _start_time;
+    for (const auto &point : _points) {
+        std::string trace = fmt::format("\tTRACE:name={:<50}, span={:<20}, total={:<20}, "
+                                        "ts={:<20}\n",
+                                        point.second,
+                                        point.first - previous_time,
+                                        point.first - _start_time,
+                                        point.first);
+        traces.append(trace);
+        previous_time = point.first;
+    }
+
+    if (_sub_tracer == nullptr) {
+        dwarn_f("TRACE:the traces as fallow:\n{}", traces);
+        return;
+    }
+
+    _sub_tracer->dump_trace_points(0, traces);
+}
+
+} // namespace utils
+} // namespace dsn

src/utils/latency_tracer.h

@@ -0,0 +1,96 @@
+// 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 <dsn/utility/synchronize.h>
+
+namespace dsn {
+namespace utils {
+
+/**
+ * latency_tracer is a tool for tracking the time spent in each of the stages during request
+ * execution. It can help users to figure out where the latency bottleneck is located. User needs to
+ * use `add_point` before entering one stage, which will record the name of this stage and its start
+ * time. When the request is finished, you can dump the formatted result by `dump_trace_points`.
+ *
+ * For example, given a request with a 4-stage pipeline (the `latency_tracer` need to
+ * be held by this request throughout the execution):
+ *
+ * ```
+ * class request {
+ *      latency_tracer tracer;
+ * }
+ * void start(request req){
+ *      req.tracer.add_point("start");
+ * }
+ * void stageA(request req){
+ *      req.tracer.add_point("stageA");
+ * }
+ * void stageB(request req){
+ *      req.tracer.add_point("stageB");
+ * }
+ * void end(request req){
+ *      req.tracer.add_point("end");
+ * }
+ * ```
+ *
+ *  point1     point2     point3    point4
+ *    |         |           |         |
+ *    |         |           |         |
+ *  start---->stageA----->stageB---->end
+ *
+ * "request.tracer" will record the time duration among all tracepoints.
+**/
+extern bool FLAGS_enable_latency_tracer;
+
+class latency_tracer
+{
+public:
+    latency_tracer(const std::string &name);
+
+    // add a trace point to the tracer
+    // -name: user specified name of the trace point
+    void add_point(const std::string &stage_name);
+
+    // sub_tracer is used for tracking the request which may transfer the other type,
+    // for example: rdsn "rpc_message" will be convert to "mutation", the "tracking
+    // responsibility" is also passed on the "mutation":
+    //
+    // stageA[rpc_message]--stageB[rpc_message]--
+    //                                          |-->stageC[mutation]
+    // stageA[rpc_message]--stageB[rpc_message]--
+    void set_sub_tracer(const std::shared_ptr<latency_tracer> &tracer);
+
+    //  threshold < 0: don't dump any trace points
+    //  threshold = 0: dump all trace points
+    //  threshold > 0: dump the trace point when time_used > threshold
+    void dump_trace_points(int threshold);
+
+private:
+    void dump_trace_points(int threshold, /*out*/ std::string &traces);
+
+    utils::rw_lock_nr _lock;
+
+    const std::string _name;
+    const uint64_t _start_time;
+    std::map<int64_t, std::string> _points;
+    std::shared_ptr<latency_tracer> _sub_tracer;
+
+    friend class latency_tracer_test;
+};
+} // namespace utils
+} // namespace dsn

src/utils/test/latency_tracer_test.cpp

@@ -0,0 +1,109 @@
+// 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 "utils/latency_tracer.h"
+
+#include <gtest/gtest.h>
+#include <dsn/dist/fmt_logging.h>
+
+namespace dsn {
+namespace utils {
+class latency_tracer_test : public testing::Test
+{
+public:
+    int _tracer1_stage_count = 3;
+    int _tracer2_stage_count = 2;
+    int _sub_tracer_stage_count = 2;
+
+    std::shared_ptr<latency_tracer> _tracer1;
+    std::shared_ptr<latency_tracer> _tracer2;
+    std::shared_ptr<latency_tracer> _sub_tracer;
+
+public:
+    void SetUp() override
+    {
+        FLAGS_enable_latency_tracer = true;
+        init_trace_points();
+    }
+
+    void init_trace_points()
+    {
+        _tracer1 = std::make_shared<latency_tracer>("name1");
+        for (int i = 0; i < _tracer1_stage_count; i++) {
+            _tracer1->add_point(fmt::format("stage{}", i));
+        }
+
+        _tracer2 = std::make_shared<latency_tracer>("name2");
+
+        for (int i = 0; i < _tracer2_stage_count; i++) {
+            _tracer2->add_point(fmt::format("stage{}", i));
+        }
+
+        _sub_tracer = std::make_shared<latency_tracer>("sub");
+
+        _tracer1->set_sub_tracer(_sub_tracer);
+        _tracer2->set_sub_tracer(_sub_tracer);
+
+        for (int i = 0; i < _sub_tracer_stage_count; i++) {
+            _sub_tracer->add_point(fmt::format("stage{}", i));
+        }
+    }
+
+    std::map<int64_t, std::string> get_points(std::shared_ptr<latency_tracer> tracer)
+    {
+        return tracer->_points;
+    }
+
+    std::shared_ptr<latency_tracer> get_sub_tracer(std::shared_ptr<latency_tracer> tracer)
+    {
+        return tracer->_sub_tracer;
+    }
+};
+
+TEST_F(latency_tracer_test, add_point)
+{
+    auto tracer1_points = get_points(_tracer1);
+    ASSERT_EQ(tracer1_points.size(), _tracer1_stage_count);
+    int count1 = 0;
+    for (auto point : tracer1_points) {
+        ASSERT_EQ(point.second, fmt::format("stage{}", count1++));
+    }
+
+    auto tracer2_points = get_points(_tracer2);
+    ASSERT_EQ(tracer2_points.size(), _tracer2_stage_count);
+    int count2 = 0;
+    for (auto point : tracer2_points) {
+        ASSERT_EQ(point.second, fmt::format("stage{}", count2++));
+    }
+
+    auto tracer1_sub_tracer = get_sub_tracer(_tracer1);
+    auto tracer2_sub_tracer = get_sub_tracer(_tracer2);
+    ASSERT_EQ(tracer1_sub_tracer, tracer2_sub_tracer);
+
+    auto points = get_points(tracer1_sub_tracer);
+    ASSERT_TRUE(get_sub_tracer(tracer1_sub_tracer) == nullptr);
+    ASSERT_EQ(points.size(), _sub_tracer_stage_count);
+    int count3 = 0;
+    for (auto point : points) {
+        ASSERT_EQ(point.second, fmt::format("stage{}", count3++));
+    }
+
+    _tracer1->dump_trace_points(0);
+    _tracer2->dump_trace_points(0);
+}
+} // namespace utils
+} // namespace dsn