From 78195b02185d80ac0e8b5c705d44fd7f35b670ce Mon Sep 17 00:00:00 2001 From: Roland Conybeare Date: Fri, 22 Aug 2025 15:10:56 -0400 Subject: [PATCH] xo-alloc: + timing stats + timeseries tooltips --- include/xo/alloc/GC.hpp | 5 ++- include/xo/alloc/GcStatistics.hpp | 75 +++++++++++++++++++++++-------- src/alloc/CMakeLists.txt | 1 + src/alloc/GC.cpp | 55 +++++++++++++++-------- src/alloc/GcStatistics.cpp | 14 +++++- 5 files changed, 110 insertions(+), 40 deletions(-) diff --git a/include/xo/alloc/GC.hpp b/include/xo/alloc/GC.hpp index ab58b902..7c4f42c6 100644 --- a/include/xo/alloc/GC.hpp +++ b/include/xo/alloc/GC.hpp @@ -132,6 +132,7 @@ namespace xo { public: using CallbackId = xo::fn::CallbackId; using GcCopyCallbackSet = xo::fn::UpCallbackSet; + using nanos = decltype(xo::qty::qty::nanosecond); public: /** create new GC instance with configuration @p config **/ @@ -224,6 +225,8 @@ namespace xo { * as number of calls to @ref disable_gc. **/ void enable_gc(); + /** same as @c this->enable_gc() followed by @c this->disable_gc() **/ + void enable_gc_once(); // inherited from IAlloc.. @@ -279,7 +282,7 @@ namespace xo { /** begin GC now **/ void execute_gc(generation g); /** cleanup phase. aux function for @ref execute_gc **/ - void cleanup_phase(generation g); + void cleanup_phase(generation g, nanos dt); /** swap roles of From/To spaces for nursery generation **/ void swap_nursery(); /** swap roles of From/To spaces for tenured generation **/ diff --git a/include/xo/alloc/GcStatistics.hpp b/include/xo/alloc/GcStatistics.hpp index d73f8947..d0f54084 100644 --- a/include/xo/alloc/GcStatistics.hpp +++ b/include/xo/alloc/GcStatistics.hpp @@ -8,6 +8,8 @@ #include "generation.hpp" #include "CircularBuffer.hpp" #include "xo/reflect/TypeDescr.hpp" +#include "xo/unit/quantity.hpp" +#include "xo/unit/quantity_iostream.hpp" #include "xo/indentlog/print/pretty.hpp" #include #include @@ -60,6 +62,13 @@ namespace xo { public: GcStatistics() = default; + /** update statistics at beginning of a GC cycle + * @param upto. nursery -> incremental collection; tenured -> full collection + * @param alloc_z. new allocations (since preceding GC) + **/ + void begin_gc(generation upto, + std::size_t alloc_z); + /** update statistics after a GC cycle * @param upto. nursery -> incremental collection; tenured -> full collection * @param alloc_z. new allocations (since preceding GC) @@ -74,6 +83,9 @@ namespace xo { **/ void update_snapshot(generation upto, std::size_t after_z); + /** number of collection cycles, whether full or incremental **/ + std::size_t n_gc() const { return gen_v_[gen2int(generation::nursery)].n_gc_; } + /** @param os. write stats on this output stream **/ void display(std::ostream & os) const; @@ -136,31 +148,54 @@ namespace xo { * @brief info we want to record over time (won't have cumulative things in it) **/ class GcStatisticsHistoryItem { + public: + using nanos = xo::qty::type::nanoseconds; + public: GcStatisticsHistoryItem() = default; - GcStatisticsHistoryItem(generation upto, - std::size_t new_alloc_z, - std::size_t survive_z, - std::size_t promote_z, - std::size_t persist_z, - std::size_t effort_z, - std::size_t garbage0_z, - std::size_t garbage1_z, - std::size_t garbageN_z) - : upto_{upto}, - new_alloc_z_{new_alloc_z}, - survive_z_{survive_z}, - promote_z_{promote_z}, - persist_z_{persist_z}, - effort_z_{effort_z}, - garbage0_z_{garbage0_z}, - garbage1_z_{garbage1_z}, - garbageN_z_{garbageN_z} - {} + constexpr GcStatisticsHistoryItem(std::size_t gc_seq, + generation upto, + std::size_t new_alloc_z, + std::size_t survive_z, + std::size_t promote_z, + std::size_t persist_z, + std::size_t effort_z, + std::size_t garbage0_z, + std::size_t garbage1_z, + std::size_t garbageN_z, + nanos dt) : gc_seq_{gc_seq}, + upto_{upto}, + new_alloc_z_{new_alloc_z}, + survive_z_{survive_z}, + promote_z_{promote_z}, + persist_z_{persist_z}, + effort_z_{effort_z}, + garbage0_z_{garbage0_z}, + garbage1_z_{garbage1_z}, + garbageN_z_{garbageN_z}, + dt_{dt} {} + constexpr GcStatisticsHistoryItem(const GcStatisticsHistoryItem &) = default; + + GcStatisticsHistoryItem & operator=(const GcStatisticsHistoryItem & x) { + gc_seq_ = x.gc_seq_; + upto_ = x.upto_; + new_alloc_z_ = x.new_alloc_z_; + survive_z_ = x.survive_z_; + promote_z_ = x.promote_z_; + persist_z_ = x.persist_z_; + effort_z_ = x.effort_z_; + garbage0_z_ = x.garbage0_z_; + garbage1_z_ = x.garbage1_z_; + garbageN_z_ = x.garbageN_z_; + this->dt_.scale_ = x.dt_.scale_; + return *this; + } /** @param os. write stats on this output stream **/ void display(std::ostream & os) const; + /** sequence number for collection being reported **/ + std::size_t gc_seq_ = 0; /** type of GC that generated this record **/ generation upto_; /** #of bytes new allocation **/ @@ -181,6 +216,8 @@ namespace xo { std::size_t garbage1_z_ = 0; /** #of bytes garbage from T (i.e. survived 2+ GCs) **/ std::size_t garbageN_z_ = 0; + /** elapsed time for this GC (see @ref GC::execute_gc) **/ + nanos dt_; }; inline std::ostream & operator<< (std::ostream & os, const GcStatisticsHistoryItem & x) { diff --git a/src/alloc/CMakeLists.txt b/src/alloc/CMakeLists.txt index 07f87784..b83e2618 100644 --- a/src/alloc/CMakeLists.txt +++ b/src/alloc/CMakeLists.txt @@ -14,6 +14,7 @@ set(SELF_SRCS ) xo_add_shared_library4(${SELF_LIB} ${PROJECT_NAME}Targets ${PROJECT_VERSION} 1 ${SELF_SRCS}) +xo_dependency(${SELF_LIB} xo_unit) xo_dependency(${SELF_LIB} reflect) xo_dependency(${SELF_LIB} callback) diff --git a/src/alloc/GC.cpp b/src/alloc/GC.cpp index a552ae1e..e6fb188f 100644 --- a/src/alloc/GC.cpp +++ b/src/alloc/GC.cpp @@ -7,6 +7,7 @@ #include "GC.hpp" #include "Object.hpp" #include "xo/indentlog/scope.hpp" +#include #include #include @@ -1037,9 +1038,9 @@ namespace xo { } void - GC::cleanup_phase(generation upto) + GC::cleanup_phase(generation upto, nanos dt) { - scope log(XO_DEBUG(config_.debug_flag_)); + scope log(XO_DEBUG(config_.stats_flag_)); std::size_t N0_before_gc = nursery_from()->after_checkpoint(); std::size_t N1_before_gc = nursery_from()->before_checkpoint(); @@ -1098,6 +1099,7 @@ namespace xo { this->tenured_to()->checkpoint(); if (log) { + log(xtag("gcseq_before_gc", gc_statistics_.n_gc())); log(xtag("N0_before_gc", N0_before_gc)); log(xtag("N1_before_gc", N1_before_gc)); log(xtag("N_after_gc", N_after_gc)); @@ -1107,18 +1109,6 @@ namespace xo { log(xtag("T_after_gc", T_after_gc)); } - GcStatisticsHistoryItem item(upto, - new_alloc_z, - survive_z, - promote_z, - persist_z, - effort_z, - garbage0_z, - garbage1_z, - garbageN_z); - - this->gc_history_.push_back(item); - this->incr_gc_pending_ = false; this->gc_statistics_.include_gc(generation::nursery, N0_before_gc, N_before_gc, N_after_gc, promote_z); @@ -1129,6 +1119,23 @@ namespace xo { // still want to update tenured stats for current alloc size this->gc_statistics_.update_snapshot(generation::tenured, T_after_gc); } + GcStatisticsHistoryItem item(gc_statistics_.n_gc(), + upto, + new_alloc_z, + survive_z, + promote_z, + persist_z, + effort_z, + garbage0_z, + garbage1_z, + garbageN_z, + dt); + + log && log(xtag("gcseq_after_gc", gc_statistics_.n_gc()), + xtag("item", item)); + + this->gc_history_.push_back(item); + } /*cleanup_phase*/ void @@ -1136,6 +1143,8 @@ namespace xo { { scope log(XO_DEBUG(config_.stats_flag_)); + auto t0 = std::chrono::steady_clock::now(); + bool full_move = (upto == generation::tenured); // TODO: RAII version in case of exceptions @@ -1146,9 +1155,7 @@ namespace xo { /* new allocation since last GC */ std::size_t new_alloc = this->after_checkpoint(); - ++(gc_statistics_.gen_v_[static_cast(upto)].n_gc_); - gc_statistics_.total_allocated_ += new_alloc; - gc_statistics_.total_promoted_sab_ = gc_statistics_.total_promoted_; + gc_statistics_.begin_gc(upto, new_alloc); log && log(xtag("new_alloc", new_alloc)); @@ -1176,10 +1183,13 @@ namespace xo { log && log("step 6 : cleanup"); - this->cleanup_phase(upto); - this->capture_object_statistics(upto, capture_phase::sae); + auto t1 = std::chrono::steady_clock::now(); + auto dt = std::chrono::duration_cast(t1 - t0); + + this->cleanup_phase(upto, xo::qty::qty::nanoseconds(dt.count())); + log && log("object statistics [nursery]:"); log && log(refrtag("stats", object_statistics_sab_[gen2int(generation::nursery)])); log && log("object statistics [tenured]:"); @@ -1233,6 +1243,13 @@ namespace xo { this->request_gc(full_gc_pending_ ? generation::tenured : generation::nursery); } } + + void + GC::enable_gc_once() { + this->enable_gc(); + this->disable_gc(); + } + } /*namespace gc*/ } /*namespace xo*/ diff --git a/src/alloc/GcStatistics.cpp b/src/alloc/GcStatistics.cpp index cb7ebebf..72624403 100644 --- a/src/alloc/GcStatistics.cpp +++ b/src/alloc/GcStatistics.cpp @@ -16,6 +16,7 @@ namespace xo { { this->update_snapshot(after_z); + //++n_gc_; new_alloc_z_ += alloc_z; scanned_z_ += before_z; survive_z_ += after_z; @@ -41,6 +42,15 @@ namespace xo { << ">"; } + void + GcStatistics::begin_gc(generation upto, + std::size_t new_alloc) + { + ++(this->gen_v_[static_cast(upto)].n_gc_); + this->total_allocated_ += new_alloc; + this->total_promoted_sab_ = total_promoted_; + } + void GcStatistics::include_gc(generation upto, std::size_t alloc_z, @@ -105,6 +115,7 @@ namespace xo { << xrtag("garbage0_z", garbage0_z_) << xrtag("garbage1_z", garbage1_z_) << xrtag("garbageN_z", garbageN_z_) + << xrtag("dt", dt_) << ">"; } @@ -177,7 +188,8 @@ namespace xo { refrtag("effort_z", x.effort_z_), refrtag("garbage0_z", x.garbage0_z_), refrtag("garbage1_z", x.garbage1_z_), - refrtag("garbageN_z", x.garbageN_z_)); + refrtag("garbageN_z", x.garbageN_z_), + refrtag("dt", x.dt_)); } } /*namespace print*/ } /*namespace xo*/