From c34d1a77051d23b73ba991b48d4f9b3ef949e7e5 Mon Sep 17 00:00:00 2001
From: Benny Halevy <bhalevy@scylladb.com>
Date: Tue, 3 May 2022 09:32:08 +0300
Subject: [PATCH 01/19] utils: logalloc: reclaim_timer round up microseconds

better report 29000 us than 28999 us.

Signed-off-by: Benny Halevy <bhalevy@scylladb.com>
---
 utils/logalloc.cc | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index 3ff0254fdd..9f89282b8d 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -2193,7 +2193,7 @@ private:
         auto MiB = 1024*1024;
 
         timing_logger.log(time_level, "Reclamation cycle took {} us, trying to release {:.3f} MiB {}preemptibly",
-                          _duration / 1us, (float)_memory_to_release / MiB, _preemptible ? "" : "non-");
+                          (_duration + 500ns) / 1us, (float)_memory_to_release / MiB, _preemptible ? "" : "non-");
         log_if_any(info_level, "reserved segments", _reserve_segments);
         if (_memory_released > 0) {
             auto bytes_per_second =

From 5ce0038e6a2be29b111f2268bca6f720a23a750e Mon Sep 17 00:00:00 2001
From: Benny Halevy <bhalevy@scylladb.com>
Date: Tue, 3 May 2022 11:17:35 +0300
Subject: [PATCH 02/19] utils: logalloc: reclaim_timer: rename
 _reserve_segments member

Rename reclaim_timer::_reserve_segments to _segments_to_release
as it is clearer and more suitable for later patches
that will add reclaim_timers in more functions.

Signed-off-by: Benny Halevy <bhalevy@scylladb.com>
---
 utils/logalloc.cc | 8 ++++----
 1 file changed, 4 insertions(+), 4 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index 9f89282b8d..e41e67e906 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -2127,7 +2127,7 @@ class reclaim_timer {
 
     const is_preemptible _preemptible;
     const size_t _memory_to_release;
-    const size_t _reserve_segments;
+    const size_t _segments_to_release;
     tracker::impl& _tracker;
 
     const bool _debug_enabled;
@@ -2141,10 +2141,10 @@ class reclaim_timer {
     segment_pool::stats _old_pool_stats;
 
 public:
-    reclaim_timer(is_preemptible preemptible, size_t memory_to_release, size_t reserve_segments, tracker::impl& tracker)
+    reclaim_timer(is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl& tracker)
         : _preemptible(preemptible)
         , _memory_to_release(memory_to_release)
-        , _reserve_segments(reserve_segments)
+        , _segments_to_release(segments_to_release)
         , _tracker(tracker)
         , _debug_enabled(timing_logger.is_enabled(logging::log_level::debug))
     {
@@ -2194,7 +2194,7 @@ private:
 
         timing_logger.log(time_level, "Reclamation cycle took {} us, trying to release {:.3f} MiB {}preemptibly",
                           (_duration + 500ns) / 1us, (float)_memory_to_release / MiB, _preemptible ? "" : "non-");
-        log_if_any(info_level, "reserved segments", _reserve_segments);
+        log_if_any(info_level, "segments to release", _segments_to_release);
         if (_memory_released > 0) {
             auto bytes_per_second =
                 static_cast<float>(_memory_released) / std::chrono::duration_cast<std::chrono::duration<float>>(_duration).count();

From c4d64c3bf702e85a88356153162b6d97d073f9b0 Mon Sep 17 00:00:00 2001
From: Benny Halevy <bhalevy@scylladb.com>
Date: Tue, 3 May 2022 11:36:16 +0300
Subject: [PATCH 03/19] utils: logalloc: reclaim_timer: rename set_result

Rename set_result to set_memory_released
to make it clearer what the result means.

Signed-off-by: Benny Halevy <bhalevy@scylladb.com>
---
 utils/logalloc.cc | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index e41e67e906..73922750d5 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -2155,7 +2155,7 @@ public:
         _old_pool_stats = shard_segment_pool.statistics();
     }
 
-    size_t set_result(size_t memory_released) noexcept {
+    size_t set_memory_released(size_t memory_released) noexcept {
         return this->_memory_released = memory_released;
     }
 
@@ -2253,7 +2253,7 @@ size_t tracker::impl::reclaim(size_t memory_to_release, is_preemptible preempt)
     }
     reclaiming_lock rl(*this);
     reclaim_timer timing_guard(preempt, memory_to_release, 0, *this);
-    return timing_guard.set_result(reclaim_locked(memory_to_release, preempt));
+    return timing_guard.set_memory_released(reclaim_locked(memory_to_release, preempt));
 }
 
 size_t tracker::impl::reclaim_locked(size_t memory_to_release, is_preemptible preempt) {
@@ -2296,7 +2296,7 @@ size_t tracker::impl::compact_and_evict(size_t reserve_segments, size_t memory_t
     }
     reclaiming_lock rl(*this);
     reclaim_timer timing_guard(preempt, memory_to_release, reserve_segments, *this);
-    return timing_guard.set_result(compact_and_evict_locked(reserve_segments, memory_to_release, preempt));
+    return timing_guard.set_memory_released(compact_and_evict_locked(reserve_segments, memory_to_release, preempt));
 }
 
 size_t tracker::impl::compact_and_evict_locked(size_t reserve_segments, size_t memory_to_release, is_preemptible preempt) {

From 239992f16c47e9d791fd66dd5d7c29eed480dd02 Mon Sep 17 00:00:00 2001
From: Benny Halevy <bhalevy@scylladb.com>
Date: Tue, 3 May 2022 11:21:13 +0300
Subject: [PATCH 04/19] utils: logalloc: reclaim_timer: get call site name

Before adding even more call sites, print the call site
name in the report.

Signed-off-by: Benny Halevy <bhalevy@scylladb.com>
---
 utils/logalloc.cc | 14 ++++++++------
 1 file changed, 8 insertions(+), 6 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index 73922750d5..71913fc541 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -2125,6 +2125,7 @@ static void reclaim_from_evictable(region::impl& r, size_t target_mem_in_use, is
 class reclaim_timer {
     using clock = utils::coarse_steady_clock;
 
+    const char* _name;
     const is_preemptible _preemptible;
     const size_t _memory_to_release;
     const size_t _segments_to_release;
@@ -2141,8 +2142,9 @@ class reclaim_timer {
     segment_pool::stats _old_pool_stats;
 
 public:
-    reclaim_timer(is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl& tracker)
-        : _preemptible(preemptible)
+    reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl& tracker)
+        : _name(name)
+        , _preemptible(preemptible)
         , _memory_to_release(memory_to_release)
         , _segments_to_release(segments_to_release)
         , _tracker(tracker)
@@ -2192,8 +2194,8 @@ private:
         auto info_level = _stall_detected ? log_level::info : log_level::debug;
         auto MiB = 1024*1024;
 
-        timing_logger.log(time_level, "Reclamation cycle took {} us, trying to release {:.3f} MiB {}preemptibly",
-                          (_duration + 500ns) / 1us, (float)_memory_to_release / MiB, _preemptible ? "" : "non-");
+        timing_logger.log(time_level, "{} took {} us, trying to release {:.3f} MiB {}preemptibly",
+                          _name, (_duration + 500ns) / 1us, (float)_memory_to_release / MiB, _preemptible ? "" : "non-");
         log_if_any(info_level, "segments to release", _segments_to_release);
         if (_memory_released > 0) {
             auto bytes_per_second =
@@ -2252,7 +2254,7 @@ size_t tracker::impl::reclaim(size_t memory_to_release, is_preemptible preempt)
         return 0;
     }
     reclaiming_lock rl(*this);
-    reclaim_timer timing_guard(preempt, memory_to_release, 0, *this);
+    reclaim_timer timing_guard("reclaim", preempt, memory_to_release, 0, *this);
     return timing_guard.set_memory_released(reclaim_locked(memory_to_release, preempt));
 }
 
@@ -2295,7 +2297,7 @@ size_t tracker::impl::compact_and_evict(size_t reserve_segments, size_t memory_t
         return 0;
     }
     reclaiming_lock rl(*this);
-    reclaim_timer timing_guard(preempt, memory_to_release, reserve_segments, *this);
+    reclaim_timer timing_guard("compact_and_evict", preempt, memory_to_release, reserve_segments, *this);
     return timing_guard.set_memory_released(compact_and_evict_locked(reserve_segments, memory_to_release, preempt));
 }
 

From acd82d3b25c556f72f09623eba6b9840644c3079 Mon Sep 17 00:00:00 2001
From: Benny Halevy <bhalevy@scylladb.com>
Date: Tue, 3 May 2022 11:40:50 +0300
Subject: [PATCH 05/19] utils: logalloc: reclaim_timer: print backtrace if
 stall detected

Signed-off-by: Benny Halevy <bhalevy@scylladb.com>
---
 utils/logalloc.cc | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index 71913fc541..045ac9a4e0 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -2193,9 +2193,11 @@ private:
         auto time_level = _stall_detected ? log_level::warn : log_level::debug;
         auto info_level = _stall_detected ? log_level::info : log_level::debug;
         auto MiB = 1024*1024;
+        auto msg_extra = _stall_detected ? fmt::format(", at {}", current_backtrace()) : "";
 
-        timing_logger.log(time_level, "{} took {} us, trying to release {:.3f} MiB {}preemptibly",
-                          _name, (_duration + 500ns) / 1us, (float)_memory_to_release / MiB, _preemptible ? "" : "non-");
+        timing_logger.log(time_level, "{} took {} us, trying to release {:.3f} MiB {}preemptibly{}",
+                          _name, (_duration + 500ns) / 1us, (float)_memory_to_release / MiB, _preemptible ? "" : "non-",
+                          msg_extra);
         log_if_any(info_level, "segments to release", _segments_to_release);
         if (_memory_released > 0) {
             auto bytes_per_second =

From 33785d261eb4740305fd5d3cf10e55159ba0ad99 Mon Sep 17 00:00:00 2001
From: Benny Halevy <bhalevy@scylladb.com>
Date: Tue, 3 May 2022 09:11:04 +0300
Subject: [PATCH 06/19] utils: logalloc: reclaim_timer make tracker optional

Signed-off-by: Benny Halevy <bhalevy@scylladb.com>
---
 utils/logalloc.cc | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index 045ac9a4e0..38426beebc 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -2129,7 +2129,7 @@ class reclaim_timer {
     const is_preemptible _preemptible;
     const size_t _memory_to_release;
     const size_t _segments_to_release;
-    tracker::impl& _tracker;
+    tracker::impl* _tracker;
 
     const bool _debug_enabled;
     bool _stall_detected = false;
@@ -2142,7 +2142,7 @@ class reclaim_timer {
     segment_pool::stats _old_pool_stats;
 
 public:
-    reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl& tracker)
+    reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker = nullptr)
         : _name(name)
         , _preemptible(preemptible)
         , _memory_to_release(memory_to_release)
@@ -2151,8 +2151,8 @@ public:
         , _debug_enabled(timing_logger.is_enabled(logging::log_level::debug))
     {
         _start = clock::now();
-        if (_debug_enabled) {
-            _old_region_occupancy = tracker.region_occupancy();
+        if (_debug_enabled && tracker) {
+            _old_region_occupancy = tracker->region_occupancy();
         }
         _old_pool_stats = shard_segment_pool.statistics();
     }
@@ -2204,9 +2204,9 @@ private:
                 static_cast<float>(_memory_released) / std::chrono::duration_cast<std::chrono::duration<float>>(_duration).count();
             timing_logger.log(info_level, "- reclamation rate = {} MiB/s", format("{:.3f}", bytes_per_second / MiB));
         }
-        if (_debug_enabled) {
+        if (_debug_enabled && _tracker) {
             log_if_changed(info_level, "occupancy of regions",
-                           _old_region_occupancy.used_fraction(), _tracker.region_occupancy().used_fraction());
+                           _old_region_occupancy.used_fraction(), _tracker->region_occupancy().used_fraction());
         }
 
         auto pool_stats = shard_segment_pool.statistics();
@@ -2256,7 +2256,7 @@ size_t tracker::impl::reclaim(size_t memory_to_release, is_preemptible preempt)
         return 0;
     }
     reclaiming_lock rl(*this);
-    reclaim_timer timing_guard("reclaim", preempt, memory_to_release, 0, *this);
+    reclaim_timer timing_guard("reclaim", preempt, memory_to_release, 0, this);
     return timing_guard.set_memory_released(reclaim_locked(memory_to_release, preempt));
 }
 
@@ -2299,7 +2299,7 @@ size_t tracker::impl::compact_and_evict(size_t reserve_segments, size_t memory_t
         return 0;
     }
     reclaiming_lock rl(*this);
-    reclaim_timer timing_guard("compact_and_evict", preempt, memory_to_release, reserve_segments, *this);
+    reclaim_timer timing_guard("compact_and_evict", preempt, memory_to_release, reserve_segments, this);
     return timing_guard.set_memory_released(compact_and_evict_locked(reserve_segments, memory_to_release, preempt));
 }
 

From fd2b4a4b7d59d74ab27483376d7d4fd08d5c694d Mon Sep 17 00:00:00 2001
From: Benny Halevy <bhalevy@scylladb.com>
Date: Tue, 3 May 2022 09:21:58 +0300
Subject: [PATCH 07/19] utils: logalloc: pull reclaim_timer definition forward

So it can be used in functions defined earlier in the source file
in the next patch.

Signed-off-by: Benny Halevy <bhalevy@scylladb.com>
---
 utils/logalloc.cc | 194 +++++++++++++++++++++++-----------------------
 1 file changed, 99 insertions(+), 95 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index 38426beebc..f4400524d5 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -879,6 +879,63 @@ public:
     size_t free_segments() const { return _free_segments; }
 };
 
+class reclaim_timer {
+    using clock = utils::coarse_steady_clock;
+
+    const char* _name;
+    const is_preemptible _preemptible;
+    const size_t _memory_to_release;
+    const size_t _segments_to_release;
+    tracker::impl* _tracker;
+
+    const bool _debug_enabled;
+    bool _stall_detected = false;
+
+    size_t _memory_released = 0;
+
+    clock::time_point _start;
+    clock::duration _duration;
+    occupancy_stats _old_region_occupancy;
+    segment_pool::stats _old_pool_stats;
+
+public:
+    inline reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker = nullptr);
+
+    ~reclaim_timer() {
+        _duration = clock::now() - _start;
+        _stall_detected = _duration >= engine().get_blocked_reactor_notify_ms();
+        if (_debug_enabled || _stall_detected) {
+            report();
+        }
+    }
+
+    size_t set_memory_released(size_t memory_released) noexcept {
+        return this->_memory_released = memory_released;
+    }
+
+private:
+    template <typename T>
+    void log_if_changed(log_level level, const char* name, T before, T now) const noexcept {
+        if (now != before) {
+            timing_logger.log(level, "- {}: {:.3f} -> {:.3f}", name, before, now);
+        }
+    }
+    template <typename T>
+    void log_if_any(log_level level, const char* name, T value) const noexcept {
+        if (value != 0) {
+            timing_logger.log(level, "- {}: {}", name, value);
+        }
+    }
+    template <typename T>
+    void log_if_any_mem(log_level level, const char* name, T value) const noexcept {
+        if (value != 0) {
+            timing_logger.log(level, "- {}: {:.3f} MiB", name, (float)value / (1024*1024));
+        }
+    }
+
+    void report() const noexcept;
+};
+
 size_t segment_pool::reclaim_segments(size_t target, is_preemptible preempt) {
     // Reclaimer tries to release segments occupying lower parts of the address
     // space.
@@ -1135,6 +1192,48 @@ segment::occupancy() {
     return { shard_segment_pool.descriptor(this).free_space(), segment::size };
 }
 
+reclaim_timer::reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker)
+    : _name(name)
+    , _preemptible(preemptible)
+    , _memory_to_release(memory_to_release)
+    , _segments_to_release(segments_to_release)
+    , _tracker(tracker)
+    , _debug_enabled(timing_logger.is_enabled(logging::log_level::debug))
+{
+    _start = clock::now();
+    if (_debug_enabled && tracker) {
+        _old_region_occupancy = tracker->region_occupancy();
+    }
+    _old_pool_stats = shard_segment_pool.statistics();
+}
+
+void reclaim_timer::report() const noexcept {
+    auto time_level = _stall_detected ? log_level::warn : log_level::debug;
+    auto info_level = _stall_detected ? log_level::info : log_level::debug;
+    auto MiB = 1024*1024;
+    auto msg_extra = _stall_detected ? fmt::format(", at {}", current_backtrace()) : "";
+
+    timing_logger.log(time_level, "{} took {} us, trying to release {:.3f} MiB {}preemptibly{}",
+                        _name, (_duration + 500ns) / 1us, (float)_memory_to_release / MiB, _preemptible ? "" : "non-",
+                        msg_extra);
+    log_if_any(info_level, "segments to release", _segments_to_release);
+    if (_memory_released > 0) {
+        auto bytes_per_second =
+            static_cast<float>(_memory_released) / std::chrono::duration_cast<std::chrono::duration<float>>(_duration).count();
+        timing_logger.log(info_level, "- reclamation rate = {} MiB/s", format("{:.3f}", bytes_per_second / MiB));
+    }
+    if (_debug_enabled && _tracker) {
+        log_if_changed(info_level, "occupancy of regions",
+                        _old_region_occupancy.used_fraction(), _tracker->region_occupancy().used_fraction());
+    }
+
+    auto pool_stats = shard_segment_pool.statistics();
+    log_if_any_mem(info_level, "evicted memory", pool_stats.memory_evicted - _old_pool_stats.memory_evicted);
+    log_if_any(info_level, "compacted segments", pool_stats.segments_compacted - _old_pool_stats.segments_compacted);
+    log_if_any_mem(info_level, "compacted memory", pool_stats.memory_compacted - _old_pool_stats.memory_compacted);
+    log_if_any_mem(info_level, "allocated memory", pool_stats.memory_allocated - _old_pool_stats.memory_allocated);
+}
+
 //
 // For interface documentation see logalloc::region and allocation_strategy.
 //
