[gjs: 3/7] context: Improve profiling data for garbage collections

[Philip Chimento <pchimento src gnome org>]

commit 7558b36fbaba73c1055b5cb81b6f8b0dceb51eac
Author: Philip Chimento <philip chimento gmail com>
Date:   Sat Mar 13 15:05:39 2021 -0800

    context: Improve profiling data for garbage collections
    
    This sends all the timing information to the profiler, that we get from
    the JS engine's GC and finalization status callbacks. Instead of just the
    sweeping timings, we keep track of the duration of the whole GC as well as
    the sweeping of zone groups, and we report the reason for the GC that the
    engine gives. For cases where GJS triggers the GC, we add a few more
    GC reason constants with explanations that will show up in Sysprof.

 gjs/context-private.h |  11 ++++-
 gjs/context.cpp       | 124 ++++++++++++++++++++++++++++++++++++++------------
 gjs/engine.cpp        |  46 +------------------
 gjs/jsapi-util.cpp    |  23 +++++++++-
 gjs/jsapi-util.h      |  31 +++++++++++++
 5 files changed, 159 insertions(+), 76 deletions(-)
---
diff --git a/gjs/context-private.h b/gjs/context-private.h
index 8e4ee20b..4884f4a4 100644
--- a/gjs/context-private.h
+++ b/gjs/context-private.h
@@ -19,6 +19,7 @@
 #include <glib-object.h>
 #include <glib.h>
 
+#include <js/GCAPI.h>
 #include <js/GCHashTable.h>
 #include <js/GCVector.h>
 #include <js/HashTable.h>  // for DefaultHasher
