xo-alloc: + timing stats + timeseries tooltips

include/xo/alloc/GC.hpp

@@ -132,6 +132,7 @@ namespace xo {
         public:
             using CallbackId = xo::fn::CallbackId;
             using GcCopyCallbackSet = xo::fn::UpCallbackSet<GcCopyCallback>;
+            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 **/

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 <ostream>
 #include <array>
@@ -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<std::int64_t>;
+
         public:
             GcStatisticsHistoryItem() = default;
-            GcStatisticsHistoryItem(generation upto,
+            constexpr GcStatisticsHistoryItem(std::size_t gc_seq,
-                                    std::size_t new_alloc_z,
+                                              generation upto,
-                                    std::size_t survive_z,
+                                              std::size_t new_alloc_z,
-                                    std::size_t promote_z,
+                                              std::size_t survive_z,
-                                    std::size_t persist_z,
+                                              std::size_t promote_z,
-                                    std::size_t effort_z,
+                                              std::size_t persist_z,
-                                    std::size_t garbage0_z,
+                                              std::size_t effort_z,
-                                    std::size_t garbage1_z,
+                                              std::size_t garbage0_z,
-                                    std::size_t garbageN_z)
+                                              std::size_t garbage1_z,
-                : upto_{upto},
+                                              std::size_t garbageN_z,
-                  new_alloc_z_{new_alloc_z},
+                                              nanos dt) : gc_seq_{gc_seq},
-                  survive_z_{survive_z},
+                                                          upto_{upto},
-                  promote_z_{promote_z},
+                                                          new_alloc_z_{new_alloc_z},
-                  persist_z_{persist_z},
+                                                          survive_z_{survive_z},
-                  effort_z_{effort_z},
+                                                          promote_z_{promote_z},
-                  garbage0_z_{garbage0_z},
+                                                          persist_z_{persist_z},
-                  garbage1_z_{garbage1_z},
+                                                          effort_z_{effort_z},
-                  garbageN_z_{garbageN_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) {

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)
 

src/alloc/GC.cpp

@@ -7,6 +7,7 @@
 #include "GC.hpp"
 #include "Object.hpp"
 #include "xo/indentlog/scope.hpp"
+#include <chrono>
 #include <cassert>
 #include <cstddef>
 
@@ -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<std::size_t>(upto)].n_gc_);
+            gc_statistics_.begin_gc(upto, new_alloc);
-            gc_statistics_.total_allocated_ += new_alloc;
-            gc_statistics_.total_promoted_sab_ = gc_statistics_.total_promoted_;
 
             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<std::chrono::nanoseconds>(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*/
 

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<std::size_t>(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*/