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..400a55c8b --- /dev/null +++ b/common/performancetimer.cpp @@ -0,0 +1,133 @@ +#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(); +} + +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(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(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..545aeeae5 --- /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(); + + 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 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 + }; +} diff --git a/goext/Makefile b/goext/Makefile index 50beb76dc..76fddb7f5 100644 --- a/goext/Makefile +++ b/goext/Makefile @@ -17,6 +17,7 @@ all: $(SWIG) $(SWIG_FLAG) -I/usr/include/swss/ swsscommon.i check: + $(GO) mod init goext sudo CGO_LDFLAGS="$(CGO_LDFLAGS)" CGO_CXXFLAGS="$(CGO_CXXFLAGS)" $(GO) test clean: 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); +}