mainloop: Instrument main loop and promise job dispatcher with debug logs

This adds a new debug topic, JS MAINLOOP, and adds debug log statements to
the promise job queue, GSource, dispatcher, and main loop machinery.

6 files changed, 36 insertions, 10 deletions

diff --git a/gjs/context.cpp b/gjs/context.cpp
index c4abbbf9..8d2cbc6e 100644
--- a/gjs/context.cpp
+++ b/gjs/context.cpp
@@ -1006,15 +1006,10 @@ bool GjsContextPrivate::should_exit(uint8_t* exit_code_p) const {
     return m_should_exit;
 }
 
-void GjsContextPrivate::start_draining_job_queue(void) {
-    gjs_debug(GJS_DEBUG_CONTEXT, "Starting promise job dispatcher");
-    m_dispatcher.start();
-}
+void GjsContextPrivate::start_draining_job_queue(void) { m_dispatcher.start(); }
 
 void GjsContextPrivate::stop_draining_job_queue(void) {
     m_draining_job_queue = false;
-
-    gjs_debug(GJS_DEBUG_CONTEXT, "Stopping promise job dispatcher");
     m_dispatcher.stop();
 }
 
@@ -1033,7 +1028,7 @@ bool GjsContextPrivate::enqueuePromiseJob(JSContext* cx [[maybe_unused]],
     g_assert(cx == m_cx);
     g_assert(from_cx(cx) == this);
 
-    gjs_debug(GJS_DEBUG_CONTEXT,
+    gjs_debug(GJS_DEBUG_MAINLOOP,
               "Enqueue job %s, promise=%s, allocation site=%s",
               gjs_debug_object(job).c_str(), gjs_debug_object(promise).c_str(),
               gjs_debug_object(allocation_site).c_str());
@@ -1088,8 +1083,11 @@ bool GjsContextPrivate::run_jobs_fallible(GCancellable* cancellable) {
      * it's crucial to recheck the queue length during each iteration. */
     for (size_t ix = 0; ix < m_job_queue.length(); ix++) {
         /* A previous job might have set this flag. e.g., System.exit(). */
-        if (m_should_exit || g_cancellable_is_cancelled(cancellable))
+        if (m_should_exit || g_cancellable_is_cancelled(cancellable)) {
+            gjs_debug(GJS_DEBUG_MAINLOOP, "Stopping jobs because of %s",
+                      m_should_exit ? "exit" : "main loop cancel");
             break;
+        }
 
         job = m_job_queue[ix];
 
@@ -1103,7 +1101,7 @@ bool GjsContextPrivate::run_jobs_fallible(GCancellable* cancellable) {
         m_job_queue[ix] = nullptr;
         {
             JSAutoRealm ar(m_cx, job);
-            gjs_debug(GJS_DEBUG_CONTEXT, "handling job %s",
+            gjs_debug(GJS_DEBUG_MAINLOOP, "handling job %zu, %s", ix,
                       gjs_debug_object(job).c_str());
             if (!JS::Call(m_cx, JS::UndefinedHandleValue, job, args, &rval)) {
                 /* Uncatchable exception - return false so that
@@ -1122,6 +1120,7 @@ bool GjsContextPrivate::run_jobs_fallible(GCancellable* cancellable) {
                 gjs_log_exception_uncaught(m_cx);
             }
         }
+        gjs_debug(GJS_DEBUG_MAINLOOP, "Completed job %zu", ix);
     }
 
     m_draining_job_queue = false;
@@ -1398,6 +1397,7 @@ bool GjsContextPrivate::set_main_loop_hook(JSObject* callable) {
 bool GjsContextPrivate::run_main_loop_hook() {
     JS::RootedObject hook(m_cx, m_main_loop_hook.get());
     m_main_loop_hook = nullptr;
+    gjs_debug(GJS_DEBUG_MAINLOOP, "Running and clearing main loop hook");
     JS::RootedValue ignored_rval(m_cx);
     return JS::Call(m_cx, JS::NullHandleValue, hook,
                     JS::HandleValueArray::empty(), &ignored_rval);
diff --git a/gjs/mainloop.cpp b/gjs/mainloop.cpp
index b69d45a8..3ad3f5c7 100644
--- a/gjs/mainloop.cpp
+++ b/gjs/mainloop.cpp
@@ -20,6 +20,7 @@ bool MainLoop::spin(GjsContextPrivate* gjs) {
     if (gjs->should_exit(nullptr)) {
         // Return false to indicate the loop is exiting due to an exit call,
         // the queue is likely not empty
+        debug("Not spinning loop because System.exit called");
         exit();
         return false;
     }
@@ -27,6 +28,7 @@ bool MainLoop::spin(GjsContextPrivate* gjs) {
     GjsAutoPointer<GMainContext, GMainContext, g_main_context_unref>
         main_context(g_main_context_ref_thread_default());
 
+    debug("Spinning loop until released or hook cleared");
     do {
         bool blocking = can_block();
 
@@ -36,6 +38,7 @@ bool MainLoop::spin(GjsContextPrivate* gjs) {
 
         // If System.exit() has not been called
         if (gjs->should_exit(nullptr)) {
+            debug("Stopped spinning loop because System.exit called");
             exit();
             return false;
         }
diff --git a/gjs/mainloop.h b/gjs/mainloop.h
index f374060c..a228d761 100644
--- a/gjs/mainloop.h
+++ b/gjs/mainloop.h
@@ -8,6 +8,8 @@
 
 #include <glib.h>
 
+#include "util/log.h"
+
 class GjsContextPrivate;
 
 namespace Gjs {
@@ -20,6 +22,10 @@ class MainLoop {
     grefcount m_hold_count;
     bool m_exiting;
 
+    void debug(const char* msg) {
+        gjs_debug(GJS_DEBUG_MAINLOOP, "Main loop instance %p: %s", this, msg);
+    }
+
     [[nodiscard]] bool can_block() {
         // Don't block if exiting
         if (m_exiting)
@@ -51,6 +57,7 @@ class MainLoop {
         if (m_exiting)
             return;
 
+        debug("hold");
         g_ref_count_inc(&m_hold_count);
     }
 
@@ -59,6 +66,7 @@ class MainLoop {
         if (m_exiting)
             return;
 
+        debug("release");
         bool zero [[maybe_unused]] = g_ref_count_dec(&m_hold_count);
         g_assert(!zero && "main loop released too many times");
     }
diff --git a/gjs/promise.cpp b/gjs/promise.cpp
index 39939aa9..0507eaf3 100644
--- a/gjs/promise.cpp
+++ b/gjs/promise.cpp
@@ -6,6 +6,8 @@
 
 #include <stddef.h>  // for size_t
 
+#include <string>
+
 #include <gio/gio.h>
 #include <glib-object.h>
 
@@ -22,6 +24,7 @@
 #include "gjs/jsapi-util.h"
 #include "gjs/macros.h"
 #include "gjs/promise.h"
+#include "util/log.h"
 
 /**
  * promise.cpp - This file implements a custom GSource, PromiseJobQueueSource,
@@ -135,6 +138,8 @@ class PromiseJobDispatcher::Source : public GSource {
         if (!g_cancellable_is_cancelled(m_cancellable))
             return;
 
+        gjs_debug(GJS_DEBUG_MAINLOOP, "Uncancelling promise job dispatcher");
+
         if (is_running())
             g_source_remove_child_source(this, m_cancellable_source);
         else
@@ -179,10 +184,14 @@ void PromiseJobDispatcher::start() {
     if (is_running())
         return;
 
+    gjs_debug(GJS_DEBUG_MAINLOOP, "Starting promise job dispatcher");
     g_source_attach(m_source.get(), m_main_context);
 }
 
-void PromiseJobDispatcher::stop() { m_source->cancel(); }
+void PromiseJobDispatcher::stop() {
+    gjs_debug(GJS_DEBUG_MAINLOOP, "Stopping promise job dispatcher");
+    m_source->cancel();
+}
 
 };  // namespace Gjs
 
@@ -212,6 +221,9 @@ bool set_main_loop_hook(JSContext* cx, unsigned argc, JS::Value* vp) {
         return false;
     }
 
+    gjs_debug(GJS_DEBUG_MAINLOOP, "Set main loop hook to %s",
+              gjs_debug_object(callback).c_str());
+
     GjsContextPrivate* priv = GjsContextPrivate::from_cx(cx);
     if (!priv->set_main_loop_hook(callback)) {
         gjs_throw(
diff --git a/util/log.cpp b/util/log.cpp
index ce4b02dd..4a910342 100644
--- a/util/log.cpp
+++ b/util/log.cpp
@@ -53,6 +53,8 @@ static const char* topic_to_prefix(GjsDebugTopic topic) {
             return "JS CAIRO";
         case GJS_DEBUG_KEEP_ALIVE:
             return "JS KP ALV";
+        case GJS_DEBUG_MAINLOOP:
+            return "JS MAINLOOP";
         case GJS_DEBUG_GREPO:
             return "JS G REPO";
         case GJS_DEBUG_GNAMESPACE:
diff --git a/util/log.h b/util/log.h
index 92880e73..93ce94f5 100644
--- a/util/log.h
+++ b/util/log.h
@@ -18,6 +18,7 @@ typedef enum {
     GJS_DEBUG_NATIVE,
     GJS_DEBUG_CAIRO,
     GJS_DEBUG_KEEP_ALIVE,
+    GJS_DEBUG_MAINLOOP,
     GJS_DEBUG_GREPO,
     GJS_DEBUG_GNAMESPACE,
     GJS_DEBUG_GOBJECT,