add performancetimer into libswsscommon

common/Makefile.am

@@ -68,7 +68,8 @@ common_libswsscommon_la_SOURCES = \
  common/zmqclient.cpp \
  common/zmqserver.cpp \
  common/asyncdbupdater.cpp \
- common/redis_table_waiter.cpp
+ common/redis_table_waiter.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,126 @@
+#include "performancetimer.h"
+
+#include "logger.h"
+#include <nlohmann/json.hpp>
+#include <fstream>
+
+using namespace swss;
+
+bool PerformanceTimer::m_enable = true;
+#define LIMIT 5
+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();
+}
+
+void PerformanceTimer::inc(uint64_t count)
+{
+ SWSS_LOG_ENTER();
+
+ 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;
+ }
+
+ 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)
+ {
+ std::ifstream indicator("/var/log/syslog_notice_flag");
+ if (indicator.good()) {
+ SWSS_LOG_NOTICE("%s", getTimerState().c_str());
+ } else {
+ SWSS_LOG_INFO("%s", getTimerState().c_str());
+ }
+ }
+
+ reset();
+ }
+}
+
+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();
+
+ void 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
+ };
+}