From 33ffd54d5f5f2db1c7c6d829352f304589c92c94 Mon Sep 17 00:00:00 2001 From: Matthias Clasen Date: Thu, 16 May 2019 19:08:34 +0000 Subject: [PATCH] Redo frame profiling We were adding incomplete frame timings to the profile, which lead to occasional nonsense numbers. Instead, only add timings to the profile once we marked them as complete. This also gives us an opportunity to add the presentation time as a marker. --- gdk/gdkframeclock.c | 109 ++++++++++++++++++++++++++++++ gdk/gdkframeclockidle.c | 112 ------------------------------- gdk/gdkframeclockprivate.h | 3 + gdk/wayland/gdksurface-wayland.c | 3 + gdk/x11/gdkdisplay-x11.c | 3 + 5 files changed, 118 insertions(+), 112 deletions(-) diff --git a/gdk/gdkframeclock.c b/gdk/gdkframeclock.c index 9338a23668..4f396bdd93 100644 --- a/gdk/gdkframeclock.c +++ b/gdk/gdkframeclock.c @@ -87,6 +87,8 @@ enum { static guint signals[LAST_SIGNAL]; +static guint fps_counter; + #define FRAME_HISTORY_MAX_LENGTH 16 struct _GdkFrameClockPrivate @@ -252,6 +254,11 @@ gdk_frame_clock_init (GdkFrameClock *clock) priv->frame_counter = -1; priv->current = FRAME_HISTORY_MAX_LENGTH - 1; + +#ifdef G_ENABLE_DEBUG + if (fps_counter == 0) + fps_counter = gdk_profiler_define_counter ("fps", "Frames per Second"); +#endif } /** @@ -645,3 +652,105 @@ _gdk_frame_clock_emit_resume_events (GdkFrameClock *frame_clock) { g_signal_emit (frame_clock, signals[RESUME_EVENTS], 0); } + +#ifdef G_ENABLE_DEBUG +static gint64 +guess_refresh_interval (GdkFrameClock *frame_clock) +{ + gint64 interval; + gint64 i; + + interval = G_MAXINT64; + + for (i = gdk_frame_clock_get_history_start (frame_clock); + i < gdk_frame_clock_get_frame_counter (frame_clock); + i++) + { + GdkFrameTimings *t, *before; + gint64 ts, before_ts; + + t = gdk_frame_clock_get_timings (frame_clock, i); + before = gdk_frame_clock_get_timings (frame_clock, i - 1); + if (t == NULL || before == NULL) + continue; + + ts = gdk_frame_timings_get_frame_time (t); + before_ts = gdk_frame_timings_get_frame_time (before); + if (ts == 0 || before_ts == 0) + continue; + + interval = MIN (interval, ts - before_ts); + } + + if (interval == G_MAXINT64) + return 0; + + return interval; +} + +static double +frame_clock_get_fps (GdkFrameClock *frame_clock) +{ + GdkFrameTimings *start, *end; + gint64 start_counter, end_counter; + gint64 start_timestamp, end_timestamp; + gint64 interval; + + start_counter = gdk_frame_clock_get_history_start (frame_clock); + end_counter = gdk_frame_clock_get_frame_counter (frame_clock); + start = gdk_frame_clock_get_timings (frame_clock, start_counter); + for (end = gdk_frame_clock_get_timings (frame_clock, end_counter); + end_counter > start_counter && end != NULL && !gdk_frame_timings_get_complete (end); + end = gdk_frame_clock_get_timings (frame_clock, end_counter)) + end_counter--; + if (end_counter - start_counter < 4) + return 0.0; + + start_timestamp = gdk_frame_timings_get_presentation_time (start); + end_timestamp = gdk_frame_timings_get_presentation_time (end); + if (start_timestamp == 0 || end_timestamp == 0) + { + start_timestamp = gdk_frame_timings_get_frame_time (start); + end_timestamp = gdk_frame_timings_get_frame_time (end); + } + interval = gdk_frame_timings_get_refresh_interval (end); + if (interval == 0) + { + interval = guess_refresh_interval (frame_clock); + if (interval == 0) + return 0.0; + } + + return ((double) end_counter - start_counter) * G_USEC_PER_SEC / (end_timestamp - start_timestamp); +} +#endif + +void +_gdk_frame_clock_add_timings_to_profiler (GdkFrameClock *clock, + GdkFrameTimings *timings) +{ +#ifdef G_ENABLE_DEBUG + gdk_profiler_add_mark (timings->frame_time * 1000, + (timings->frame_end_time - timings->frame_time) * 1000, + "frame", ""); + + if (timings->layout_start_time != 0) + gdk_profiler_add_mark (timings->layout_start_time * 1000, + (timings->paint_start_time - timings->layout_start_time) * 1000, + "layout", ""); + + if (timings->paint_start_time != 0) + gdk_profiler_add_mark (timings->paint_start_time * 1000, + (timings->frame_end_time - timings->paint_start_time) * 1000, + "paint", ""); + + if (timings->presentation_time != 0) + gdk_profiler_add_mark (timings->presentation_time * 1000, + 0, + "presentation", ""); + + gdk_profiler_set_counter (fps_counter, + timings->frame_end_time * 1000, + frame_clock_get_fps (clock)); +#endif +} diff --git a/gdk/gdkframeclockidle.c b/gdk/gdkframeclockidle.c index 8bbdffb68b..a917176993 100644 --- a/gdk/gdkframeclockidle.c +++ b/gdk/gdkframeclockidle.c @@ -114,96 +114,6 @@ get_sleep_serial (void) return sleep_serial; } -static guint fps_counter = 0; - -static void -add_timings_to_profiler (GdkFrameTimings *timings) -{ - gdk_profiler_add_mark (timings->frame_time * 1000, - (timings->frame_end_time - timings->frame_time) * 1000, - "frame", ""); - if (timings->layout_start_time != 0) - gdk_profiler_add_mark (timings->layout_start_time * 1000, - (timings->paint_start_time - timings->layout_start_time) * 1000, - "layout", ""); - - if (timings->paint_start_time != 0) - gdk_profiler_add_mark (timings->paint_start_time * 1000, - (timings->frame_end_time - timings->paint_start_time) * 1000, - "paint", ""); -} - -static gint64 -guess_refresh_interval (GdkFrameClock *frame_clock) -{ - gint64 interval; - gint64 i; - - interval = G_MAXINT64; - - for (i = gdk_frame_clock_get_history_start (frame_clock); - i < gdk_frame_clock_get_frame_counter (frame_clock); - i++) - { - GdkFrameTimings *t, *before; - gint64 ts, before_ts; - - t = gdk_frame_clock_get_timings (frame_clock, i); - before = gdk_frame_clock_get_timings (frame_clock, i - 1); - if (t == NULL || before == NULL) - continue; - - ts = gdk_frame_timings_get_frame_time (t); - before_ts = gdk_frame_timings_get_frame_time (before); - if (ts == 0 || before_ts == 0) - continue; - - interval = MIN (interval, ts - before_ts); - } - - if (interval == G_MAXINT64) - return 0; - - return interval; -} - -static double -frame_clock_get_fps (GdkFrameClock *frame_clock) -{ - GdkFrameTimings *start, *end; - gint64 start_counter, end_counter; - gint64 start_timestamp, end_timestamp; - gint64 interval; - - start_counter = gdk_frame_clock_get_history_start (frame_clock); - end_counter = gdk_frame_clock_get_frame_counter (frame_clock); - start = gdk_frame_clock_get_timings (frame_clock, start_counter); - for (end = gdk_frame_clock_get_timings (frame_clock, end_counter); - end_counter > start_counter && end != NULL && !gdk_frame_timings_get_complete (end); - end = gdk_frame_clock_get_timings (frame_clock, end_counter)) - end_counter--; - if (end_counter - start_counter < 4) - return 0.0; - - start_timestamp = gdk_frame_timings_get_presentation_time (start); - end_timestamp = gdk_frame_timings_get_presentation_time (end); - if (start_timestamp == 0 || end_timestamp == 0) - { - start_timestamp = gdk_frame_timings_get_frame_time (start); - end_timestamp = gdk_frame_timings_get_frame_time (end); - } - - interval = gdk_frame_timings_get_refresh_interval (end); - if (interval == 0) - { - interval = guess_refresh_interval (frame_clock); - if (interval == 0) - return 0.0; - } - - return ((double) end_counter - start_counter) * G_USEC_PER_SEC / (end_timestamp - start_timestamp); -} - static void gdk_frame_clock_idle_init (GdkFrameClockIdle *frame_clock_idle) { @@ -214,11 +124,6 @@ gdk_frame_clock_idle_init (GdkFrameClockIdle *frame_clock_idle) priv->frame_time = g_get_monotonic_time (); /* more sane than zero */ priv->freeze_count = 0; - -#ifdef G_ENABLE_DEBUG - if (fps_counter == 0) - fps_counter = gdk_profiler_define_counter ("fps", "Frames per Second"); -#endif } static void @@ -570,23 +475,6 @@ gdk_frame_clock_paint_idle (void *data) } } -#ifdef G_ENABLE_DEBUG - if (gdk_profiler_is_running ()) - { - if (timings) - { - add_timings_to_profiler (timings); - gdk_profiler_set_counter (fps_counter, timings->frame_end_time * 1000, frame_clock_get_fps (clock)); - } - } - - if (GDK_DEBUG_CHECK (FRAMES)) - { - if (timings && timings->complete) - _gdk_frame_clock_debug_print_timings (clock, 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/gdkframeclockprivate.h b/gdk/gdkframeclockprivate.h index 17e06dfcf7..17d063b434 100644 --- a/gdk/gdkframeclockprivate.h +++ b/gdk/gdkframeclockprivate.h @@ -28,6 +28,7 @@ #define __GDK_FRAME_CLOCK_PRIVATE_H__ #include +#include G_BEGIN_DECLS @@ -110,6 +111,8 @@ void _gdk_frame_clock_thaw (GdkFrameClock *clock); void _gdk_frame_clock_begin_frame (GdkFrameClock *clock); void _gdk_frame_clock_debug_print_timings (GdkFrameClock *clock, GdkFrameTimings *timings); +void _gdk_frame_clock_add_timings_to_profiler (GdkFrameClock *frame_clock, + GdkFrameTimings *timings); GdkFrameTimings *_gdk_frame_timings_new (gint64 frame_counter); gboolean _gdk_frame_timings_steal (GdkFrameTimings *timings, diff --git a/gdk/wayland/gdksurface-wayland.c b/gdk/wayland/gdksurface-wayland.c index 7af011b814..f92a8ce2ad 100644 --- a/gdk/wayland/gdksurface-wayland.c +++ b/gdk/wayland/gdksurface-wayland.c @@ -423,6 +423,9 @@ frame_callback (void *data, #ifdef G_ENABLE_DEBUG if ((_gdk_debug_flags & GDK_DEBUG_FRAMES) != 0) _gdk_frame_clock_debug_print_timings (clock, timings); + + if (gdk_profiler_is_running ()) + _gdk_frame_clock_add_timings_to_profiler (clock, timings); #endif } diff --git a/gdk/x11/gdkdisplay-x11.c b/gdk/x11/gdkdisplay-x11.c index ca1237e703..dc0f017afd 100644 --- a/gdk/x11/gdkdisplay-x11.c +++ b/gdk/x11/gdkdisplay-x11.c @@ -1283,6 +1283,9 @@ _gdk_wm_protocols_filter (const XEvent *xevent, #ifdef G_ENABLE_DEBUG if (GDK_DISPLAY_DEBUG_CHECK (display, FRAMES)) _gdk_frame_clock_debug_print_timings (clock, timings); + + if (gdk_profiler_is_running ()) + _gdk_frame_clock_add_timings_to_profiler (clock, timings); #endif /* G_ENABLE_DEBUG */ } }