[glib: 2/6] gmain: Add sysprof tracing to GMainContext and GSource

[Philip Withnall <pwithnall src gnome org>]

commit bfe161742cc2b25ff9c22d69509b7b3580f6e4c4
Author: Philip Withnall <withnall endlessm com>
Date:   Thu Jun 25 22:23:17 2020 +0100

    gmain: Add sysprof tracing to GMainContext and GSource
    
    This allows you to see how long each `GMainContext` iteration and each
    `GSource` `check`/`prepare`/`dispatch` takes. It provides more detail
    than sysprof’s speedtrack plugin can provide, since it has access to
    more internal GLib data.
    
    Use it with `sysprof-cli`, for example:
    ```
    sysprof-cli --use-trace-fd -- my-test-program
    ```
    
    Signed-off-by: Philip Withnall <withnall endlessm com>

 glib/gmain.c | 43 +++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 43 insertions(+)
---
diff --git a/glib/gmain.c b/glib/gmain.c
index c18d29079..34ed594ca 100644
--- a/glib/gmain.c
+++ b/glib/gmain.c
@@ -88,6 +88,7 @@
 #include "gstrfuncs.h"
 #include "gtestutils.h"
 #include "gthreadprivate.h"
+#include "gtrace-private.h"
 
 #ifdef G_OS_WIN32
 #include "gwin32.h"
@@ -1248,6 +1249,12 @@ g_source_attach_unlocked (GSource      *source,
   if (do_wakeup && context->owner && context->owner != G_THREAD_SELF)
     g_wakeup_signal (context->wakeup);
 
+  g_trace_mark (G_TRACE_CURRENT_TIME, 0,
+                "GLib", "g_source_attach",
+                "%s to context %p",
+                (g_source_get_name (source) != NULL) ? g_source_get_name (source) : "(unnamed)",
+                context);
+
   return source->source_id;
 }
 
@@ -3291,6 +3298,7 @@ g_main_dispatch (GMainContext *context)
                                GSourceFunc,
                                gpointer);
           GSource *prev_source;
+          gint64 begin_time_nsec G_GNUC_UNUSED;
 
          dispatch = source->source_funcs->dispatch;
          cb_funcs = source->callback_funcs;
@@ -3317,12 +3325,20 @@ g_main_dispatch (GMainContext *context)
           current->source = source;
           current->depth++;
 
+          begin_time_nsec = G_TRACE_CURRENT_TIME;
+
           TRACE (GLIB_MAIN_BEFORE_DISPATCH (g_source_get_name (source), source,
                                             dispatch, callback, user_data));
           need_destroy = !(* dispatch) (source, callback, user_data);
           TRACE (GLIB_MAIN_AFTER_DISPATCH (g_source_get_name (source), source,
                                            dispatch, need_destroy));
 
+          g_trace_mark (begin_time_nsec, G_TRACE_CURRENT_TIME - begin_time_nsec,
+                        "GLib", "GSource.dispatch",
+                        "%s ⇒ %s",
+                        (g_source_get_name (source) != NULL) ? g_source_get_name (source) : "(unnamed)",
+                        need_destroy ? "destroy" : "keep");
+
           current->source = prev_source;
           current->depth--;
 
@@ -3626,12 +3642,22 @@ g_main_context_prepare (GMainContext *context,
 
           if (prepare)
             {
+              gint64 begin_time_nsec G_GNUC_UNUSED;
+
               context->in_check_or_prepare++;
               UNLOCK_CONTEXT (context);
 
+              begin_time_nsec = G_TRACE_CURRENT_TIME;
+
               result = (* prepare) (source, &source_timeout);
               TRACE (GLIB_MAIN_AFTER_PREPARE (source, prepare, source_timeout));
 
+              g_trace_mark (begin_time_nsec, G_TRACE_CURRENT_TIME - begin_time_nsec,
+                            "GLib", "GSource.prepare",
+                            "%s ⇒ %s",
+                            (g_source_get_name (source) != NULL) ? g_source_get_name (source) : "(unnamed)",
+                            result ? "ready" : "unready");
+
               LOCK_CONTEXT (context);
               context->in_check_or_prepare--;
             }
@@ -3886,14 +3912,24 @@ g_main_context_check (GMainContext *context,
 
           if (check)
             {
+              gint64 begin_time_nsec G_GNUC_UNUSED;
+
               /* If the check function is set, call it. */
               context->in_check_or_prepare++;
               UNLOCK_CONTEXT (context);
 
+              begin_time_nsec = G_TRACE_CURRENT_TIME;
+
               result = (* check) (source);
 
               TRACE (GLIB_MAIN_AFTER_CHECK (source, check, result));
 
+              g_trace_mark (begin_time_nsec, G_TRACE_CURRENT_TIME - begin_time_nsec,
+                            "GLib", "GSource.check",
+                            "%s ⇒ %s",
+                            (g_source_get_name (source) != NULL) ? g_source_get_name (source) : "(unnamed)",
+                            result ? "dispatch" : "ignore");
+
               LOCK_CONTEXT (context);
               context->in_check_or_prepare--;
             }
@@ -4004,9 +4040,12 @@ g_main_context_iterate (GMainContext *context,
   gboolean some_ready;
   gint nfds, allocated_nfds;
   GPollFD *fds = NULL;
+  gint64 begin_time_nsec G_GNUC_UNUSED;
 
   UNLOCK_CONTEXT (context);
 
+  begin_time_nsec = G_TRACE_CURRENT_TIME;
+
   if (!g_main_context_acquire (context))
     {
       gboolean got_ownership;
@@ -4061,6 +4100,10 @@ g_main_context_iterate (GMainContext *context,
   
   g_main_context_release (context);
 
+  g_trace_mark (begin_time_nsec, G_TRACE_CURRENT_TIME - begin_time_nsec,
+                "GLib", "g_main_context_iterate",
+                "Context %p, %s ⇒ %s", context, block ? "blocking" : "non-blocking", some_ready ? 
"dispatched" : "nothing");
+
   LOCK_CONTEXT (context);
 
   return some_ready;