@@ -2122,101 +2221,6 @@ static void reclaim_from_evictable(region::impl& r, size_t target_mem_in_use, is
     }
 }
 
-class reclaim_timer {
-    using clock = utils::coarse_steady_clock;
-
-    const char* _name;
-    const is_preemptible _preemptible;
-    const size_t _memory_to_release;
-    const size_t _segments_to_release;
-    tracker::impl* _tracker;
-
-    const bool _debug_enabled;
-    bool _stall_detected = false;
-
-    size_t _memory_released = 0;
-
-    clock::time_point _start;
-    clock::duration _duration;
-    occupancy_stats _old_region_occupancy;
-    segment_pool::stats _old_pool_stats;
-
-public:
-    reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker = nullptr)
-        : _name(name)
-        , _preemptible(preemptible)
-        , _memory_to_release(memory_to_release)
-        , _segments_to_release(segments_to_release)
-        , _tracker(tracker)
-        , _debug_enabled(timing_logger.is_enabled(logging::log_level::debug))
-    {
-        _start = clock::now();
-        if (_debug_enabled && tracker) {
-            _old_region_occupancy = tracker->region_occupancy();
-        }
-        _old_pool_stats = shard_segment_pool.statistics();
-    }
-
-    size_t set_memory_released(size_t memory_released) noexcept {
-        return this->_memory_released = memory_released;
-    }
-
-    ~reclaim_timer() {
-        _duration = clock::now() - _start;
-        _stall_detected = _duration >= engine().get_blocked_reactor_notify_ms();
-        if (_debug_enabled || _stall_detected) {
-            report();
-        }
-    }
-
-private:
-    template <typename T>
-    void log_if_changed(log_level level, const char* name, T before, T now) const noexcept {
-        if (now != before) {
-            timing_logger.log(level, "- {}: {:.3f} -> {:.3f}", name, before, now);
-        }
-    }
-    template <typename T>
-    void log_if_any(log_level level, const char* name, T value) const noexcept {
-        if (value != 0) {
-            timing_logger.log(level, "- {}: {}", name, value);
-        }
-    }
-    template <typename T>
-    void log_if_any_mem(log_level level, const char* name, T value) const noexcept {
-        if (value != 0) {
-            timing_logger.log(level, "- {}: {:.3f} MiB", name, (float)value / (1024*1024));
-        }
-    }
-
-    void report() const noexcept {
-        auto time_level = _stall_detected ? log_level::warn : log_level::debug;
-        auto info_level = _stall_detected ? log_level::info : log_level::debug;
-        auto MiB = 1024*1024;
-        auto msg_extra = _stall_detected ? fmt::format(", at {}", current_backtrace()) : "";
-
-        timing_logger.log(time_level, "{} took {} us, trying to release {:.3f} MiB {}preemptibly{}",
-                          _name, (_duration + 500ns) / 1us, (float)_memory_to_release / MiB, _preemptible ? "" : "non-",
-                          msg_extra);
-        log_if_any(info_level, "segments to release", _segments_to_release);
-        if (_memory_released > 0) {
-            auto bytes_per_second =
-                static_cast<float>(_memory_released) / std::chrono::duration_cast<std::chrono::duration<float>>(_duration).count();
-            timing_logger.log(info_level, "- reclamation rate = {} MiB/s", format("{:.3f}", bytes_per_second / MiB));
-        }
-        if (_debug_enabled && _tracker) {
-            log_if_changed(info_level, "occupancy of regions",
-                           _old_region_occupancy.used_fraction(), _tracker->region_occupancy().used_fraction());
-        }
-
-        auto pool_stats = shard_segment_pool.statistics();
-        log_if_any_mem(info_level, "evicted memory", pool_stats.memory_evicted - _old_pool_stats.memory_evicted);
-        log_if_any(info_level, "compacted segments", pool_stats.segments_compacted - _old_pool_stats.segments_compacted);
-        log_if_any_mem(info_level, "compacted memory", pool_stats.memory_compacted - _old_pool_stats.memory_compacted);
-        log_if_any_mem(info_level, "allocated memory", pool_stats.memory_allocated - _old_pool_stats.memory_allocated);
-    }
-};
-
 idle_cpu_handler_result tracker::impl::compact_on_idle(work_waiting_on_reactor check_for_work) {
     if (!_reclaiming_enabled) {
         return idle_cpu_handler_result::no_more_work;

From 42db63d012122c751fd10da5fb9211b630c7f126 Mon Sep 17 00:00:00 2001
From: Benny Halevy <bhalevy@scylladb.com>
Date: Tue, 3 May 2022 09:06:06 +0300
Subject: [PATCH 08/19] utils: logalloc: move reclaim_timer to
 compact_and_evict_locked

track compact_and_evict_locked timing from
all call paths, not only from compact_and_evict.

Signed-off-by: Benny Halevy <bhalevy@scylladb.com>
---
 utils/logalloc.cc | 7 ++++---
 1 file changed, 4 insertions(+), 3 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index f4400524d5..34da016052 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -2303,11 +2303,12 @@ size_t tracker::impl::compact_and_evict(size_t reserve_segments, size_t memory_t
         return 0;
     }
     reclaiming_lock rl(*this);
-    reclaim_timer timing_guard("compact_and_evict", preempt, memory_to_release, reserve_segments, this);
-    return timing_guard.set_memory_released(compact_and_evict_locked(reserve_segments, memory_to_release, preempt));
+    return compact_and_evict_locked(reserve_segments, memory_to_release, preempt);
 }
 
 size_t tracker::impl::compact_and_evict_locked(size_t reserve_segments, size_t memory_to_release, is_preemptible preempt) {
+    reclaim_timer timing_guard("compact_and_evict_locked", preempt, memory_to_release, reserve_segments, this);
+
     llogger.debug("compact_and_evict_locked({}, {}, {})", reserve_segments, memory_to_release, int(bool(preempt)));
     //
     // Algorithm outline.
@@ -2405,7 +2406,7 @@ size_t tracker::impl::compact_and_evict_locked(size_t reserve_segments, size_t m
     llogger.debug("Released {} bytes (wanted {}), {} during compaction",
         mem_released, memory_to_release, released_during_compaction);
 
-    return mem_released;
+    return timing_guard.set_memory_released(mem_released);
 }
 
 void tracker::impl::register_region(region::impl* r) {

From 76ca93b7794bd94a2a63b8dce71b204617dd7879 Mon Sep 17 00:00:00 2001
From: Benny Halevy <bhalevy@scylladb.com>
Date: Tue, 3 May 2022 09:31:39 +0300
Subject: [PATCH 09/19] utils: logalloc: add more reclaim_timers

Measure stalls at higher resolution.

Refs #6189

Signed-off-by: Benny Halevy <bhalevy@scylladb.com>
---
 utils/logalloc.cc | 2 ++
 1 file changed, 2 insertions(+)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index 34da016052..d44c7a847f 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -939,6 +939,7 @@ private:
 size_t segment_pool::reclaim_segments(size_t target, is_preemptible preempt) {
     // Reclaimer tries to release segments occupying lower parts of the address
     // space.
+    reclaim_timer timing_guard("reclaim_segments", preempt, target * segment::size, target);
 
     llogger.debug("Trying to reclaim {} segments", target);
 
@@ -985,6 +986,7 @@ size_t segment_pool::reclaim_segments(size_t target, is_preemptible preempt) {
     }
 
     llogger.debug("Reclaimed {} segments (requested {})", reclaimed_segments, target);
+    timing_guard.set_memory_released(reclaimed_segments * segment::size);
     return reclaimed_segments;
 }
 

From 3fced6554259beb7304e273d7c8d050e8038b700 Mon Sep 17 00:00:00 2001
From: Michael Livshin <michael.livshin@scylladb.com>
Date: Thu, 12 May 2022 21:16:44 +0300
Subject: [PATCH 10/19] utils: logalloc: have reclaim timers detect being
 nested

Make sure that inner timers don't waste CPU measuring anything.

Signed-off-by: Michael Livshin <michael.livshin@scylladb.com>
---
 utils/logalloc.cc | 15 +++++++++++++++
 1 file changed, 15 insertions(+)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index d44c7a847f..f908fe999e 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -882,7 +882,10 @@ public:
 class reclaim_timer {
     using clock = utils::coarse_steady_clock;
 
+    static thread_local reclaim_timer* _active_timer;
+
     const char* _name;
+
     const is_preemptible _preemptible;
     const size_t _memory_to_release;
     const size_t _segments_to_release;
@@ -902,11 +905,17 @@ public:
     inline reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker = nullptr);
 
     ~reclaim_timer() {
+        if (_active_timer != this) {
+            return;
+        }
+
         _duration = clock::now() - _start;
         _stall_detected = _duration >= engine().get_blocked_reactor_notify_ms();
         if (_debug_enabled || _stall_detected) {
             report();
         }
+
+        _active_timer = nullptr;
     }
 
     size_t set_memory_released(size_t memory_released) noexcept {
@@ -1194,6 +1203,7 @@ segment::occupancy() {
     return { shard_segment_pool.descriptor(this).free_space(), segment::size };
 }
 
+thread_local reclaim_timer* reclaim_timer::_active_timer;
 reclaim_timer::reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker)
     : _name(name)
     , _preemptible(preemptible)
@@ -1202,6 +1212,11 @@ reclaim_timer::reclaim_timer(const char* name, is_preemptible preemptible, size_
     , _tracker(tracker)
     , _debug_enabled(timing_logger.is_enabled(logging::log_level::debug))
 {
+    if (_active_timer) {
+        return;
+    }
+    _active_timer = this;
+
     _start = clock::now();
     if (_debug_enabled && tracker) {
         _old_region_occupancy = tracker->region_occupancy();

From 0eefbfa3ccec3faada8a2fc2f0a82c8fb16ec633 Mon Sep 17 00:00:00 2001
From: Michael Livshin <michael.livshin@scylladb.com>
Date: Sun, 15 May 2022 22:30:12 +0300
Subject: [PATCH 11/19] utils: logalloc: add arithmetic operations to
 segment_pool::stats

Signed-off-by: Michael Livshin <michael.livshin@scylladb.com>
---
 utils/logalloc.cc | 29 +++++++++++++++++++++++++++++
 1 file changed, 29 insertions(+)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index f908fe999e..f0da1cf612 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -866,6 +866,35 @@ public:
         uint64_t memory_freed;
         uint64_t memory_compacted;
         uint64_t memory_evicted;
+
+        friend stats operator+(const stats& s1, const stats& s2) {
+            stats result(s1);
+            result += s2;
+            return result;
+        }
+        friend stats operator-(const stats& s1, const stats& s2) {
+            stats result(s1);
+            result -= s2;
+            return result;
+        }
+        stats& operator+=(const stats& other) {
+            segments_compacted += other.segments_compacted;
+            lsa_buffer_segments += other.lsa_buffer_segments;
+            memory_allocated += other.memory_allocated;
+            memory_freed += other.memory_freed;
+            memory_compacted += other.memory_compacted;
+            memory_evicted += other.memory_evicted;
+            return *this;
+        }
+        stats& operator-=(const stats& other) {
+            segments_compacted -= other.segments_compacted;
+            lsa_buffer_segments -= other.lsa_buffer_segments;
+            memory_allocated -= other.memory_allocated;
+            memory_freed -= other.memory_freed;
+            memory_compacted -= other.memory_compacted;
+            memory_evicted -= other.memory_evicted;
+            return *this;
+        }
     };
 private:
     stats _stats{};

From c15e384507f5098231dfdad877cf0a000a474a3c Mon Sep 17 00:00:00 2001
From: Michael Livshin <michael.livshin@scylladb.com>
Date: Sun, 15 May 2022 22:44:51 +0300
Subject: [PATCH 12/19] utils: logalloc: define a proper bundle type for
 reclaim_timer stats

And define/use arithmetics on it.

Signed-off-by: Michael Livshin <michael.livshin@scylladb.com>
---
 utils/logalloc.cc | 55 +++++++++++++++++++++++++++++++++++++----------
 1 file changed, 44 insertions(+), 11 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index f0da1cf612..fbe392112d 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -910,6 +910,31 @@ public:
 
 class reclaim_timer {
     using clock = utils::coarse_steady_clock;
+    struct stats {
+        occupancy_stats region_occupancy;
+        segment_pool::stats pool_stats;
+
+        friend stats operator+(const stats& s1, const stats& s2) {
+            stats result(s1);
+            result += s2;
+            return result;
+        }
+        friend stats operator-(const stats& s1, const stats& s2) {
+            stats result(s1);
+            result -= s2;
+            return result;
+        }
+        stats& operator+=(const stats& other) {
+            region_occupancy += other.region_occupancy;
+            pool_stats += other.pool_stats;
+            return *this;
+        }
+        stats& operator-=(const stats& other) {
+            region_occupancy -= other.region_occupancy;
+            pool_stats -= other.pool_stats;
+            return *this;
+        }
+    };
 
     static thread_local reclaim_timer* _active_timer;
 
@@ -926,9 +951,9 @@ class reclaim_timer {
     size_t _memory_released = 0;
 
     clock::time_point _start;
+    stats _start_stats, _end_stats, _stat_diff;
+
     clock::duration _duration;
-    occupancy_stats _old_region_occupancy;
-    segment_pool::stats _old_pool_stats;
 
 public:
     inline reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker = nullptr);
@@ -941,6 +966,8 @@ public:
         _duration = clock::now() - _start;
         _stall_detected = _duration >= engine().get_blocked_reactor_notify_ms();
         if (_debug_enabled || _stall_detected) {
+            sample_stats(_end_stats);
+            _stat_diff = _end_stats - _start_stats;
             report();
         }
 
@@ -952,6 +979,7 @@ public:
     }
 
 private:
+    void sample_stats(stats& data);
     template <typename T>
     void log_if_changed(log_level level, const char* name, T before, T now) const noexcept {
         if (now != before) {
@@ -1247,10 +1275,14 @@ reclaim_timer::reclaim_timer(const char* name, is_preemptible preemptible, size_
     _active_timer = this;
 
     _start = clock::now();
-    if (_debug_enabled && tracker) {
-        _old_region_occupancy = tracker->region_occupancy();
+    sample_stats(_start_stats);
+}
+
+void reclaim_timer::sample_stats(stats& data) {
+    if (_debug_enabled && _tracker) {
+        data.region_occupancy = _tracker->region_occupancy();
     }
-    _old_pool_stats = shard_segment_pool.statistics();
+    data.pool_stats = shard_segment_pool.statistics();
 }
 
 void reclaim_timer::report() const noexcept {
@@ -1268,16 +1300,17 @@ void reclaim_timer::report() const noexcept {
             static_cast<float>(_memory_released) / std::chrono::duration_cast<std::chrono::duration<float>>(_duration).count();
         timing_logger.log(info_level, "- reclamation rate = {} MiB/s", format("{:.3f}", bytes_per_second / MiB));
     }
+
     if (_debug_enabled && _tracker) {
         log_if_changed(info_level, "occupancy of regions",
-                        _old_region_occupancy.used_fraction(), _tracker->region_occupancy().used_fraction());
+                        _start_stats.region_occupancy.used_fraction(), _end_stats.region_occupancy.used_fraction());
     }
 
-    auto pool_stats = shard_segment_pool.statistics();
-    log_if_any_mem(info_level, "evicted memory", pool_stats.memory_evicted - _old_pool_stats.memory_evicted);
-    log_if_any(info_level, "compacted segments", pool_stats.segments_compacted - _old_pool_stats.segments_compacted);
-    log_if_any_mem(info_level, "compacted memory", pool_stats.memory_compacted - _old_pool_stats.memory_compacted);
-    log_if_any_mem(info_level, "allocated memory", pool_stats.memory_allocated - _old_pool_stats.memory_allocated);
+    auto pool_diff = _stat_diff.pool_stats;
+    log_if_any_mem(info_level, "evicted memory", pool_diff.memory_evicted);
+    log_if_any(info_level, "compacted segments", pool_diff.segments_compacted);
+    log_if_any_mem(info_level, "compacted memory", pool_diff.memory_compacted);
+    log_if_any_mem(info_level, "allocated memory", pool_diff.memory_allocated);
 }
 
 //

From 256b911fbd4876ba1675563b990bec2cc646ffeb Mon Sep 17 00:00:00 2001
From: Michael Livshin <michael.livshin@scylladb.com>
Date: Tue, 14 Jun 2022 10:23:17 +0300
Subject: [PATCH 13/19] utils: logalloc: move reclaim timer destructor for more
 readability

Signed-off-by: Michael Livshin <michael.livshin@scylladb.com>
---
 utils/logalloc.cc | 32 +++++++++++++++++---------------
 1 file changed, 17 insertions(+), 15 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index fbe392112d..73509602e4 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -958,21 +958,7 @@ class reclaim_timer {
 public:
     inline reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker = nullptr);
 
-    ~reclaim_timer() {
-        if (_active_timer != this) {
-            return;
-        }
-
-        _duration = clock::now() - _start;
-        _stall_detected = _duration >= engine().get_blocked_reactor_notify_ms();
-        if (_debug_enabled || _stall_detected) {
-            sample_stats(_end_stats);
-            _stat_diff = _end_stats - _start_stats;
-            report();
-        }
-
-        _active_timer = nullptr;
-    }
+    inline ~reclaim_timer();
 
     size_t set_memory_released(size_t memory_released) noexcept {
         return this->_memory_released = memory_released;
@@ -1278,6 +1264,22 @@ reclaim_timer::reclaim_timer(const char* name, is_preemptible preemptible, size_
     sample_stats(_start_stats);
 }
 
+reclaim_timer::~reclaim_timer() {
+    if (_active_timer != this) {
+        return;
+    }
+
+    _duration = clock::now() - _start;
+    _stall_detected = _duration >= engine().get_blocked_reactor_notify_ms();
+    if (_debug_enabled || _stall_detected) {
+        sample_stats(_end_stats);
+        _stat_diff = _end_stats - _start_stats;
+        report();
+    }
+
+    _active_timer = nullptr;
+}
+
 void reclaim_timer::sample_stats(stats& data) {
     if (_debug_enabled && _tracker) {
         data.region_occupancy = _tracker->region_occupancy();

From 07fdcb268e630dd7e2d4254cc7998870b5947a0c Mon Sep 17 00:00:00 2001
From: Michael Livshin <michael.livshin@scylladb.com>
Date: Tue, 14 Jun 2022 13:36:24 +0300
Subject: [PATCH 14/19] utils: logalloc: have reclaim_timer print reserve
 limits

Signed-off-by: Michael Livshin <michael.livshin@scylladb.com>
---
 utils/logalloc.cc | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index 73509602e4..3723b88c5e 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -943,6 +943,7 @@ class reclaim_timer {
     const is_preemptible _preemptible;
     const size_t _memory_to_release;
     const size_t _segments_to_release;
+    const size_t _reserve_goal, _reserve_max;
     tracker::impl* _tracker;
 
     const bool _debug_enabled;
@@ -1252,6 +1253,8 @@ reclaim_timer::reclaim_timer(const char* name, is_preemptible preemptible, size_
     , _preemptible(preemptible)
     , _memory_to_release(memory_to_release)
     , _segments_to_release(segments_to_release)
+    , _reserve_goal(shard_segment_pool.current_emergency_reserve_goal())
+    , _reserve_max(shard_segment_pool.emergency_reserve_max())
     , _tracker(tracker)
     , _debug_enabled(timing_logger.is_enabled(logging::log_level::debug))
 {
@@ -1293,8 +1296,9 @@ void reclaim_timer::report() const noexcept {
     auto MiB = 1024*1024;
     auto msg_extra = _stall_detected ? fmt::format(", at {}", current_backtrace()) : "";
 
-    timing_logger.log(time_level, "{} took {} us, trying to release {:.3f} MiB {}preemptibly{}",
+    timing_logger.log(time_level, "{} took {} us, trying to release {:.3f} MiB {}preemptibly, reserve: {{goal: {}, max: {}}}{}",
                         _name, (_duration + 500ns) / 1us, (float)_memory_to_release / MiB, _preemptible ? "" : "non-",
+                        _reserve_goal, _reserve_max,
                         msg_extra);
     log_if_any(info_level, "segments to release", _segments_to_release);
     if (_memory_released > 0) {

From abd7b9f01ce15f10e00938103dcacccad780930d Mon Sep 17 00:00:00 2001
From: Michael Livshin <michael.livshin@scylladb.com>
Date: Tue, 14 Jun 2022 14:55:47 +0300
Subject: [PATCH 15/19] utils: logalloc: reclaim_timer: report non-decreasing
 durations

The hope is that this reduces logspam without losing utility.

Signed-off-by: Michael Livshin <michael.livshin@scylladb.com>
---
 utils/logalloc.cc | 9 ++++++++-
 1 file changed, 8 insertions(+), 1 deletion(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index 3723b88c5e..b773570f8d 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -937,6 +937,7 @@ class reclaim_timer {
     };
 
     static thread_local reclaim_timer* _active_timer;
+    static thread_local clock::duration _duration_threshold;
 
     const char* _name;
 
@@ -1248,6 +1249,8 @@ segment::occupancy() {
 }
 
 thread_local reclaim_timer* reclaim_timer::_active_timer;
+thread_local clock::duration reclaim_timer::_duration_threshold = clock::duration::zero();
+
 reclaim_timer::reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker)
     : _name(name)
     , _preemptible(preemptible)
@@ -1265,6 +1268,10 @@ reclaim_timer::reclaim_timer(const char* name, is_preemptible preemptible, size_
 
     _start = clock::now();
     sample_stats(_start_stats);
+
+    if (_duration_threshold == clock::duration::zero()) {
+        _duration_threshold = engine().get_blocked_reactor_notify_ms();
+    }
 }
 
 reclaim_timer::~reclaim_timer() {
@@ -1273,7 +1280,7 @@ reclaim_timer::~reclaim_timer() {
     }
 
     _duration = clock::now() - _start;
-    _stall_detected = _duration >= engine().get_blocked_reactor_notify_ms();
+    _stall_detected = _duration >= _duration_threshold;
     if (_debug_enabled || _stall_detected) {
         sample_stats(_end_stats);
         _stat_diff = _end_stats - _start_stats;

From 1d700442ae5f6d9801fa75c3e0bb8e09ce1ea580 Mon Sep 17 00:00:00 2001
From: Michael Livshin <michael.livshin@scylladb.com>
Date: Sat, 25 Jun 2022 22:15:08 +0300
Subject: [PATCH 16/19] utils: logalloc: reclaim_timer: add optional extra log
 callback

The idea is to let the caller add arbitrary extra info to the timeout
report.

Signed-off-by: Michael Livshin <michael.livshin@scylladb.com>
---
 utils/logalloc.cc | 14 +++++++++++---
 1 file changed, 11 insertions(+), 3 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index b773570f8d..c6396d5f64 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -908,7 +908,9 @@ public:
     size_t free_segments() const { return _free_segments; }
 };
 
-class reclaim_timer {
+struct reclaim_timer {
+    using extra_logger = noncopyable_function<void(log_level)>;
+private:
     using clock = utils::coarse_steady_clock;
     struct stats {
         occupancy_stats region_occupancy;
@@ -946,6 +948,7 @@ class reclaim_timer {
     const size_t _segments_to_release;
     const size_t _reserve_goal, _reserve_max;
     tracker::impl* _tracker;
+    extra_logger _extra_logs;
 
     const bool _debug_enabled;
     bool _stall_detected = false;
@@ -958,7 +961,10 @@ class reclaim_timer {
     clock::duration _duration;
 
 public:
-    inline reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker = nullptr);
+    inline reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker, extra_logger extra_logs = [](log_level){});
+    inline reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, extra_logger extra_logs = [](log_level){})
+        : reclaim_timer(name, preemptible, memory_to_release, segments_to_release, nullptr, std::move(extra_logs))
+    {}
 
     inline ~reclaim_timer();
 
@@ -1251,7 +1257,7 @@ segment::occupancy() {
 thread_local reclaim_timer* reclaim_timer::_active_timer;
 thread_local clock::duration reclaim_timer::_duration_threshold = clock::duration::zero();
 
-reclaim_timer::reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker)
+reclaim_timer::reclaim_timer(const char* name, is_preemptible preemptible, size_t memory_to_release, size_t segments_to_release, tracker::impl* tracker, extra_logger extra_logs)
     : _name(name)
     , _preemptible(preemptible)
     , _memory_to_release(memory_to_release)
@@ -1259,6 +1265,7 @@ reclaim_timer::reclaim_timer(const char* name, is_preemptible preemptible, size_
     , _reserve_goal(shard_segment_pool.current_emergency_reserve_goal())
     , _reserve_max(shard_segment_pool.emergency_reserve_max())
     , _tracker(tracker)
+    , _extra_logs(std::move(extra_logs))
     , _debug_enabled(timing_logger.is_enabled(logging::log_level::debug))
 {
     if (_active_timer) {
@@ -1308,6 +1315,7 @@ void reclaim_timer::report() const noexcept {
                         _reserve_goal, _reserve_max,
                         msg_extra);
     log_if_any(info_level, "segments to release", _segments_to_release);
+    _extra_logs(info_level);
     if (_memory_released > 0) {
         auto bytes_per_second =
             static_cast<float>(_memory_released) / std::chrono::duration_cast<std::chrono::duration<float>>(_duration).count();

From 007d8fb5c9ebb3904e0a0b76ff92dae4fd70ac96 Mon Sep 17 00:00:00 2001
From: Michael Livshin <michael.livshin@scylladb.com>
Date: Sat, 25 Jun 2022 22:18:39 +0300
Subject: [PATCH 17/19] utils: logalloc: report segment stats if
 reclaim_segments() times out

Signed-off-by: Michael Livshin <michael.livshin@scylladb.com>
---
 utils/logalloc.cc | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index c6396d5f64..8bae80de74 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -999,13 +999,15 @@ private:
 size_t segment_pool::reclaim_segments(size_t target, is_preemptible preempt) {
     // Reclaimer tries to release segments occupying lower parts of the address
     // space.
-    reclaim_timer timing_guard("reclaim_segments", preempt, target * segment::size, target);
-
     llogger.debug("Trying to reclaim {} segments", target);
 
     // Reclamation. Migrate segments to higher addresses and shrink segment pool.
     size_t reclaimed_segments = 0;
 
+    reclaim_timer timing_guard("reclaim_segments", preempt, target * segment::size, target, [&] (log_level level) {
+        timing_logger.log(level, "- reclaimed {} out of requested {} segments", reclaimed_segments, target);
+    });
+
     // We may fail to reclaim because a region has reclaim disabled (usually because
     // it is in an allocating_section. Failed reclaims can cause high CPU usage
     // if all of the lower addresses happen to be in a reclaim-disabled region (this

From bcb7404a0e33860e799e0d69a5b7c8982020c79a Mon Sep 17 00:00:00 2001
From: Michael Livshin <michael.livshin@scylladb.com>
Date: Sat, 25 Jun 2022 22:20:44 +0300
Subject: [PATCH 18/19] utils: logalloc: split the reclaim_timer in
 compact_and_evict_locked()

(Into one for the compact part and one for the evict part)

Signed-off-by: Michael Livshin <michael.livshin@scylladb.com>
---
 utils/logalloc.cc | 19 ++++++++++++++++---
 1 file changed, 16 insertions(+), 3 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index 8bae80de74..f54d7da9be 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -2409,8 +2409,6 @@ size_t tracker::impl::compact_and_evict(size_t reserve_segments, size_t memory_t
 }
 
 size_t tracker::impl::compact_and_evict_locked(size_t reserve_segments, size_t memory_to_release, is_preemptible preempt) {
-    reclaim_timer timing_guard("compact_and_evict_locked", preempt, memory_to_release, reserve_segments, this);
-
     llogger.debug("compact_and_evict_locked({}, {}, {})", reserve_segments, memory_to_release, int(bool(preempt)));
     //
     // Algorithm outline.
@@ -2459,6 +2457,12 @@ size_t tracker::impl::compact_and_evict_locked(size_t reserve_segments, size_t m
         }
     }
 
+    {
+    int regions = 0, evictable_regions = 0;
+    reclaim_timer timing_guard("compact", preempt, memory_to_release, reserve_segments, this, [&] (log_level level) {
+        timing_logger.log(level, "- processed {} regions: reclaimed from {}, compacted {}",
+                          regions, evictable_regions, regions - evictable_regions);
+    });
     while (shard_segment_pool.total_memory_in_use() > target_mem) {
         boost::range::pop_heap(_regions, cmp);
         region::impl* r = _regions.back();
@@ -2467,6 +2471,7 @@ size_t tracker::impl::compact_and_evict_locked(size_t reserve_segments, size_t m
             llogger.trace("Unable to release segments, no compactible pools.");
             break;
         }
+        ++regions;
 
         // Prefer evicting if average occupancy ratio is above the compaction threshold to avoid
         // overhead of compaction in workloads where allocation order matches eviction order, where
@@ -2474,6 +2479,7 @@ size_t tracker::impl::compact_and_evict_locked(size_t reserve_segments, size_t m
         // would be higher than the cost of repopulating the region with evicted items.
         if (r->is_evictable() && r->occupancy().used_space() >= max_used_space_ratio_for_compaction * r->occupancy().total_space()) {
             reclaim_from_evictable(*r, target_mem, preempt);
+            ++evictable_regions;
         } else {
             r->compact();
         }
@@ -2484,17 +2490,24 @@ size_t tracker::impl::compact_and_evict_locked(size_t reserve_segments, size_t m
             break;
         }
     }
+    }
 
     auto released_during_compaction = mem_in_use - shard_segment_pool.total_memory_in_use();
 
     if (shard_segment_pool.total_memory_in_use() > target_mem) {
+        int regions = 0, evictable_regions = 0;
+        reclaim_timer timing_guard("evict", preempt, memory_to_release, reserve_segments, this, [&] (log_level level) {
+            timing_logger.log(level, "- processed {} regions, reclaimed from {}", regions, evictable_regions);
+        });
         llogger.debug("Considering evictable regions.");
         // FIXME: Fair eviction
         for (region::impl* r : _regions) {
             if (preempt && need_preempt()) {
                 break;
             }
+            ++regions;
             if (r->is_evictable()) {
+                ++evictable_regions;
                 reclaim_from_evictable(*r, target_mem, preempt);
                 if (shard_segment_pool.total_memory_in_use() <= target_mem) {
                     break;
@@ -2508,7 +2521,7 @@ size_t tracker::impl::compact_and_evict_locked(size_t reserve_segments, size_t m
     llogger.debug("Released {} bytes (wanted {}), {} during compaction",
         mem_released, memory_to_release, released_during_compaction);
 
-    return timing_guard.set_memory_released(mem_released);
+    return mem_released;
 }
 
 void tracker::impl::register_region(region::impl* r) {

From ca21ce8e6f8fd3bc2d054fa1233605cffb6f6e8e Mon Sep 17 00:00:00 2001
From: Michael Livshin <michael.livshin@scylladb.com>
Date: Sat, 25 Jun 2022 22:10:01 +0300
Subject: [PATCH 19/19] utils: logalloc: fix indentation

Signed-off-by: Michael Livshin <michael.livshin@scylladb.com>
---
 utils/logalloc.cc | 60 +++++++++++++++++++++++------------------------
 1 file changed, 30 insertions(+), 30 deletions(-)

diff --git a/utils/logalloc.cc b/utils/logalloc.cc
index f54d7da9be..90ee0ba468 100644
--- a/utils/logalloc.cc
+++ b/utils/logalloc.cc
@@ -2458,38 +2458,38 @@ size_t tracker::impl::compact_and_evict_locked(size_t reserve_segments, size_t m
     }
 
     {
-    int regions = 0, evictable_regions = 0;
-    reclaim_timer timing_guard("compact", preempt, memory_to_release, reserve_segments, this, [&] (log_level level) {
-        timing_logger.log(level, "- processed {} regions: reclaimed from {}, compacted {}",
-                          regions, evictable_regions, regions - evictable_regions);
-    });
-    while (shard_segment_pool.total_memory_in_use() > target_mem) {
-        boost::range::pop_heap(_regions, cmp);
-        region::impl* r = _regions.back();
+        int regions = 0, evictable_regions = 0;
+        reclaim_timer timing_guard("compact", preempt, memory_to_release, reserve_segments, this, [&] (log_level level) {
+            timing_logger.log(level, "- processed {} regions: reclaimed from {}, compacted {}",
+                              regions, evictable_regions, regions - evictable_regions);
+        });
+        while (shard_segment_pool.total_memory_in_use() > target_mem) {
+            boost::range::pop_heap(_regions, cmp);
+            region::impl* r = _regions.back();
 
-        if (!r->is_compactible()) {
-            llogger.trace("Unable to release segments, no compactible pools.");
-            break;
+            if (!r->is_compactible()) {
+                llogger.trace("Unable to release segments, no compactible pools.");
+                break;
+            }
+            ++regions;
+
+            // Prefer evicting if average occupancy ratio is above the compaction threshold to avoid
+            // overhead of compaction in workloads where allocation order matches eviction order, where
+            // we can reclaim memory by eviction only. In some cases the cost of compaction on allocation
+            // would be higher than the cost of repopulating the region with evicted items.
+            if (r->is_evictable() && r->occupancy().used_space() >= max_used_space_ratio_for_compaction * r->occupancy().total_space()) {
+                reclaim_from_evictable(*r, target_mem, preempt);
+                ++evictable_regions;
+            } else {
+                r->compact();
+            }
+
+            boost::range::push_heap(_regions, cmp);
+
+            if (preempt && need_preempt()) {
+                break;
+            }
         }
-        ++regions;
-
-        // Prefer evicting if average occupancy ratio is above the compaction threshold to avoid
-        // overhead of compaction in workloads where allocation order matches eviction order, where
-        // we can reclaim memory by eviction only. In some cases the cost of compaction on allocation
-        // would be higher than the cost of repopulating the region with evicted items.
-        if (r->is_evictable() && r->occupancy().used_space() >= max_used_space_ratio_for_compaction * r->occupancy().total_space()) {
-            reclaim_from_evictable(*r, target_mem, preempt);
-            ++evictable_regions;
-        } else {
-            r->compact();
-        }
-
-        boost::range::push_heap(_regions, cmp);
-
-        if (preempt && need_preempt()) {
-            break;
-        }
-    }
     }
 
     auto released_during_compaction = mem_in_use - shard_segment_pool.total_memory_in_use();