diff options
author | Philip Chimento <philip.chimento@gmail.com> | 2023-03-04 23:26:04 -0800 |
---|---|---|
committer | Philip Chimento <philip.chimento@gmail.com> | 2023-03-04 23:44:19 -0800 |
commit | 38161234b69941ee6dc3e3006300dea0d5ee3e45 (patch) | |
tree | 57c20be59f304b6ee7357eb83644f4cdb723ca9c | |
parent | 9f119427e50557ba000c68c246303edbe3a3507e (diff) | |
download | gjs-38161234b69941ee6dc3e3006300dea0d5ee3e45.tar.gz |
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.
-rw-r--r-- | gjs/context.cpp | 18 | ||||
-rw-r--r-- | gjs/mainloop.cpp | 3 | ||||
-rw-r--r-- | gjs/mainloop.h | 8 | ||||
-rw-r--r-- | gjs/promise.cpp | 14 | ||||
-rw-r--r-- | util/log.cpp | 2 | ||||
-rw-r--r-- | util/log.h | 1 |
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: @@ -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, |