[GDK3] update frame_time only in gdk_frame_clock_paint_idle()

TLDR

The frame clock time might be updated when gdk_frame_clock_get_frame_time() is called, even if we don't blow our frame budget. This has several issues, so with this MR the frame clock time is no longer updated in this function.

The root cause for the bug is that right after the 'begin-paint' phase, frame_time is already at a delta from the current time. This delta can be several milliseconds. So even if gdk_frame_clock_get_frame_time() is called less than a frame interval later, is will reset the frame clock time.

Description

In order to demonstrate the bug, the code of tests/testinput.c from the GTK source tree was slightly modified with added debug prints. The modified, hackish version can be found here. The function smooth_scroll_notify_event() was added in order to get the frame time whenever a "smooth scroll" event is received. It also forces a frame update.

This is the relevant part:

static gint
smooth_scroll_notify_event (GtkWidget *widget, GdkEventScroll *event, void *dummy)
{
  GdkFrameClock *frame_clock = gtk_widget_get_frame_clock (widget);
  GdkFrameClockIdlePrivate *priv = ((struct _GdkFrameClockIdle *)frame_clock)->priv;

  gint64 orig_frame_time = priv->frame_time;
  static gint64 previous_time = 0;
  gint64 current_time = g_get_monotonic_time ();
  gint64 frame_time = gdk_frame_clock_get_frame_time (frame_clock);

  printf ("input: current_time = %ld current_time - previous_time = %ld original frame_time = %ld frame_time = %ld current_time - original frame_time = %ld\n",
          current_time,
          current_time - previous_time,
          orig_frame_time,
          frame_time,
          current_time - orig_frame_time);

  if (orig_frame_time != frame_time)
    printf ("\n*** BOOM *** frame_time - original frame_time = %ld\n\n",
            frame_time - orig_frame_time);

  previous_time = current_time;

smooth_scroll_notify_event() is connected to the scroll_event signal of the drawing area:

    g_signal_connect (drawing_area, "scroll_event",
          G_CALLBACK (smooth_scroll_notify_event), NULL);

Essentially the above code calls gdk_frame_clock_get_frame_time() while handling a scroll event, and checks if frame_time was modified by that call.

In addition, the following debug print was added to gdk_frame_clock_paint_idle(). Incidentally, the following snippet is also where frame_time is normally updated:

diff --git a/gdk/gdkframeclockidle.c b/gdk/gdkframeclockidle.c
index 8f17d7596f..1e30e677fc 100644
--- a/gdk/gdkframeclockidle.c
+++ b/gdk/gdkframeclockidle.c
@@ -366,6 +366,18 @@ gdk_frame_clock_paint_idle (void *data)
               smoothest_frame_time = priv->frame_time + frame_interval;
               reset_frame_time = compute_frame_time (clock_idle);
               frame_time_error = ABS (reset_frame_time - smoothest_frame_time);
+
+              gint64 current_time = g_get_monotonic_time();
+              static gint64 previous_time = 0;
+
+              printf ("idle: current_time = %ld current_time - previous_time = %ld frame_time = %ld frame_time_error = %ld\n",
+                      current_time,
+                      current_time - previous_time,
+                      priv->frame_time,
+                      frame_time_error);
+
+              previous_time = current_time;
+
               if (frame_time_error >= frame_interval)
                 priv->frame_time = reset_frame_time;
               else
                 priv->frame_time = smoothest_frame_time;

The following log snippet was generated by running tests/testinput and continuously scrolling in circles using the touchpad:

input: current_time = 40961097759 current_time - previous_time = 11872 original frame_time = 40961091835 frame_time = 40961091835 current_time - original frame_time = 5924
input: current_time = 40961108394 current_time - previous_time = 10635 original frame_time = 40961091835 frame_time = 40961091835 current_time - original frame_time = 16559
idle: current_time = 40961111963 current_time - previous_time = 16932 frame_time = 40961091835 frame_time_error = 3462
input: current_time = 40961120420 current_time - previous_time = 12026 original frame_time = 40961108501 frame_time = 40961108501 current_time - original frame_time = 11919
idle: current_time = 40961128801 current_time - previous_time = 16838 frame_time = 40961108501 frame_time_error = 3633
input: current_time = 40961131750 current_time - previous_time = 11330 original frame_time = 40961125167 frame_time = 40961125167 current_time - original frame_time = 6583
input: current_time = 40961142143 current_time - previous_time = 10393 original frame_time = 40961125167 frame_time = 40961142144 current_time - original frame_time = 16976

*** BOOM *** frame_time - original frame_time = 16977

idle: current_time = 40961145673 current_time - previous_time = 16872 frame_time = 40961142144 frame_time_error = 13137
input: current_time = 40961154153 current_time - previous_time = 12010 original frame_time = 40961158810 frame_time = 40961158810 current_time - original frame_time = -4657
idle: current_time = 40961162072 current_time - previous_time = 16399 frame_time = 40961158810 frame_time_error = 13404
input: current_time = 40961165460 current_time - previous_time = 11307 original frame_time = 40961175476 frame_time = 40961175476 current_time - original frame_time = -10016
input: current_time = 40961175951 current_time - previous_time = 10491 original frame_time = 40961175476 frame_time = 40961175476 current_time - original frame_time = 475
idle: current_time = 40961178061 current_time - previous_time = 15989 frame_time = 40961175476 frame_time_error = 14081

In the above snippet, lines starting with "input:" were printed by the application, and those starting with "idle:" are from
gdk_frame_clock_paint_idle().. In all debug lines, current_time is the value returned by g_get_monotonic_time(), previous_time is the value of current_time in the previous debug print of the same source - i.e. previous_time is calculated separately for "input" and for "idle". In the "input" lines, original frame_time is the value of the frame_time member of GdkFrameClockIdlePrivate before calling gdk_frame_clock_get_frame_time(). frame_time is the value returned by gdk_frame_clock_get_frame_time().

The line which is subtly marked with "BOOM" is printed when frame_time is different from original frame_time, i.e. it was modified by the call to gdk_frame_clock_get_frame_time().

A cursory look might lead one to believe that we blew our frame budget here, since in the "BOOM" line we clearly see that original frame_time (the last debug print before the "BOOM") is more than a frame interval away from the current time. So obviously we should reset frame_time, right?

Not so fast. The truth is that we didn't blow our frame budget here. In fact, we didn't actually have to reset frame_time in this case. So let's see what happens here.

The bug

Normally, GDK_FRAME_CLOCK_PHASE_BEFORE_PAINT is where frame_time is updated (and reset). This is done in the function gdk_frame_clock_paint_idle(), see here or the code snippet above.

This is the timeline:

... --> vblank --> ... --> before paint (new frame_time) --> ... -> after paint -> ... --> vblank --> ....

When the 'before paint' phase is handled in gdk_frame_clock_paint_idle(), the frame_time is updated. If, at that point, frame_time_error - the delta between (frame_time + frame interval) and the current time - is more than a frame interval, frame_time is reset. This should keep the value of frame_time within 1 frame interval of the current time at that point.

In fact, since under normal operation frame_time is advanced by exactly 1 frame interval at that point, the delta between frame_time and the current time at that point stays more-or-less constant. Taking a look at the values of frame_time_error in the log snippet above, it is apparent that before the reset of frame_time (the "BOOM") the delta hovered around 3,500 microseconds after the update. This value is smaller than a frame interval, which is 16,667 on this system (corresponding to 60FPS), so frame_time was not reset.

If we now look only at the "idle:" lines in the log snippet, we can see that no frame skip occurred. The delta between consecutive calls to gdk_frame_clock_paint_idle() - i.e., current_time - previous_time - was always around 16,667 microseconds, which is the frame interval. So there was no real need to reset the frame time.

Now, let's look what happened right before frame_time was reset:

1. gdk_frame_clock_paint_idle() was called at time 40961128801 (note: this is the timestamp of the debug print, but the time used for the calculations was actually 1 microsecond earlier. That's because g_get_monotonic_time() was called separately for compute_frame_time() before the debug print). frame_time was 40961108501 at that point. frame_time_error, the delta between (frame_time + frame interval) and current time, is 3633 - which is smaller than 16666, a frame interval - so no problem. Then frame_time was increased by 16666 - the frame interval - to 40961125167.
2. First input event arrives at time 40961131750. The delta from frame_time is 6583 so no problem.
3. Second input event arrives at time 40961142143. The delta from frame_time is 16976 so frame_time is reset by the call to gdk_frame_clock_get_frame_time(). That happens because, after the 'begin-paint' phase, frame_time was already at a delta of 3633 microseconds from the then-current time. This event arrived just 13342 microseconds after "begin-paint", so there was no actual need for a frame_time reset.
4. gdk_frame_clock_paint_idle() was called at time 40961145673, which amounts to 16872 microseconds after the previous call to that function. This is almost exactly a frame interval, and if gdk_frame_clock_get_frame_time() was not called by the input event handler, no frame_time reset would have occurred.

Summary

Because gdk_frame_clock_get_frame_time() updated the frame_time, the latter was reset for no good reason. This causes a skew in frame_time, which in turn leads to jittery animations, further resets etc. To add insult to injury, since frame_time was changed in the middle of processing an input event, it could lead to parts of the frame being rendered differently compared to other parts. So in addition to a clock skew, we might also get a jank frame.

The essense of this problem is that gdk_frame_clock_paint_idle() has more information than gdk_frame_clock_idle_get_frame_time(). While the former is usually called more or less every "frame interval" microseconds, the latter can be called at any point in the frame life cycle. That means that gdk_frame_clock_paint_idle() can make more informed decisions regarding if and how to reset frame_time. For example, it knows that when it is called, it should compare current time to (frame_time + frame interval), since about a single frame interval should have passed since it was last called. This is in contrast to gdk_frame_clock_idle_get_frame_time(), which can have no informed opinion on what the value of frame_time should be when it is called.

Some more thoughts

The original code had this comment:

* get_frame_time() would normally be used outside of a paint to
* record an animation start time for example.

This is probably wrong. An application should record the frame time on the first time that the frame clock's update signal fires. Thereafter it should draw the animation based on the delta between the current frame time and the recorded one. Incidentally this is exactly what the various in-tree demo applications do.

If an application calls gdk_frame_clock_get_frame_time() outside of a paint - say, when an input event is received - the frame time might change, as explained above. This both leads to different frame times at different phases of the frame, and to jittery animation since the frame time won't advance in steps of frame interval.

This is especially annoying when, for example, the frame time is used in debug prints for input events. In this case we get a 'Heisenbug' since the animation would only be erratic when the debug prints are enabled, and even then only occasionally.

There is an additional minor issue with the current implementation of gdk_frame_clock_idle_get_frame_time() - it assumes that the frame interval is a contant 16667 microseconds which corresponds to a 60FPS monitor. This is of course not always true.

From the commit message:

frame_time should stay stable during a frame, and ideally increase in
multiples of frame interval in order to accurately track actual
presentation times.

To achieve that, frame_time should only be updated once per frame, at
the start of each frame. Remove updating it in
gdk_frame_clock_idle_get_frame_time(), so it is only updated in the
BEFORE_PAINT phase in gdk_frame_clock_paint_idle().

Fixes #2475 (closed)