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>
This commit is contained in:
Philip Withnall 2020-06-25 22:23:17 +01:00
parent fa13c41da7
commit bfe161742c

View File

@ -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;