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.
This commit is contained in:
Matthias Clasen 2019-05-16 19:08:34 +00:00
parent 96a806e096
commit 33ffd54d5f
5 changed files with 118 additions and 112 deletions

View File

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

View File

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

View File

@ -28,6 +28,7 @@
#define __GDK_FRAME_CLOCK_PRIVATE_H__
#include <gdk/gdkframeclock.h>
#include <gdk/gdkprofilerprivate.h>
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,

View File

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

View File

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