From a27d21e5d59692c3aca30bd9dbba49d7ad49e2f4 Mon Sep 17 00:00:00 2001 From: Yijiao Qin Date: Fri, 12 Jul 2024 15:22:37 -0700 Subject: [PATCH 1/2] add performancetimer into libswsscommon --- common/Makefile.am | 3 +- common/performancetimer.cpp | 128 ++++++++++++++++++++++++++++++++++++ common/performancetimer.h | 63 ++++++++++++++++++ 3 files changed, 193 insertions(+), 1 deletion(-) create mode 100644 common/performancetimer.cpp create mode 100644 common/performancetimer.h diff --git a/common/Makefile.am b/common/Makefile.am index 5d1de753e..df41c3be1 100644 --- a/common/Makefile.am +++ b/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) diff --git a/common/performancetimer.cpp b/common/performancetimer.cpp new file mode 100644 index 000000000..0ac33c9f2 --- /dev/null +++ b/common/performancetimer.cpp @@ -0,0 +1,128 @@ +#include "performancetimer.h" + +#include "logger.h" +#include +#include + +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(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(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(INDICATOR); + 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(m_tasks) / static_cast(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; +} diff --git a/common/performancetimer.h b/common/performancetimer.h new file mode 100644 index 000000000..46a06bfb8 --- /dev/null +++ b/common/performancetimer.h @@ -0,0 +1,63 @@ +#pragma once + +#include "sal.h" +#include + +#include +#include +#include +#include +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 m_start; + std::chrono::time_point m_stop; + + /* records how long the timer has idled between last stop and this start */ + std::deque m_gaps; + /* records how long each call takes */ + std::deque m_intervals; + /* records how many tasks each call finishes */ + std::deque 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 + }; +} From 54294f67c870f0052abe452b79af0d71076ddb75 Mon Sep 17 00:00:00 2001 From: Yijiao Qin Date: Thu, 25 Jul 2024 17:42:36 -0700 Subject: [PATCH 2/2] add unit tests --- common/performancetimer.cpp | 13 +++++++---- common/performancetimer.h | 2 +- tests/Makefile.am | 1 + tests/performancetimer_ut.cpp | 43 +++++++++++++++++++++++++++++++++++ 4 files changed, 54 insertions(+), 5 deletions(-) create mode 100644 tests/performancetimer_ut.cpp diff --git a/common/performancetimer.cpp b/common/performancetimer.cpp index 0ac33c9f2..400a55c8b 100644 --- a/common/performancetimer.cpp +++ b/common/performancetimer.cpp @@ -51,10 +51,12 @@ void PerformanceTimer::stop() m_stop = std::chrono::steady_clock::now(); } -void PerformanceTimer::inc(uint64_t count) +std::string PerformanceTimer::inc(uint64_t count) { SWSS_LOG_ENTER(); + std::string output = ""; + m_calls += 1; m_tasks += count; @@ -68,7 +70,7 @@ void PerformanceTimer::inc(uint64_t count) if (count == 0) { m_gaps.pop_back(); m_calls -= 1; - return; + return output; } if (m_incs.size() <= LIMIT) { @@ -84,16 +86,19 @@ void PerformanceTimer::inc(uint64_t count) if (m_enable && mseconds > 0) { + output = getTimerState(); std::ifstream indicator(INDICATOR); if (indicator.good()) { - SWSS_LOG_NOTICE("%s", getTimerState().c_str()); + SWSS_LOG_NOTICE("%s", output.c_str()); } else { - SWSS_LOG_INFO("%s", getTimerState().c_str()); + SWSS_LOG_INFO("%s", output.c_str()); } } reset(); } + + return output; } std::string PerformanceTimer::getTimerState() diff --git a/common/performancetimer.h b/common/performancetimer.h index 46a06bfb8..545aeeae5 100644 --- a/common/performancetimer.h +++ b/common/performancetimer.h @@ -27,7 +27,7 @@ namespace swss void stop(); - void inc(uint64_t count = 1); + std::string inc(uint64_t count = 1); void reset(); diff --git a/tests/Makefile.am b/tests/Makefile.am index 39712b233..9642b09ab 100644 --- a/tests/Makefile.am +++ b/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) diff --git a/tests/performancetimer_ut.cpp b/tests/performancetimer_ut.cpp new file mode 100644 index 000000000..4bdaf74ef --- /dev/null +++ b/tests/performancetimer_ut.cpp @@ -0,0 +1,43 @@ +#include "common/performancetimer.h" +#include +#include "gtest/gtest.h" +#include + +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); +}