From 8855bf052d8bbbd8fdfce1cd5f4a3540661a9c8e Mon Sep 17 00:00:00 2001 From: "Owen W. Taylor" Date: Wed, 14 Nov 2012 19:21:33 -0500 Subject: [PATCH] Add GDK_DEBUG=frames Add a debug option to print out detailed statistics about each frame drawn. https://bugzilla.gnome.org/show_bug.cgi?id=685460 --- gdk/gdk.c | 3 +- gdk/gdkframeclockidle.c | 45 ++++++++++++++++++++++++++++-- gdk/gdkframehistory.c | 41 +++++++++++++++++++++++++++ gdk/gdkframetimings.c | 60 ++++++++++++++++++++++++++++++++++++++++ gdk/gdkinternals.h | 23 ++++++++++++++- gdk/x11/gdkdisplay-x11.c | 5 ++++ gdk/x11/gdkwindow-x11.c | 12 ++++++++ 7 files changed, 184 insertions(+), 5 deletions(-) diff --git a/gdk/gdk.c b/gdk/gdk.c index bc668d4cd..babe08028 100644 --- a/gdk/gdk.c +++ b/gdk/gdk.c @@ -138,7 +138,8 @@ static const GDebugKey gdk_debug_keys[] = { {"multihead", GDK_DEBUG_MULTIHEAD}, {"xinerama", GDK_DEBUG_XINERAMA}, {"draw", GDK_DEBUG_DRAW}, - {"eventloop", GDK_DEBUG_EVENTLOOP} + {"eventloop", GDK_DEBUG_EVENTLOOP}, + {"frames", GDK_DEBUG_FRAMES} }; static gboolean diff --git a/gdk/gdkframeclockidle.c b/gdk/gdkframeclockidle.c index f6e2d339b..09624c45b 100644 --- a/gdk/gdkframeclockidle.c +++ b/gdk/gdkframeclockidle.c @@ -26,6 +26,7 @@ #include "config.h" +#include "gdkinternals.h" #include "gdkframeclockidle.h" #include "gdk.h" @@ -271,6 +272,8 @@ gdk_frame_clock_paint_idle (void *data) GdkFrameClockIdle *clock_idle = GDK_FRAME_CLOCK_IDLE (clock); GdkFrameClockIdlePrivate *priv = clock_idle->priv; gboolean skip_to_resume_events; + GdkFrameTimings *timings = NULL; + gint64 frame_counter = 0; priv->paint_idle_id = 0; priv->in_paint_idle = TRUE; @@ -278,6 +281,12 @@ gdk_frame_clock_paint_idle (void *data) skip_to_resume_events = (priv->requested & ~(GDK_FRAME_CLOCK_PHASE_FLUSH_EVENTS | GDK_FRAME_CLOCK_PHASE_RESUME_EVENTS)) == 0; + if (priv->phase > GDK_FRAME_CLOCK_PHASE_BEFORE_PAINT) + { + frame_counter = gdk_frame_history_get_frame_counter (priv->history); + timings = gdk_frame_history_get_timings (priv->history, frame_counter); + } + if (!skip_to_resume_events) { switch (priv->phase) @@ -288,13 +297,12 @@ gdk_frame_clock_paint_idle (void *data) case GDK_FRAME_CLOCK_PHASE_BEFORE_PAINT: if (priv->freeze_count == 0) { - GdkFrameTimings *timings; - gint64 frame_counter; - priv->frame_time = compute_frame_time (clock_idle); + gdk_frame_history_begin_frame (priv->history); frame_counter = gdk_frame_history_get_frame_counter (priv->history); timings = gdk_frame_history_get_timings (priv->history, frame_counter); + gdk_frame_timings_set_frame_time (timings, priv->frame_time); gdk_frame_timings_set_slept_before (timings, @@ -322,6 +330,15 @@ gdk_frame_clock_paint_idle (void *data) case GDK_FRAME_CLOCK_PHASE_LAYOUT: if (priv->freeze_count == 0) { +#ifdef G_ENABLE_DEBUG + if ((_gdk_debug_flags & GDK_DEBUG_FRAMES) != 0) + { + if (priv->phase != GDK_FRAME_CLOCK_PHASE_LAYOUT && + (priv->requested & GDK_FRAME_CLOCK_PHASE_LAYOUT)) + _gdk_frame_timings_set_layout_start_time (timings, g_get_monotonic_time ()); + } +#endif /* G_ENABLE_DEBUG */ + priv->phase = GDK_FRAME_CLOCK_PHASE_LAYOUT; if (priv->requested & GDK_FRAME_CLOCK_PHASE_LAYOUT) { @@ -332,6 +349,15 @@ gdk_frame_clock_paint_idle (void *data) case GDK_FRAME_CLOCK_PHASE_PAINT: if (priv->freeze_count == 0) { +#ifdef G_ENABLE_DEBUG + if ((_gdk_debug_flags & GDK_DEBUG_FRAMES) != 0) + { + if (priv->phase != GDK_FRAME_CLOCK_PHASE_PAINT && + (priv->requested & GDK_FRAME_CLOCK_PHASE_PAINT)) + _gdk_frame_timings_set_paint_start_time (timings, g_get_monotonic_time ()); + } +#endif /* G_ENABLE_DEBUG */ + priv->phase = GDK_FRAME_CLOCK_PHASE_PAINT; if (priv->requested & GDK_FRAME_CLOCK_PHASE_PAINT) { @@ -347,12 +373,25 @@ gdk_frame_clock_paint_idle (void *data) /* the ::after-paint phase doesn't get repeated on freeze/thaw, */ priv->phase = GDK_FRAME_CLOCK_PHASE_NONE; + +#ifdef G_ENABLE_DEBUG + if ((_gdk_debug_flags & GDK_DEBUG_FRAMES) != 0) + _gdk_frame_timings_set_frame_end_time (timings, g_get_monotonic_time ()); +#endif /* G_ENABLE_DEBUG */ } case GDK_FRAME_CLOCK_PHASE_RESUME_EVENTS: ; } } +#ifdef G_ENABLE_DEBUG + if ((_gdk_debug_flags & GDK_DEBUG_FRAMES) != 0) + { + if (gdk_frame_timings_get_complete (timings)) + _gdk_frame_history_debug_print (priv->history, timings); + } +#endif /* G_ENABLE_DEBUG */ + if (priv->requested & GDK_FRAME_CLOCK_PHASE_RESUME_EVENTS) { priv->requested &= ~GDK_FRAME_CLOCK_PHASE_RESUME_EVENTS; diff --git a/gdk/gdkframehistory.c b/gdk/gdkframehistory.c index e993e5e3f..322467bc8 100644 --- a/gdk/gdkframehistory.c +++ b/gdk/gdkframehistory.c @@ -18,6 +18,7 @@ #include "config.h" #include "gdkframehistory.h" +#include "gdkinternals.h" #define FRAME_HISTORY_MAX_LENGTH 16 @@ -141,3 +142,43 @@ gdk_frame_history_get_last_complete (GdkFrameHistory *history) return NULL; } + +#ifdef G_ENABLE_DEBUG +void +_gdk_frame_history_debug_print (GdkFrameHistory *history, + GdkFrameTimings *timings) +{ + gint64 frame_counter = gdk_frame_timings_get_frame_counter (timings); + gint64 layout_start_time = _gdk_frame_timings_get_layout_start_time (timings); + gint64 paint_start_time = _gdk_frame_timings_get_paint_start_time (timings); + gint64 frame_end_time = _gdk_frame_timings_get_frame_end_time (timings); + gint64 frame_time = gdk_frame_timings_get_frame_time (timings); + gint64 presentation_time = gdk_frame_timings_get_presentation_time (timings); + gint64 refresh_interval = gdk_frame_timings_get_refresh_interval (timings); + gint64 previous_frame_time = 0; + gboolean slept_before = gdk_frame_timings_get_slept_before (timings); + GdkFrameTimings *previous_timings = gdk_frame_history_get_timings (history, + frame_counter - 1); + + if (previous_timings != NULL) + previous_frame_time = gdk_frame_timings_get_frame_time (previous_timings); + + g_print ("%5" G_GINT64_FORMAT ":", frame_counter); + if (previous_frame_time != 0) + { + g_print (" interval=%-4.1f", (frame_time - previous_frame_time) / 1000.); + g_print (slept_before ? " (sleep)" : " "); + } + if (layout_start_time != 0) + g_print (" layout_start=%-4.1f", (layout_start_time - frame_time) / 1000.); + if (paint_start_time != 0) + g_print (" paint_start=%-4.1f", (paint_start_time - frame_time) / 1000.); + if (frame_end_time != 0) + g_print (" frame_end=%-4.1f", (frame_end_time - frame_time) / 1000.); + if (presentation_time != 0) + g_print (" present=%-4.1f", (presentation_time - frame_time) / 1000.); + if (refresh_interval != 0) + g_print (" refresh_interval=%-4.1f", refresh_interval / 1000.); + g_print ("\n"); +} +#endif /* G_ENABLE_DEBUG */ diff --git a/gdk/gdkframetimings.c b/gdk/gdkframetimings.c index a51912baa..08130015f 100644 --- a/gdk/gdkframetimings.c +++ b/gdk/gdkframetimings.c @@ -30,6 +30,12 @@ struct _GdkFrameTimings gint64 presentation_time; gint64 refresh_interval; +#ifdef G_ENABLE_DEBUG + gint64 layout_start_time; + gint64 paint_start_time; + gint64 frame_end_time; +#endif /* G_ENABLE_DEBUG */ + guint complete : 1; guint slept_before : 1; }; @@ -197,3 +203,57 @@ gdk_frame_timings_set_refresh_interval (GdkFrameTimings *timings, timings->refresh_interval = refresh_interval; } + +#ifdef G_ENABLE_DEBUG +gint64 +_gdk_frame_timings_get_layout_start_time (GdkFrameTimings *timings) +{ + g_return_val_if_fail (timings != NULL, 0); + + return timings->layout_start_time; +} + +void +_gdk_frame_timings_set_layout_start_time (GdkFrameTimings *timings, + gint64 layout_start_time) +{ + g_return_if_fail (timings != NULL); + + timings->layout_start_time = layout_start_time; +} + +gint64 +_gdk_frame_timings_get_paint_start_time (GdkFrameTimings *timings) +{ + g_return_val_if_fail (timings != NULL, 0); + + return timings->paint_start_time; +} + +void +_gdk_frame_timings_set_paint_start_time (GdkFrameTimings *timings, + gint64 paint_start_time) +{ + g_return_if_fail (timings != NULL); + + timings->paint_start_time = paint_start_time; +} + +gint64 +_gdk_frame_timings_get_frame_end_time (GdkFrameTimings *timings) +{ + g_return_val_if_fail (timings != NULL, 0); + + return timings->frame_end_time; +} + +void +_gdk_frame_timings_set_frame_end_time (GdkFrameTimings *timings, + gint64 frame_end_time) +{ + g_return_if_fail (timings != NULL); + + timings->frame_end_time = frame_end_time; +} + +#endif /* G_ENABLE_DEBUG */ diff --git a/gdk/gdkinternals.h b/gdk/gdkinternals.h index babef6e7f..423918842 100644 --- a/gdk/gdkinternals.h +++ b/gdk/gdkinternals.h @@ -82,7 +82,8 @@ typedef enum { GDK_DEBUG_MULTIHEAD = 1 << 7, GDK_DEBUG_XINERAMA = 1 << 8, GDK_DEBUG_DRAW = 1 << 9, - GDK_DEBUG_EVENTLOOP = 1 << 10 + GDK_DEBUG_EVENTLOOP = 1 << 10, + GDK_DEBUG_FRAMES = 1 << 11 } GdkDebugFlag; typedef enum { @@ -428,6 +429,26 @@ cairo_surface_t * _gdk_offscreen_window_create_surface (GdkWindow *window, gint width, gint height); +/******************************** + * Debug-only frame statistics * + ********************************/ + +#ifdef G_ENABLE_DEBUG + +gint64 _gdk_frame_timings_get_layout_start_time (GdkFrameTimings *timings); +void _gdk_frame_timings_set_layout_start_time (GdkFrameTimings *timings, + gint64 layout_start_time); +gint64 _gdk_frame_timings_get_paint_start_time (GdkFrameTimings *timings); +void _gdk_frame_timings_set_paint_start_time (GdkFrameTimings *timings, + gint64 paint_time); +gint64 _gdk_frame_timings_get_frame_end_time (GdkFrameTimings *timings); +void _gdk_frame_timings_set_frame_end_time (GdkFrameTimings *timings, + gint64 frame_end_time); + +void _gdk_frame_history_debug_print (GdkFrameHistory *history, + GdkFrameTimings *timings); + +#endif /* G_ENABLE_DEBUG */ G_END_DECLS diff --git a/gdk/x11/gdkdisplay-x11.c b/gdk/x11/gdkdisplay-x11.c index ae4aaafb0..888d87dd7 100644 --- a/gdk/x11/gdkdisplay-x11.c +++ b/gdk/x11/gdkdisplay-x11.c @@ -1155,6 +1155,11 @@ _gdk_wm_protocols_filter (GdkXEvent *xev, gdk_frame_timings_set_refresh_interval (timings, refresh_interval); gdk_frame_timings_set_complete (timings, TRUE); +#ifdef G_ENABLE_DEBUG + if ((_gdk_debug_flags & GDK_DEBUG_FRAMES) != 0) + _gdk_frame_history_debug_print (gdk_frame_clock_get_history (clock), + timings); +#endif /* G_ENABLE_DEBUG */ } } } diff --git a/gdk/x11/gdkwindow-x11.c b/gdk/x11/gdkwindow-x11.c index e70d3fda6..ea74baa3f 100644 --- a/gdk/x11/gdkwindow-x11.c +++ b/gdk/x11/gdkwindow-x11.c @@ -322,6 +322,18 @@ gdk_x11_window_end_frame (GdkWindow *window) if (impl->toplevel->current_counter_value % 2 == 1) { +#ifdef G_ENABLE_DEBUG + if ((_gdk_debug_flags & GDK_DEBUG_FRAMES) != 0) + { + XImage *image = XGetImage (GDK_WINDOW_XDISPLAY (window), + GDK_WINDOW_XID (window), + 0, 0, 1, 1, + (1 << 24) - 1, + ZPixmap); + XDestroyImage (image); + } +#endif /* G_ENABLE_DEBUG */ + /* An increment of 3 means that the frame was not drawn as fast as possible, * but rather at a particular time. This can trigger different handling from * the compositor. -- 2.43.2