[gtk/frame-profiling] Redo frame profiling

[Matthias Clasen <matthiasc src gnome org>]

commit 33ffd54d5f5f2db1c7c6d829352f304589c92c94
Author: Matthias Clasen <mclasen redhat com>
Date:   Thu May 16 19:08:34 2019 +0000

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