From bfe161742cc2b25ff9c22d69509b7b3580f6e4c4 Mon Sep 17 00:00:00 2001
From: Philip Withnall <withnall@endlessm.com>
Date: Thu, 25 Jun 2020 22:23:17 +0100
Subject: [PATCH] gmain: Add sysprof tracing to GMainContext and GSource
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

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;