From a7cf76455a2b824df7f9762aaf300d689de32b65 Mon Sep 17 00:00:00 2001 From: Xiaoxi Chen Date: Thu, 7 May 2026 18:26:33 +0800 Subject: [PATCH 1/5] SDSTOR-21921 Improve LOG_EVERY_N logic with memory optimization and time-based rate limiting This change enhances LOG_EVERY_N macros to fix memory leaks and add new capabilities: - Refactor check_logged_already() to check_and_format_log() which consolidates rate-limiting decision and suffix formatting into single function - Use hash-based keys instead of full message strings for memory efficiency - Clear entire map every 300s to prevent unbounded memory growth - Store millisecond offsets and counts for time-based rate limiting - Log first occurrence (count==1) in addition to every Nth occurrence - Add HS_LOG_EVERY_N_SEC for time-based rate limiting (log every N seconds) - Add HS_LOG_EVERY_N_OR_SEC for hybrid rate limiting (every N occurrences OR every M seconds) - Use consistent suffix format: "Last logged X.Xs ago, N occurrences" Memory impact: Reduces per-entry storage from ~124 bytes to ~20 bytes (6x improvement) Resolves: #880 --- .gitignore | 3 + conanfile.py | 2 +- src/lib/common/homestore_assert.hpp | 132 +++++++++++++++++++++++----- 3 files changed, 116 insertions(+), 21 deletions(-) diff --git a/.gitignore b/.gitignore index 78b8a1f38..47363d6a8 100644 --- a/.gitignore +++ b/.gitignore @@ -111,3 +111,6 @@ CMakeUserPresets.json # claude .claude/** + +# worktrees +.worktrees/ diff --git a/conanfile.py b/conanfile.py index 6b4fac0e3..0d1b7df1d 100644 --- a/conanfile.py +++ b/conanfile.py @@ -9,7 +9,7 @@ class HomestoreConan(ConanFile): name = "homestore" - version = "7.5.6" + version = "7.5.7" homepage = "https://github.com/eBay/Homestore" description = "HomeStore Storage Engine" diff --git a/src/lib/common/homestore_assert.hpp b/src/lib/common/homestore_assert.hpp index 9ffa46273..9bacf4727 100644 --- a/src/lib/common/homestore_assert.hpp +++ b/src/lib/common/homestore_assert.hpp @@ -143,21 +143,63 @@ fmt::make_format_args(detail_name, detail_val)))) \ (); \ fmt::vformat_to(fmt::appender{buf}, fmt::string_view{msgcb}, fmt::make_format_args(args...)); \ - const auto count{check_logged_already(buf)}; \ - if (count % freq == 0) { \ - if (count) { \ - fmt::vformat_to(fmt::appender{buf}, fmt::string_view{" ...Repeated {} times in this thread"}, \ - fmt::make_format_args(freq)); \ - } \ - return true; \ - } \ - return false; \ + return check_and_format_log(buf, freq, 0); \ }), \ msg, ##__VA_ARGS__); \ } #define HS_LOG_EVERY_N(level, mod, freq, msg, ...) HS_DETAILED_LOG_EVERY_N(level, mod, freq, , , , , msg, ##__VA_ARGS__) +#define HS_DETAILED_LOG_EVERY_N_SEC(level, mod, interval_sec, submod_name, submod_val, detail_name, detail_val, msg, \ + ...) \ + { \ + LOG##level##MOD_FMT( \ + BOOST_PP_IF(BOOST_VMD_IS_EMPTY(mod), base, mod), \ + ([&](fmt::memory_buffer& buf, const char* const msgcb, auto&&... args) -> bool { \ + fmt::vformat_to(fmt::appender{buf}, fmt::string_view{"[{}:{}] "}, \ + fmt::make_format_args(unmove(file_name(__FILE__)), unmove(__LINE__))); \ + BOOST_PP_IF(BOOST_VMD_IS_EMPTY(submod_name), BOOST_PP_EMPTY, \ + BOOST_PP_IDENTITY(fmt::vformat_to(fmt::appender{buf}, fmt::string_view{"[{}={}] "}, \ + fmt::make_format_args(submod_name, submod_val)))) \ + (); \ + BOOST_PP_IF(BOOST_VMD_IS_EMPTY(detail_name), BOOST_PP_EMPTY, \ + BOOST_PP_IDENTITY(fmt::vformat_to(fmt::appender{buf}, fmt::string_view{"[{}={}] "}, \ + fmt::make_format_args(detail_name, detail_val)))) \ + (); \ + fmt::vformat_to(fmt::appender{buf}, fmt::string_view{msgcb}, fmt::make_format_args(args...)); \ + return check_and_format_log(buf, 0, interval_sec); \ + }), \ + msg, ##__VA_ARGS__); \ + } + +#define HS_LOG_EVERY_N_SEC(level, mod, interval_sec, msg, ...) \ + HS_DETAILED_LOG_EVERY_N_SEC(level, mod, interval_sec, , , , , msg, ##__VA_ARGS__) + +#define HS_DETAILED_LOG_EVERY_N_OR_SEC(level, mod, freq, interval_sec, submod_name, submod_val, detail_name, \ + detail_val, msg, ...) \ + { \ + LOG##level##MOD_FMT( \ + BOOST_PP_IF(BOOST_VMD_IS_EMPTY(mod), base, mod), \ + ([&](fmt::memory_buffer& buf, const char* const msgcb, auto&&... args) -> bool { \ + fmt::vformat_to(fmt::appender{buf}, fmt::string_view{"[{}:{}] "}, \ + fmt::make_format_args(unmove(file_name(__FILE__)), unmove(__LINE__))); \ + BOOST_PP_IF(BOOST_VMD_IS_EMPTY(submod_name), BOOST_PP_EMPTY, \ + BOOST_PP_IDENTITY(fmt::vformat_to(fmt::appender{buf}, fmt::string_view{"[{}={}] "}, \ + fmt::make_format_args(submod_name, submod_val)))) \ + (); \ + BOOST_PP_IF(BOOST_VMD_IS_EMPTY(detail_name), BOOST_PP_EMPTY, \ + BOOST_PP_IDENTITY(fmt::vformat_to(fmt::appender{buf}, fmt::string_view{"[{}={}] "}, \ + fmt::make_format_args(detail_name, detail_val)))) \ + (); \ + fmt::vformat_to(fmt::appender{buf}, fmt::string_view{msgcb}, fmt::make_format_args(args...)); \ + return check_and_format_log(buf, freq, interval_sec); \ + }), \ + msg, ##__VA_ARGS__); \ + } + +#define HS_LOG_EVERY_N_OR_SEC(level, mod, freq, interval_sec, msg, ...) \ + HS_DETAILED_LOG_EVERY_N_OR_SEC(level, mod, freq, interval_sec, , , , , msg, ##__VA_ARGS__) + #define HS_SUBMOD_LOG(level, mod, req, submod_name, submod_val, msg, ...) \ HS_DETAILED_LOG(level, mod, req, submod_name, submod_val, , , msg, ##__VA_ARGS__) #define HS_REQ_LOG(level, mod, req, msg, ...) HS_SUBMOD_LOG(level, mod, req, , , msg, ##__VA_ARGS__) @@ -310,16 +352,66 @@ #define HS_REL_ASSERT_NULL(val, ...) HS_ASSERT_NULL(RELEASE_ASSERT_CMP, val, ##__VA_ARGS__) #define HS_REL_ASSERT_NOTNULL(val, ...) HS_ASSERT_NOTNULL(RELEASE_ASSERT_CMP, val, ##__VA_ARGS__) -[[maybe_unused]] static uint64_t check_logged_already(const fmt::memory_buffer& buf) { +[[maybe_unused]] static bool check_and_format_log(fmt::memory_buffer& buf, uint64_t freq = 0, + uint64_t interval_sec = 0) { static constexpr uint64_t COUNTER_RESET_SEC{300}; // Reset every 5 minutes - static thread_local std::unordered_map< std::string, std::pair< Clock::time_point, uint64_t > > log_map{}; - - const std::string_view msg{buf.data()}; - auto [it, happened] = log_map.emplace(msg, std::make_pair(Clock::now(), 0)); - HS_REL_ASSERT(it != std::cend(log_map), "Expected entry to be either present or new insertion to succeed"); - auto& [tm, count] = it->second; - auto result = count; - count = (get_elapsed_time_sec(tm) > COUNTER_RESET_SEC) ? static_cast< decltype(count) >(0) : count + 1; - tm = Clock::now(); - return result; + static thread_local Clock::time_point last_cleanup{Clock::now()}; + static thread_local std::unordered_map< size_t, std::pair< uint32_t, uint64_t > > log_map{}; + // hash -> (last_log_ms, count) + + const auto now = Clock::now(); + if (get_elapsed_time_sec(last_cleanup) > COUNTER_RESET_SEC) { + log_map.clear(); + last_cleanup = now; + } + + // Hash the buffer content BEFORE appending any suffix + const std::string_view msg{buf.data(), buf.size()}; + const size_t msg_hash = std::hash< std::string_view >{}(msg); + + // Milliseconds since last cleanup (max ~49 days with uint32_t) + const uint32_t now_ms = + std::chrono::duration_cast< std::chrono::milliseconds >(now - last_cleanup).count(); + + auto [it, happened] = log_map.emplace(msg_hash, std::make_pair(now_ms, 1)); + uint32_t elapsed_ms = 0; + uint64_t count = 1; + + if (!happened) { + // Entry exists - increment count and calculate elapsed time + elapsed_ms = now_ms - it->second.first; // Time since last log emission + it->second.second++; // Increment count + count = it->second.second; + } + + // Decide if we should log + bool should_log = false; + if (count == 1) { + // Always log first occurrence + should_log = true; + } else if (freq > 0 && count % freq == 0) { + // Count-based: log every Nth occurrence + should_log = true; + } else if (interval_sec > 0 && elapsed_ms >= static_cast< uint32_t >(interval_sec) * 1000) { + // Time-based: log if enough time has passed since last emission + should_log = true; + } + + // If logging, update timestamp and append suffix + if (should_log) { + // Append formatted suffix if not first occurrence + if (count > 1) { + // Always show elapsed time and count since last log + fmt::vformat_to(fmt::appender{buf}, fmt::string_view{" ...Last logged {:.1f}s ago, {} occurrences"}, + fmt::make_format_args(elapsed_ms / 1000.0, count)); + } + + // Update state after logging (so next log shows "since this log") + if (!happened) { + it->second.first = now_ms; // Update timestamp + it->second.second = 1; // Reset count (next occurrence will be "1 since this log") + } + } + + return should_log; } From eeb7a9c38442da72229a21ef28a67bf66e3771f7 Mon Sep 17 00:00:00 2001 From: Xiaoxi Chen Date: Fri, 8 May 2026 01:38:04 +0800 Subject: [PATCH 2/5] Fix fmt::make_format_args compilation error Use milliseconds directly in format string instead of converting to seconds, avoiding rvalue binding issue with fmt::make_format_args. Co-Authored-By: Claude Opus 4.6 --- src/lib/common/homestore_assert.hpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/lib/common/homestore_assert.hpp b/src/lib/common/homestore_assert.hpp index 9bacf4727..27789e3ab 100644 --- a/src/lib/common/homestore_assert.hpp +++ b/src/lib/common/homestore_assert.hpp @@ -402,8 +402,8 @@ // Append formatted suffix if not first occurrence if (count > 1) { // Always show elapsed time and count since last log - fmt::vformat_to(fmt::appender{buf}, fmt::string_view{" ...Last logged {:.1f}s ago, {} occurrences"}, - fmt::make_format_args(elapsed_ms / 1000.0, count)); + fmt::vformat_to(fmt::appender{buf}, fmt::string_view{" ...Last logged {}ms ago, {} occurrences"}, + fmt::make_format_args(elapsed_ms, count)); } // Update state after logging (so next log shows "since this log") From e3c007c8c4d22afca6d53a092d3502c532f04384 Mon Sep 17 00:00:00 2001 From: Xiaoxi Chen Date: Fri, 8 May 2026 01:47:11 +0800 Subject: [PATCH 3/5] Fix off-by-one error in count tracking and improve memory cleanup - Fix count tracking: reset to 0 instead of 1 to avoid off-by-one in rate limiting (was logging at 10, 19, 28... instead of 10, 20, 30...) - Use happened flag to detect first occurrence instead of count==1 - Use swap with empty map to actually release memory during cleanup (clear() only removes entries but retains bucket array capacity) Co-Authored-By: Claude Opus 4.6 --- src/lib/common/homestore_assert.hpp | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/src/lib/common/homestore_assert.hpp b/src/lib/common/homestore_assert.hpp index 27789e3ab..9d2aead03 100644 --- a/src/lib/common/homestore_assert.hpp +++ b/src/lib/common/homestore_assert.hpp @@ -361,7 +361,7 @@ const auto now = Clock::now(); if (get_elapsed_time_sec(last_cleanup) > COUNTER_RESET_SEC) { - log_map.clear(); + std::unordered_map< size_t, std::pair< uint32_t, uint64_t > >().swap(log_map); // Actually release memory last_cleanup = now; } @@ -373,9 +373,9 @@ const uint32_t now_ms = std::chrono::duration_cast< std::chrono::milliseconds >(now - last_cleanup).count(); - auto [it, happened] = log_map.emplace(msg_hash, std::make_pair(now_ms, 1)); + auto [it, happened] = log_map.emplace(msg_hash, std::make_pair(now_ms, 0)); uint32_t elapsed_ms = 0; - uint64_t count = 1; + uint64_t count = 0; if (!happened) { // Entry exists - increment count and calculate elapsed time @@ -386,8 +386,8 @@ // Decide if we should log bool should_log = false; - if (count == 1) { - // Always log first occurrence + if (happened) { + // Always log first occurrence (new entry) should_log = true; } else if (freq > 0 && count % freq == 0) { // Count-based: log every Nth occurrence @@ -400,7 +400,7 @@ // If logging, update timestamp and append suffix if (should_log) { // Append formatted suffix if not first occurrence - if (count > 1) { + if (!happened && count > 0) { // Always show elapsed time and count since last log fmt::vformat_to(fmt::appender{buf}, fmt::string_view{" ...Last logged {}ms ago, {} occurrences"}, fmt::make_format_args(elapsed_ms, count)); @@ -409,7 +409,7 @@ // Update state after logging (so next log shows "since this log") if (!happened) { it->second.first = now_ms; // Update timestamp - it->second.second = 1; // Reset count (next occurrence will be "1 since this log") + it->second.second = 0; // Reset count (next occurrence will be "1 since this log") } } From 0d4b49ae915062bc68c84713330c1689dc4f67ba Mon Sep 17 00:00:00 2001 From: Xiaoxi Chen Date: Fri, 8 May 2026 10:25:31 +0800 Subject: [PATCH 4/5] Add missing functional include and handle edge case - Add #include for std::hash to avoid relying on transitive includes - Handle edge case when both freq=0 and interval_sec=0: always log (fallback behavior) instead of only logging first occurrence then suppressing all subsequent logs Co-Authored-By: Claude Opus 4.6 --- src/lib/common/homestore_assert.hpp | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/src/lib/common/homestore_assert.hpp b/src/lib/common/homestore_assert.hpp index 9d2aead03..7b4633266 100644 --- a/src/lib/common/homestore_assert.hpp +++ b/src/lib/common/homestore_assert.hpp @@ -17,6 +17,7 @@ #include #include +#include #include #include #include @@ -389,6 +390,9 @@ if (happened) { // Always log first occurrence (new entry) should_log = true; + } else if (freq == 0 && interval_sec == 0) { + // Both rate limiters disabled: always log (fallback behavior) + should_log = true; } else if (freq > 0 && count % freq == 0) { // Count-based: log every Nth occurrence should_log = true; From 7643a6b972c24a793a5e9478b1e9b6e62c0e93ea Mon Sep 17 00:00:00 2001 From: Xiaoxi Chen Date: Fri, 8 May 2026 13:23:59 +0800 Subject: [PATCH 5/5] Add documentation and warning for interval_sec > 300s - Add function comment documenting the 300s cleanup limitation - Log one-time warning when interval_sec exceeds cleanup period - Clarifies expected behavior when using large interval_sec values Co-Authored-By: Claude Opus 4.6 --- src/lib/common/homestore_assert.hpp | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/src/lib/common/homestore_assert.hpp b/src/lib/common/homestore_assert.hpp index 7b4633266..690021f1a 100644 --- a/src/lib/common/homestore_assert.hpp +++ b/src/lib/common/homestore_assert.hpp @@ -353,6 +353,13 @@ #define HS_REL_ASSERT_NULL(val, ...) HS_ASSERT_NULL(RELEASE_ASSERT_CMP, val, ##__VA_ARGS__) #define HS_REL_ASSERT_NOTNULL(val, ...) HS_ASSERT_NOTNULL(RELEASE_ASSERT_CMP, val, ##__VA_ARGS__) +/** + * Rate-limited logging helper with count-based and time-based controls. + * + * State is cleaned up every 300 seconds to prevent unbounded memory growth. + * This means time-based rate limiting works correctly only when interval_sec < 300. + * If interval_sec >= 300, the behavior effectively becomes "log first occurrence after each 5min reset." + */ [[maybe_unused]] static bool check_and_format_log(fmt::memory_buffer& buf, uint64_t freq = 0, uint64_t interval_sec = 0) { static constexpr uint64_t COUNTER_RESET_SEC{300}; // Reset every 5 minutes @@ -360,6 +367,16 @@ static thread_local std::unordered_map< size_t, std::pair< uint32_t, uint64_t > > log_map{}; // hash -> (last_log_ms, count) + // Warn once if interval_sec exceeds cleanup period + if (interval_sec > COUNTER_RESET_SEC) { + static thread_local bool warned = false; + if (!warned) { + LOGWARN("interval_sec={} exceeds cleanup period ({}s) - time-based rate limiting may not work as expected", + interval_sec, COUNTER_RESET_SEC); + warned = true; + } + } + const auto now = Clock::now(); if (get_elapsed_time_sec(last_cleanup) > COUNTER_RESET_SEC) { std::unordered_map< size_t, std::pair< uint32_t, uint64_t > >().swap(log_map); // Actually release memory