[common] add PerformanceTimer

common/Makefile.am

@@ -77,7 +77,8 @@ common_libswsscommon_la_SOURCES = \
     common/c-api/zmqclient.cpp             \
     common/c-api/zmqserver.cpp             \
     common/c-api/zmqconsumerstatetable.cpp \
-    common/c-api/zmqproducerstatetable.cpp
+    common/c-api/zmqproducerstatetable.cpp \
+    common/performancetimer.cpp
 
 common_libswsscommon_la_CXXFLAGS = $(DBGFLAGS) $(AM_CFLAGS) $(CFLAGS_COMMON) $(LIBNL_CFLAGS) $(CODE_COVERAGE_CXXFLAGS)
 common_libswsscommon_la_CPPFLAGS = $(DBGFLAGS) $(AM_CFLAGS) $(CFLAGS_COMMON) $(LIBNL_CPPFLAGS) $(CODE_COVERAGE_CPPFLAGS)

common/performancetimer.cpp

@@ -0,0 +1,133 @@
+#include "performancetimer.h"
+
+#include "logger.h"
+#include <nlohmann/json.hpp>
+#include <fstream>
+
+using namespace swss;
+
+bool PerformanceTimer::m_enable = true;
+#define LIMIT 5
+#define INDICATOR "/var/log/syslog_notice_flag"
+
+PerformanceTimer::PerformanceTimer(
+        _In_ std::string funcName,
+        _In_ uint64_t threshold,
+        _In_ bool verbose):
+        m_name(funcName),
+        m_threshold(threshold),
+        m_verbose(verbose)
+{
+    reset();
+    m_stop = std::chrono::steady_clock::now();
+}
+
+void PerformanceTimer::reset()
+{
+    SWSS_LOG_ENTER();
+
+    m_tasks = 0;
+    m_calls = 0;
+    m_busy = 0;
+    m_idle = 0;
+
+    m_intervals.clear();
+    m_gaps.clear();
+    m_incs.clear();
+}
+
+void PerformanceTimer::start()
+{
+    SWSS_LOG_ENTER();
+
+    m_start = std::chrono::steady_clock::now();
+    // measures the gap between this start() and the last stop()
+    m_gaps.push_back(std::chrono::duration_cast<std::chrono::milliseconds>(m_start-m_stop).count());
+}
+
+void PerformanceTimer::stop()
+{
+    SWSS_LOG_ENTER();
+    m_stop = std::chrono::steady_clock::now();
+}
+
+std::string PerformanceTimer::inc(uint64_t count)
+{
+    SWSS_LOG_ENTER();
+
+    std::string output = "";
+
+    m_calls += 1;
+
+    m_tasks += count;
+
+    m_idle += m_gaps.back();
+
+    uint64_t interval = std::chrono::duration_cast<std::chrono::nanoseconds>(m_stop - m_start).count();
+
+    m_busy += interval;
+
+    if (count == 0) {
+        m_gaps.pop_back();
+        m_calls -= 1;
+        return output;
+    }
+
+    if (m_incs.size() <= LIMIT) {
+        m_incs.push_back(count);
+        m_intervals.push_back(interval/1000000);
+    } else {
+        m_gaps.pop_back();
+    }
+
+    if (m_tasks >= m_threshold)
+    {
+        uint64_t mseconds = m_busy/1000000;
+
+        if (m_enable && mseconds > 0)
+        {
+            output = getTimerState();
+            std::ifstream indicator(INDICATOR);
+            if (indicator.good()) {
+                SWSS_LOG_NOTICE("%s", output.c_str());
+            } else {
+                SWSS_LOG_INFO("%s", output.c_str());
+            }
+        }
+
+        reset();
+    }
+
+    return output;
+}
+
+std::string PerformanceTimer::getTimerState()
+{
+    nlohmann::json data;
+    data["API"] = m_name;
+    data["Tasks"] = m_tasks;
+    data["busy[ms]"] = m_busy/1000000;
+    data["idle[ms]"] = m_idle;
+    data["Total[ms]"] = m_busy/1000000 + m_idle;
+    double ratio = static_cast<double>(m_tasks) / static_cast<double>(m_busy/1000000 + m_idle);
+    data["RPS[k]"] = std::round(ratio * 10.0) / 10.0f;
+    if (m_verbose) {
+        data["m_intervals"] = m_intervals;
+        data["m_gaps"] = m_gaps;
+        data["m_incs"] = m_incs;
+    }
+
+    return data.dump();
+}
+
+void PerformanceTimer::setTimerName(const std::string& funcName) {
+    m_name = funcName;
+}
+
+void PerformanceTimer::setTimerThreshold(uint64_t threshold) {
+    m_threshold = threshold;
+}
+
+void PerformanceTimer::setTimerVerbose(bool verbose) {
+    m_verbose = verbose;
+}

