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
This commit is contained in:
Owen W. Taylor 2012-11-14 19:21:33 -05:00
parent 9690567d50
commit 8855bf052d
7 changed files with 184 additions and 5 deletions

View File

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

View File

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

View File

@ -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 */

View File

@ -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 */

View File

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

View File

@ -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 */
}
}
}

View File

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