@@ -111,11 +112,16 @@ class GjsContextPrivate : public JS::JobQueue {
     bool m_exec_as_module : 1;
     bool m_should_listen_sigusr2 : 1;
 
+    // If profiling is enabled, we record the durations and reason for GC mark
+    // and sweep
+    int64_t m_gc_begin_time;
     int64_t m_sweep_begin_time;
+    int64_t m_group_sweep_begin_time;
+    const char* m_gc_reason;  // statically allocated
 
     void schedule_gc_internal(bool force_gc);
     static gboolean trigger_gc_if_needed(void* data);
-    void on_garbage_collection(JSGCStatus);
+    void on_garbage_collection(JSGCStatus, JS::GCReason);
 
     class SavedQueue;
     void start_draining_job_queue(void);
@@ -235,7 +241,8 @@ class GjsContextPrivate : public JS::JobQueue {
     [[nodiscard]] bool register_module(const char* identifier,
                                        const char* filename, GError** error);
 
-    void set_sweeping(bool value);
+    void set_gc_status(JSGCStatus status, JS::GCReason reason);
+    void set_finalize_status(JSFinalizeStatus status);
 
     static void trace(JSTracer* trc, void* data);
 
diff --git a/gjs/context.cpp b/gjs/context.cpp
index f9f01539..894e39df 100644
--- a/gjs/context.cpp
+++ b/gjs/context.cpp
@@ -405,7 +405,7 @@ void GjsContextPrivate::dispose(void) {
          * context
          */
         gjs_debug(GJS_DEBUG_CONTEXT, "Final triggered GC");
-        JS_GC(m_cx);
+        JS_GC(m_cx, Gjs::GCReason::GJS_CONTEXT_DISPOSE);
 
         gjs_debug(GJS_DEBUG_CONTEXT, "Destroying JS context");
         m_destroying.store(true);
@@ -497,9 +497,9 @@ GjsContextPrivate::GjsContextPrivate(JSContext* cx, GjsContext* public_context)
 
     JS_SetGCCallback(
         cx,
-        [](JSContext*, JSGCStatus status, JS::GCReason, void* data) {
+        [](JSContext*, JSGCStatus status, JS::GCReason reason, void* data) {
             static_cast<GjsContextPrivate*>(data)->on_garbage_collection(
-                status);
+                status, reason);
         },
         this);
 
@@ -709,7 +709,7 @@ gboolean GjsContextPrivate::trigger_gc_if_needed(void* data) {
 
     if (gjs->m_force_gc) {
         gjs_debug_lifecycle(GJS_DEBUG_CONTEXT, "Big Hammer hit");
-        JS_GC(gjs->m_cx);
+        JS_GC(gjs->m_cx, Gjs::GCReason::BIG_HAMMER);
     } else {
         gjs_gc_if_needed(gjs->m_cx);
     }
@@ -746,38 +746,106 @@ void GjsContextPrivate::schedule_gc_if_needed(void) {
     schedule_gc_internal(false);
 }
 
-void GjsContextPrivate::on_garbage_collection(JSGCStatus status) {
-    // We finalize any pending toggle refs before doing any garbage collection,
-    // so that we can collect the JS wrapper objects, and in order to minimize
-    // the chances of objects having a pending toggle up queued when they are
-    // garbage collected. */
-    if (status == JSGC_BEGIN) {
-        gjs_debug_lifecycle(GJS_DEBUG_CONTEXT, "Begin garbage collection");
-        gjs_object_clear_toggles();
-        gjs_function_clear_async_closures();
-    } else if (status == JSGC_END) {
-        gjs_debug_lifecycle(GJS_DEBUG_CONTEXT, "End garbage collection");
+void GjsContextPrivate::on_garbage_collection(JSGCStatus status, JS::GCReason reason) {
+    int64_t now = 0;
+    if (m_profiler)
+        now = g_get_monotonic_time() * 1000L;
+
+    switch (status) {
+        case JSGC_BEGIN:
+            m_gc_begin_time = now;
+            m_gc_reason = gjs_explain_gc_reason(reason);
+            gjs_debug_lifecycle(GJS_DEBUG_CONTEXT,
+                                "Begin garbage collection because of %s",
+                                m_gc_reason);
+
+            // We finalize any pending toggle refs before doing any garbage
+            // collection, so that we can collect the JS wrapper objects, and in
+            // order to minimize the chances of objects having a pending toggle
+            // up queued when they are garbage collected.
+            gjs_object_clear_toggles();
+            gjs_function_clear_async_closures();
+            break;
+        case JSGC_END:
+            if (m_profiler && m_gc_begin_time != 0) {
+                _gjs_profiler_add_mark(m_profiler, m_gc_begin_time,
+                                       now - m_gc_begin_time, "GJS",
+                                       "Garbage collection", m_gc_reason);
+            }
+            m_gc_begin_time = 0;
+            m_gc_reason = nullptr;
+            gjs_debug_lifecycle(GJS_DEBUG_CONTEXT, "End garbage collection");
+            break;
+        default:
+            g_assert_not_reached();
     }
 }
 
-void GjsContextPrivate::set_sweeping(bool value) {
-    // If we have a profiler enabled, record the duration of GC sweep
-    if (this->m_profiler != nullptr) {
-        int64_t now = g_get_monotonic_time() * 1000L;
+void GjsContextPrivate::set_finalize_status(JSFinalizeStatus status) {
+    // Implementation note for mozjs-24:
+    //
+    // Sweeping happens in two phases, in the first phase all GC things from the
+    // allocation arenas are queued for sweeping, then the actual sweeping
+    // happens. The first phase is marked by JSFINALIZE_GROUP_START, the second
+    // one by JSFINALIZE_GROUP_END, and finally we will see
+    // JSFINALIZE_COLLECTION_END at the end of all GC. (see jsgc.cpp,
+    // BeginSweepPhase/BeginSweepingZoneGroup and SweepPhase, all called from
+    // IncrementalCollectSlice).
+    //
+    // Incremental GC muddies the waters, because BeginSweepPhase is always run
+    // to entirety, but SweepPhase can be run incrementally and mixed with JS
+    // code runs or even native code, when MaybeGC/IncrementalGC return.
+    //
+    // Luckily for us, objects are treated specially, and are not really queued
+    // for deferred incremental finalization (unless they are marked for
+    // background sweeping). Instead, they are finalized immediately during
+    // phase 1, so the following guarantees are true (and we rely on them):
+    // - phase 1 of GC will begin and end in the same JSAPI call (i.e., our
+    //   callback will be called with GROUP_START and the triggering JSAPI call
+    //   will not return until we see a GROUP_END)
+    // - object finalization will begin and end in the same JSAPI call
+    // - therefore, if there is a finalizer frame somewhere in the stack,
+    //   GjsContextPrivate::sweeping() will return true.
+    //
+    // Comments in mozjs-24 imply that this behavior might change in the future,
+    // but it hasn't changed in mozilla-central as of 2014-02-23. In addition to
+    // that, the mozilla-central version has a huge comment in a different
+    // portion of the file, explaining why finalization of objects can't be
+    // mixed with JS code, so we can probably rely on this behavior.
+
+    int64_t now = 0;
 
-        if (value) {
+    if (m_profiler)
+        now = g_get_monotonic_time() * 1000L;
+
+    switch (status) {
+        case JSFINALIZE_GROUP_PREPARE:
+            m_in_gc_sweep = true;
             m_sweep_begin_time = now;
-        } else {
-            if (m_sweep_begin_time != 0) {
-                _gjs_profiler_add_mark(this->m_profiler, m_sweep_begin_time,
+            break;
+        case JSFINALIZE_GROUP_START:
+            m_group_sweep_begin_time = now;
+            break;
+        case JSFINALIZE_GROUP_END:
+            if (m_profiler && m_group_sweep_begin_time != 0) {
+                _gjs_profiler_add_mark(m_profiler, m_group_sweep_begin_time,
+                                       now - m_group_sweep_begin_time, "GJS",
+                                       "Group sweep", nullptr);
+            }
+            m_group_sweep_begin_time = 0;
+            break;
+        case JSFINALIZE_COLLECTION_END:
+            m_in_gc_sweep = false;
+            if (m_profiler && m_sweep_begin_time != 0) {
+                _gjs_profiler_add_mark(m_profiler, m_sweep_begin_time,
                                        now - m_sweep_begin_time, "GJS", "Sweep",
                                        nullptr);
-                m_sweep_begin_time = 0;
             }
-        }
+            m_sweep_begin_time = 0;
+            break;
+        default:
+            g_assert_not_reached();
     }
-
-    m_in_gc_sweep = value;
 }
 
 void GjsContextPrivate::exit(uint8_t exit_code) {
@@ -1028,7 +1096,7 @@ void
 gjs_context_gc (GjsContext  *context)
 {
     GjsContextPrivate* gjs = GjsContextPrivate::from_object(context);
-    JS_GC(gjs->context());
+    JS_GC(gjs->context(), Gjs::GCReason::GJS_API_CALL);
 }
 
 /**
diff --git a/gjs/engine.cpp b/gjs/engine.cpp
index 04e67415..ec8ca26a 100644
--- a/gjs/engine.cpp
+++ b/gjs/engine.cpp
@@ -35,51 +35,7 @@
 static void gjs_finalize_callback(JSFreeOp*, JSFinalizeStatus status,
                                   void* data) {
     auto* gjs = static_cast<GjsContextPrivate*>(data);
-
-  /* Implementation note for mozjs 24:
-     sweeping happens in two phases, in the first phase all
-     GC things from the allocation arenas are queued for
-     sweeping, then the actual sweeping happens.
-     The first phase is marked by JSFINALIZE_GROUP_START,
-     the second one by JSFINALIZE_GROUP_END, and finally
-     we will see JSFINALIZE_COLLECTION_END at the end of
-     all GC.
-     (see jsgc.cpp, BeginSweepPhase/BeginSweepingZoneGroup
-     and SweepPhase, all called from IncrementalCollectSlice).
-     Incremental GC muds the waters, because BeginSweepPhase
-     is always run to entirety, but SweepPhase can be run
-     incrementally and mixed with JS code runs or even
-     native code, when MaybeGC/IncrementalGC return.
-
-     Luckily for us, objects are treated specially, and
-     are not really queued for deferred incremental
-     finalization (unless they are marked for background
-     sweeping). Instead, they are finalized immediately
-     during phase 1, so the following guarantees are
-     true (and we rely on them)
-     - phase 1 of GC will begin and end in the same JSAPI
-       call (ie, our callback will be called with GROUP_START
-       and the triggering JSAPI call will not return until
-       we see a GROUP_END)
-     - object finalization will begin and end in the same
-       JSAPI call
-     - therefore, if there is a finalizer frame somewhere
-       in the stack, gjs_runtime_is_sweeping() will return
-       true.
-
-     Comments in mozjs24 imply that this behavior might
-     change in the future, but it hasn't changed in
-     mozilla-central as of 2014-02-23. In addition to
-     that, the mozilla-central version has a huge comment
-     in a different portion of the file, explaining
-     why finalization of objects can't be mixed with JS
-     code, so we can probably rely on this behavior.
-  */
-
-  if (status == JSFINALIZE_GROUP_PREPARE)
-        gjs->set_sweeping(true);
-  else if (status == JSFINALIZE_GROUP_END)
-        gjs->set_sweeping(false);
+    gjs->set_finalize_status(status);
 }
 
 static void on_promise_unhandled_rejection(
diff --git a/gjs/jsapi-util.cpp b/gjs/jsapi-util.cpp
index 6262ac2d..4024d086 100644
--- a/gjs/jsapi-util.cpp
+++ b/gjs/jsapi-util.cpp
@@ -575,7 +575,8 @@ gjs_gc_if_needed (JSContext *context)
         uint64_t rss_usize = rss_size;
         if (rss_usize > linux_rss_trigger) {
             linux_rss_trigger = MIN(G_MAXUINT32, rss_usize * 1.25);
-            JS::NonIncrementalGC(context, GC_SHRINK, JS::GCReason::API);
+            JS::NonIncrementalGC(context, GC_SHRINK,
+                                 Gjs::GCReason::LINUX_RSS_TRIGGER);
         } else if (rss_size < (0.75 * linux_rss_trigger)) {
             /* If we've shrunk by 75%, lower the trigger */
             linux_rss_trigger = rss_usize * 1.25;
@@ -674,3 +675,23 @@ std::u16string gjs_utf8_script_to_utf16(const char* script, ssize_t len) {
     return convert.from_bytes(script, script + len);
 #endif
 }
+
+const char* gjs_explain_gc_reason(JS::GCReason reason) {
+    if (JS::InternalGCReason(reason))
+        return JS::ExplainGCReason(reason);
+
+    static const char* reason_strings[] = {
+        "RSS above threshold",
+        "GjsContext disposed",
+        "Big Hammer hit",
+        "gjs_context_gc() called",
+    };
+    static_assert(G_N_ELEMENTS(reason_strings) == Gjs::GCReason::N_REASONS,
+                  "Explanations must match the values in Gjs::GCReason");
+
+    g_assert(size_t(reason) < size_t(JS::GCReason::FIRST_FIREFOX_REASON) +
+                                  Gjs::GCReason::N_REASONS &&
+             "Bad Gjs::GCReason");
+    return reason_strings[size_t(reason) -
+                          size_t(JS::GCReason::FIRST_FIREFOX_REASON)];
+}
diff --git a/gjs/jsapi-util.h b/gjs/jsapi-util.h
index 5c21b750..e1f41e5a 100644
--- a/gjs/jsapi-util.h
+++ b/gjs/jsapi-util.h
@@ -21,6 +21,7 @@
 #include <glib-object.h>
 #include <glib.h>
 
+#include <js/GCAPI.h>
 #include <js/GCPolicyAPI.h>  // for IgnoreGCPolicy
 #include <js/Id.h>
 #include <js/TypeDecls.h>
@@ -567,4 +568,34 @@ bool gjs_object_require_converted_property(JSContext       *context,
 [[nodiscard]] std::wstring gjs_win32_vc140_utf8_to_utf16(const char* str);
 #endif
 
+// Custom GC reasons; SpiderMonkey includes a bunch of "Firefox reasons" which
+// don't apply when embedding the JS engine, so we repurpose them for our own
+// reasons.
+
+// clang-format off
+#define FOREACH_GC_REASON(macro)  \
+    macro(LINUX_RSS_TRIGGER, 0)   \
+    macro(GJS_CONTEXT_DISPOSE, 1) \
+    macro(BIG_HAMMER, 2)          \
+    macro(GJS_API_CALL, 3)
+// clang-format on
+
+namespace Gjs {
+
+struct GCReason {
+#define DEFINE_GC_REASON(name, ix)                     \
+    static constexpr JS::GCReason name = JS::GCReason( \
+        static_cast<int>(JS::GCReason::FIRST_FIREFOX_REASON) + ix);
+FOREACH_GC_REASON(DEFINE_GC_REASON);
+#undef DEFINE_GC_REASON
+
+#define COUNT_GC_REASON(name, ix) +1
+static constexpr size_t N_REASONS = 0 FOREACH_GC_REASON(COUNT_GC_REASON);
+#undef COUNT_GC_REASON
+};
+
+}  // namespace Gjs
+
+[[nodiscard]] const char* gjs_explain_gc_reason(JS::GCReason reason);
+
 #endif  // GJS_JSAPI_UTIL_H_