From c6364d1bace34f4431adcdba26983f1a45ce4e94 Mon Sep 17 00:00:00 2001 From: Yijiao Qin Date: Fri, 1 Nov 2024 08:40:42 -0700 Subject: [PATCH 1/2] [common] add PerformanceTimer (#893) What I did Extend the PerformanceIntervalTimer utility in sonic-sairedis repo to measure API performance. To optimize performance of a periodically invoked function, we not only pay attention to how long it takes to finish execution (busy time), but also care about how long it waits to get executed (idle time). The total time determines the actual throughput in the real world system. Hence we want to see data in 3 ways: 1. Idle time between two calls (a gap between this start and the last end, during which the thread just waits) 2. Busy time of each API call (interval between this start and this end, it's the true execution time) 3. Total time elapsed (idle + busy) | <- Initial Gap -> | <- - 1st **Execution** - -> | <- 2nd Gap -> | <- - 2nd **Execution** - -> | | <---------------- 1st **Total** --------------> | <------------ 2nd **Total**--------------> | Other features 1. calculate the number of tasks finished per call (Routes Per Second in the context of routes loading) 2. batch the logging output 3. adjust the SWSSLOGLEVEL using a file indicator, default level is "INFO", hence we could enable perf logs in a dynamic way. Why I did it original utility has limited functionality we need gap data to obtain more insight on the mutual influence of upstream and downstream modules original utility is in libsairedis, to use it in sonic-swss, there would be much Makefile.am change, not necessary. a utility tool for swss should be included in swss-common when enabled on-demand, it could help measure the API performance under scaled traffic one use case: help measuring perf in pr optimized bgp loading speed --- common/Makefile.am | 3 +- common/performancetimer.cpp | 133 ++++++++++++++++++++++++++++++++++ common/performancetimer.h | 63 ++++++++++++++++ tests/Makefile.am | 1 + tests/performancetimer_ut.cpp | 43 +++++++++++ 5 files changed, 242 insertions(+), 1 deletion(-) create mode 100644 common/performancetimer.cpp create mode 100644 common/performancetimer.h create mode 100644 tests/performancetimer_ut.cpp 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/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); +} From ace2080462d6ef36ce52e69a1391e2d9ebcfdabc Mon Sep 17 00:00:00 2001 From: ganglv <88995770+ganglyu@users.noreply.github.com> Date: Sat, 2 Nov 2024 19:28:38 +0800 Subject: [PATCH 2/2] Fix goext ut for bookworm (#940) Why I did it #937 PR checker is blocked by goext build How I did it Remove go build, and keep go test to run unit test. How to verify it Pass all UT and E2E test cases. --- goext/Makefile | 1 + 1 file changed, 1 insertion(+) 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: