From 9fff9729465e95b2eb1a987f69c915d68bfe0c4e Mon Sep 17 00:00:00 2001 From: "Owen W. Taylor" Date: Wed, 16 Jul 2014 10:05:02 -0400 Subject: [PATCH] perf: add a ShellGlobal property to call glFinish and log the time It's useful to know how long frames are taking to render on the GPU. This is impossible to measure in the normal case because frames may parallelize with previous frames, but by calling glFinish() at the end of the frame, we can create a (somewhat artificial, but useful) environment where we have a meaningful timestamp for the frame finishing drawing. https://bugzilla.gnome.org/show_bug.cgi?id=732350 --- src/shell-global.c | 76 ++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 73 insertions(+), 3 deletions(-) diff --git a/src/shell-global.c b/src/shell-global.c index 571483e81..bf38e7d98 100644 --- a/src/shell-global.c +++ b/src/shell-global.c @@ -97,6 +97,7 @@ struct _ShellGlobal { gboolean has_modal; gboolean frame_timestamps; + gboolean frame_finish_timestamp; }; enum { @@ -118,6 +119,7 @@ enum { PROP_USERDATADIR, PROP_FOCUS_MANAGER, PROP_FRAME_TIMESTAMPS, + PROP_FRAME_FINISH_TIMESTAMP, }; /* Signals */ @@ -151,6 +153,9 @@ shell_global_set_property(GObject *object, case PROP_FRAME_TIMESTAMPS: global->frame_timestamps = g_value_get_boolean (value); break; + case PROP_FRAME_FINISH_TIMESTAMP: + global->frame_finish_timestamp = g_value_get_boolean (value); + break; default: G_OBJECT_WARN_INVALID_PROPERTY_ID (object, prop_id, pspec); break; @@ -225,6 +230,9 @@ shell_global_get_property(GObject *object, case PROP_FRAME_TIMESTAMPS: g_value_set_boolean (value, global->frame_timestamps); break; + case PROP_FRAME_FINISH_TIMESTAMP: + g_value_set_boolean (value, global->frame_finish_timestamp); + break; default: G_OBJECT_WARN_INVALID_PROPERTY_ID (object, prop_id, pspec); break; @@ -515,6 +523,13 @@ shell_global_class_init (ShellGlobalClass *klass) "Whether to log frame timestamps in the performance log", FALSE, G_PARAM_READWRITE)); + g_object_class_install_property (gobject_class, + PROP_FRAME_FINISH_TIMESTAMP, + g_param_spec_boolean ("frame-finish-timestamp", + "Frame Finish Timestamps", + "Whether at the end of a frame to call glFinish and log paintCompletedTimestamp", + FALSE, + G_PARAM_READWRITE)); } /* @@ -781,8 +796,56 @@ global_stage_before_paint (gpointer data) } static gboolean -global_stage_after_paint (gpointer data) +load_gl_symbol (const char *name, + void **func) { + *func = cogl_get_proc_address (name); + if (!*func) + { + g_warning ("failed to resolve required GL symbol \"%s\"\n", name); + return FALSE; + } + return TRUE; +} + +static void +global_stage_after_paint (ClutterStage *stage, + ShellGlobal *global) +{ + /* At this point, we've finished all layout and painting, but haven't + * actually flushed or swapped */ + + if (global->frame_timestamps && global->frame_finish_timestamp) + { + /* It's interesting to find out when the paint actually finishes + * on the GPU. We could wait for this asynchronously with + * ARB_timer_query (see https://bugzilla.gnome.org/show_bug.cgi?id=732350 + * for an implementation of this), but what we actually would + * find out then is the latency for drawing a frame, not how much + * GPU work was needed, since frames can overlap. Calling glFinish() + * is a fairly reliable way to separate out adjacent frames + * and measure the amount of GPU work. This is turned on with a + * separate property from ::frame-timestamps, since it should not + * be turned on if we're trying to actual measure latency or frame + * rate. + */ + static void (*finish) (void); + + if (!finish) + load_gl_symbol ("glFinish", (void **)&finish); + + finish (); + + shell_perf_log_event (shell_perf_log_get_default (), + "clutter.paintCompletedTimestamp"); + } +} + +static gboolean +global_stage_after_swap (gpointer data) +{ + /* Everything is done, we're ready for a new frame */ + ShellGlobal *global = SHELL_GLOBAL (data); if (global->frame_timestamps) @@ -974,17 +1037,24 @@ _shell_global_set_plugin (ShellGlobal *global, global_stage_before_paint, global, NULL); + g_signal_connect (global->stage, "after-paint", + G_CALLBACK (global_stage_after_paint), global); + clutter_threads_add_repaint_func_full (CLUTTER_REPAINT_FLAGS_POST_PAINT, - global_stage_after_paint, + global_stage_after_swap, global, NULL); shell_perf_log_define_event (shell_perf_log_get_default(), "clutter.stagePaintStart", "Start of stage page repaint", ""); + shell_perf_log_define_event (shell_perf_log_get_default(), + "clutter.paintCompletedTimestamp", + "Paint completion on GPU", + ""); shell_perf_log_define_event (shell_perf_log_get_default(), "clutter.stagePaintDone", - "End of stage page repaint", + "End of frame, possibly including swap time", ""); g_signal_connect (global->stage, "notify::key-focus",