common/performancetimer.h

@@ -0,0 +1,63 @@
+#pragma once
+
+#include "sal.h"
+#include <cstdint>
+
+#include <iostream>
+#include <chrono>
+#include <string>
+#include <deque>
+namespace swss
+{
+    class PerformanceTimer
+    {
+        public:
+
+            PerformanceTimer(
+                _In_ std::string funcName = "",
+                _In_ uint64_t threshold = 10000,
+                _In_ bool verbose = false
+            );
+
+            ~PerformanceTimer() = default;
+
+        public:
+
+            void start();
+
+            void stop();
+
+            std::string inc(uint64_t count = 1);
+
+            void reset();
+
+            std::string getTimerState();
+
+            static bool m_enable;
+
+            void setTimerName(const std::string& funcName);
+            void setTimerThreshold(uint64_t threshold);
+            void setTimerVerbose(bool verbose);
+
+        private:
+
+            std::string m_name; // records what this timer measures about
+            uint64_t m_threshold; // reset the timer when the m_tasks reachs m_threshold
+            bool m_verbose; // decides whether to print in verbose when m_threshold is reached
+
+            std::chrono::time_point<std::chrono::steady_clock> m_start;
+            std::chrono::time_point<std::chrono::steady_clock> m_stop;
+
+            /* records how long the timer has idled between last stop and this start */
+            std::deque<uint64_t> m_gaps;
+            /* records how long each call takes */
+            std::deque<uint64_t> m_intervals;
+            /* records how many tasks each call finishes */
+            std::deque<uint64_t> m_incs;
+
+            uint64_t m_tasks; // sum of m_incs
+            uint64_t m_calls; // how many times the timer is used
+            uint64_t m_busy;  // sum of m_intervals
+            uint64_t m_idle;  // sum of m_gaps
+    };
+}

tests/Makefile.am

@@ -43,6 +43,7 @@ tests_tests_SOURCES = tests/redis_ut.cpp                \
                       tests/zmq_state_ut.cpp            \
                       tests/profileprovider_ut.cpp      \
                       tests/c_api_ut.cpp                \
+                      tests/performancetimer_ut.cpp     \
                       tests/main.cpp
 
 tests_tests_CFLAGS = $(DBGFLAGS) $(AM_CFLAGS) $(CFLAGS_COMMON) $(CFLAGS_GTEST) $(LIBNL_CFLAGS)

tests/performancetimer_ut.cpp

@@ -0,0 +1,43 @@
+#include "common/performancetimer.h"
+#include <nlohmann/json.hpp>
+#include "gtest/gtest.h"
+#include <thread>
+
+using namespace std;
+
+#define PRINT_ALL 1
+
+TEST(PerformancetimerTest, basic)
+{
+    std::string expected;
+
+    static swss::PerformanceTimer timer("basic", PRINT_ALL);
+    timer.start();
+    this_thread::sleep_for(chrono::milliseconds(100));
+    timer.stop();
+    std::string output = timer.inc(1000);
+
+    expected = R"({"API":"basic","RPS[k]":10.0,"Tasks":1000,"Total[ms]":100,"busy[ms]":100,"idle[ms]":0})";
+    EXPECT_EQ(output, expected);
+
+    timer.setTimerName("basic_set_name");
+    timer.setTimerVerbose(true);
+    timer.setTimerThreshold(3000);
+
+    timer.start();
+    this_thread::sleep_for(chrono::milliseconds(100));
+    timer.stop();
+    output = timer.inc(1000);
+    EXPECT_EQ(output, "");
+
+    this_thread::sleep_for(chrono::milliseconds(200));
+
+    timer.start();
+    this_thread::sleep_for(chrono::milliseconds(300));
+    timer.stop();
+    output = timer.inc(2000);
+
+    expected = R"({"API":"basic_set_name","RPS[k]":5.0,"Tasks":3000,"Total[ms]":600,"busy[ms]":400,"idle[ms]":200,"m_gaps":[0,200],"m_incs":[1000,2000],"m_intervals":[100,300]})";
+
+    EXPECT_EQ(output, expected);
+}