Exact time of display: requestAnimationFrame usage and timeline
Asked Answered
N

1

9

What I want to achieve is to detect the precise time of when a certain change appeared on the screen (primarily with Google Chrome). For example I show an item using $("xelement").show(); or change it using $("#xelement").text("sth new"); and then I would want to see what the performance.now() was exactly when the change appeared on the user's screen with the given screen repaint. So I'm totally open to any solutions - below I just refer primarily to requestAnimationFrame (rAF) because that is the function that is supposed to help achieve exactly this, only it doesn't seem to; see below.

Basically, as I imagine, rAF should execute everything inside it in about 0-17 ms (whenever the next frame appears on my standard 60 Hz screen). Moreover, the timestamp argument should give the value of the time of this execution (and this value is based on the same DOMHighResTimeStamp measure as performance.now()).

Now here is one of the many tests I made for this: https://jsfiddle.net/gasparl/k5nx7zvh/31/

function item_display() {
    var before = performance.now();
    requestAnimationFrame(function(timest){
        var r_start = performance.now();
        var r_ts = timest;
        console.log("before:", before);
        console.log("RAF callback start:", r_start);
        console.log("RAF stamp:", r_ts);
        console.log("before vs. RAF callback start:", r_start - before);
        console.log("before vs. RAF stamp:", r_ts - before);
        console.log("")
    });
}
setInterval(item_display, Math.floor(Math.random() * (1000 - 500 + 1)) + 500);

What I see in Chrome is: the function inside rAF is executed always within about 0-3 ms (counting from a performance.now() immediately before it), and, what's weirdest, the rAF timestamp is something totally different from what I get with the performance.now() inside the rAF, being usually about 0-17 ms earlier than the performance.now() called before the rAF (but sometimes about 0-1 ms afterwards).

Here is a typical example:

before: 409265.00000001397
RAF callback start: 409266.30000001758
RAF stamp: 409260.832 
before vs. RAF callback start: 1.30000000353902
before vs. RAF stamp: -4.168000013974961 

In Firefox and in IE it is different. In Firefox the "before vs. RAF callback start" is either around 1-3 ms or around 16-17 ms. The "before vs. RAF stamp" is always positive, usually around 0-3 ms, but sometimes anything between 3-17 ms. In IE both differences are almost always around 15-18 ms (positive). These are more or less the same of different PCs. However, when I run it on my phone's Chrome, then, and only then, it seems plausibly correct: "before vs. RAF stamp" randomly around 0-17, and "RAF callback start" always a few ms afterwards.

For more context: This is for an online response-time experiment where users use their own PC (but I typically restrict browser to Chrome, so that's the only browser that really matters to me). I show various items repeatedly, and measure the response time as "from the moment of the display of the element (when the person sees it) to the moment when they press a key", and count an average from the recorded response times for specific items, and then check the difference between certain item types. This also means that it doesn't matter much if the recorded time is always a bit skewed in a direction (e.g. always 3 ms before the actual appearance of the element) as long as this skew is consistent for each display, because only the difference really matters. A 1-2 ms precision would be the ideal, but anything that mitigates the random "refresh rate noise" (0-17 ms) would be nice.

I also gave a try to jQuery.show() callback, but it does not take refresh rate into account: https://jsfiddle.net/gasparl/k5nx7zvh/67/

var r_start;
function shown() {
    r_start = performance.now();
}
function item_display() {
    var before = performance.now();
    $("#stim_id").show(complete = shown())
    var after = performance.now();
    var text = "before: " + before + "<br>callback RT: " + r_start + "<br>after: " + after + "<br>before vs. callback: " + (r_start - before) + "<br>before vs. after: " + (after - r_start)
    console.log("")
    console.log(text)
    $("p").html(text);
    setTimeout(function(){ $("#stim_id").hide(); }, 500);
}
setInterval(item_display, Math.floor(Math.random() * (1000 - 500 + 1)) + 800);

With HTML:

<p><br><br><br><br><br></p>
<span id="stim_id">STIMULUS</span>

The solution (based on Kaiido's answer) along with working display example:

function monkeyPatchRequestPostAnimationFrame() {
  const channel = new MessageChannel();
  const callbacks = [];
  let timestamp = 0;
  let called = false;
  channel.port2.onmessage = e => {
    called = false;
    const toCall = callbacks.slice();
    callbacks.length = 0;
    toCall.forEach(fn => {
      try {
        fn(timestamp);
      } catch (e) {}
    });
  };
  window.requestPostAnimationFrame = function(callback) {
    if (typeof callback !== 'function') {
      throw new TypeError('Argument 1 is not callable');
    }
    callbacks.push(callback);
    if (!called) {
      requestAnimationFrame((time) => {
        timestamp = time;
        channel.port1.postMessage('');
      });
      called = true;
    }
  };
}

if (typeof requestPostAnimationFrame !== 'function') {
  monkeyPatchRequestPostAnimationFrame();
}

function chromeWorkaroundLoop() {
  if (needed) {
    requestAnimationFrame(chromeWorkaroundLoop);
  }
}

// here is how I display items
// includes a 100 ms "warm-up"
function item_display() {
  window.needed = true;
  chromeWorkaroundLoop();
  setTimeout(function() {
    var before = performance.now();
    $("#stim_id").text("Random new text: " + Math.round(Math.random()*1000) + ".");
    $("#stim_id").show();
    // I ask for display above, and get display time below
    requestPostAnimationFrame(function() {
      var rPAF_now = performance.now();
      console.log("before vs. rPAF now:", rPAF_now - before);
      console.log("");
      needed = false;
    });
  }, 100);
}

// below is just running example instances of displaying stuff
function example_loop(count) {
  $("#stim_id").hide();
  setTimeout(function() {
    item_display();
    if (count > 1) {
      example_loop(--count);
    }
  }, Math.floor(Math.random() * (1000 - 500 + 1)) + 500);
}

example_loop(10);
<script src="https://cdnjs.cloudflare.com/ajax/libs/jquery/2.2.3/jquery.min.js"></script>
<div id="stim_id">Any text</div>

EDIT: So, based on empirical measurements, out of all this, it turns out that all that matters is the rAF loop. The rPAF makes no real difference.

Needlework answered 17/6, 2018 at 9:4 Comment(9)
read about perfomance.now - steps have been taken to mitigate spectre ... i.e. Some browsers may also slightly randomize the timestampLegendre
Wonder if you'll get that level of precision with the randomizationLegendre
The fact that before vs raf is negative 4ms, i doubt you'll get 1ms precisionLegendre
But i don't think this inconsistency is about precision. As i wrote, the difference can range up to 17 ms (in the negative in Chrome), and i hardly think it could be a coincidence that my screen frame interval is around 17 ms too. Now i tested in Firefox and IE too, see my additions in my original questionNeedlework
Yes... spectre killed timing functions... how much precision do you need? Date might not be randomized yet, given its low precision, though it might also be in a near future... Otherwise, AudioContext's timing might have been forgotten, worth a try...Allaround
Also, could you clarify a bit your use case? Why does it really matters the time it has taken between the empirical execution time of your script and the almost empirical time the browser will trigger the rAF callbacks? Because rAF fires before the next frame paint, so at this time, your elements are still not on screen.Allaround
That's true about the rAF firing before the display, I had that it mind, but it does not really matter as long as the time between the rAF firing and the actual display is always the same: see further clarification about the context.Needlework
I also added that precision would be nice to have around 1-2 ms. So yeah, I could use Date.now() as well, it doesn't really matter - but seriously, I really don't think this is an issue, the performance.now() is perfectly fine as well, to test it just put this in the console for example: for (i = 0; i < 19; i++) { console.log(performance.now()); } It will give consecutive numbers with sub-millisecond precision. So it's definitely not like it's being randomized so much that it loses ms precision.Needlework
@Allaround - BaseAudioContext.currentTIme has already been "coarsened": developer.mozilla.org/en-US/docs/Web/API/BaseAudioContext/…Sparkle
A
10

What you are experiencing is a Chrome bug (and even two).

Basically, when the pool of requestAnimationFrame callbacks is empty, they'll call it directly at the end of the current event loop, without waiting for the actual painting frame as the specs require.

To workaround this bug, you can keep an ever-going requestAnimationFrame loop, but beware this will mark your document as "animated" and will trigger a bunch of side-effects on your page (like forcing a repaint at every screen refresh). So I'm not sure what you are doing, but it's generally not a great idea to do this, and I would rather invite you to run this animation loop only when required.

let needed = true; // set to false when you don't need the rAF loop anymore

function item_display() {
  var before = performance.now();
  requestAnimationFrame(function(timest) {
    var r_start = performance.now();
    var r_ts = timest;
    console.log("before:", before);
    console.log("RAF callback start:", r_start);
    console.log("RAF stamp:", r_ts);
    console.log("before vs. RAF callback start:", r_start - before);
    console.log("before vs. RAF stamp:", r_ts - before);
    console.log("")
    setTimeout(item_display, Math.floor(Math.random() * (1000 - 500 + 1)) + 500);
  });
}
chromeWorkaroundLoop();
item_display();

function chromeWorkaroundLoop() {
  if (needed) {
    requestAnimationFrame(chromeWorkaroundLoop);
  }
};

Now, requestAnimationFrame callbacks fire before the next paint (actually in the same event loop), and the TimeStamp argument should represent the time after all main tasks and microtasks of the current frame were executed, before it's starts its "update the rendering" sub-task (step 9 here).
[edit]: However it's not really what browsers implement, see this Q/A for more details.

So it's not the most precise you can have, and you are right that using performance.now() inside this callback should get you closer to the actual painting time.

Moreover when Chrome faces yet an other bug here, probably related to the first one, when they do set this rAF timeStamp to... I must admit I don't know what... maybe the previous painting frame's timeStamp.

(function() {
let raf_id,
  eventLoopReport = {
    id: 0,
    timeStamp: 0,
    now: 0
  },
  report = {
    nb_of_loops_between_call_and_start: -1,
    mouseClick_timeStamp: 0,
    calling_task: {
        eventLoop: null,
      now: 0
    },
    rAF_task: {
        eventLoop: null,
      now: 0,
      timeStamp: 0
    }
  };
  
startEventLoopCounter();
  
btn.onclick = triggerSingleFrame;


// increments eventLoop_id at every event loop
// (or at least every time our postMessage loop fires)
function startEventLoopCounter() {
  const channel = new MessageChannel()
  channel.port2.onmessage = e => {
    eventLoopReport.id ++;
    eventLoopReport.timeStamp = e.timeStamp;
    eventLoopReport.now = performance.now();
    channel.port1.postMessage('*');
  };
  channel.port1.postMessage('*');
}

function triggerSingleFrame(e) {
  // mouseClick Event should be generated at least the previous event loop, so its timeStamp should be in the past
    report.mouseClick_timeStamp = e.timeStamp;
    const report_calling = report.calling_task;
  report_calling.now = performance.now();
  report_calling.eventLoop = Object.assign({}, eventLoopReport);

    cancelAnimationFrame(raf_id);
  
    raf_id = requestAnimationFrame((raf_ts) => {
    const report_rAF = report.rAF_task;
        report_rAF.now = performance.now();
    report_rAF.timeStamp = raf_ts;
    report_rAF.eventLoop = Object.assign({}, eventLoopReport);
    report.nb_of_loops_between_call_and_start = report_rAF.eventLoop.id - report_calling.eventLoop.id;
    // this should always be positive
    report_el.textContent = "rAF.timeStamp - mouse_click.timeStamp: " +
            (report.rAF_task.timeStamp - report.mouseClick_timeStamp) + '\n\n' +
      // verbose
        JSON.stringify(report, null, 2) ;
  });
}
})();
<button id="btn">flash</button>
<div id="out"></div>
<pre id="report_el"></pre>

Once again, running an infinite rAF loop will fix this weird bug.

So one thing you might want to check is the maybe incoming requestPostAnimationFrame method.

You can access it in Chrome,1 after you enable "Experimental Web Platform features" in chrome:flags. This method if accepted by html standards will allow us to fire callbacks immediately after the paint operation occurred.

From there, you should be at the closest of the painting.

var needed = true;
function item_display() {
  var before = performance.now();
  requestAnimationFrame(function() {
    requestPostAnimationFrame(function() {
      var rPAF_now = performance.now();
      console.log("before vs. rPAF now:", rPAF_now - before);
      console.log("");
      setTimeout(item_display, Math.floor(Math.random() * (1000 - 500 + 1)) + 500);
    });
  });
}

if (typeof requestPostAnimationFrame === 'function') {
  chromeWorkaroundLoop();
  item_display();
} else {
  console.error("Your browser doesn't support 'requestPostAnimationFrame' method, be sure you enabled 'Experimental Web Platform features' in chrome:flags");
}

function chromeWorkaroundLoop() {
  if (needed) {
    requestAnimationFrame(chromeWorkaroundLoop);
  }
};

And for the browsers that do not yet implement this proposal, or if this proposal never does it through the specs, you can try to polyfill it using either the Task Scheduling API, or a MessageEvent, which should be the first thing to fire at the next event loop.

// polyfills requestPostAnimationFrame
// requestPostAnimationFrame polyfill
if (typeof requestPostAnimationFrame !== "function") {
  // Either use the Task Scheduling API if available,
  // or fallback to a MessageChannel
  const postTask = (cb) => {
    if (globalThis.scheduler?.postTask) {
      return scheduler.postTask(cb, { priority: "user-blocking" });
    }
    return new Promise((resolve, reject) => {
      const { port1, port2 } = postTask.channel ??= new MessageChannel();
      port1.addEventListener("message", () => {
        try {
          resolve(cb());
        }
        catch(err) {
          reject(err);
        }
      }, { once: true });
      port1.start();
      port2.postMessage("");
    });
  }
  const callbacks = [];
  let timestamp = 0;
  let called = false;
  let scheduled = false; // to make it work from rAF
  let inRAF = false; // to make it work from rAF

  const afterFrame = () => {
    called = false;
    const toCall = callbacks.slice();
    callbacks.length = 0;
    toCall.forEach(fn => {
      try {
        fn(timestamp);
      } catch (err) {
        reportError(err);
      }
    });
  }
  // We need to overwrite rAF to let us know we are inside an rAF callback
  // as to avoid scheduling yet an other rAF, which would be one painting frame late
  // We could have hooked an infinite loop on rAF, but this means
  // forcing the document to be animated all the time
  // which is bad for perfs
  const rAF = globalThis.requestAnimationFrame;
  globalThis.requestAnimationFrame = function(...args) {
    if (!scheduled) {
      scheduled = true;
      rAF.call(globalThis, (time) => inRAF = time);
      globalThis.requestPostAnimationFrame(() => {
        scheduled = false;
        inRAF = false;
      });
    }
    rAF.apply(globalThis, args);
  };
  globalThis.requestPostAnimationFrame = function(callback) {
    if (typeof callback !== "function") {
      throw new TypeError("Argument 1 is not callable");
    }
    callbacks.push(callback);
    if (!called) {
      if (inRAF) {
        timestamp = inRAF;
        postTask(afterFrame);
      } else {
        requestAnimationFrame((time) => {
          timestamp = time;
          postTask(afterFrame);
        });
      }
      called = true;
    }
  };
}

var needed = true;

function item_display() {
  var before = performance.now();
  requestPostAnimationFrame(function() {
    var rPAF_now = performance.now();
    console.log("before vs. rPAF now:", rPAF_now - before);
    console.log("");
    setTimeout(item_display, Math.floor(Math.random() * (1000 - 500 + 1)) + 500);
  });
}


chromeWorkaroundLoop();
item_display();

function chromeWorkaroundLoop() {
  if (needed) {
    requestAnimationFrame(chromeWorkaroundLoop);
  }
};
  1. Turns out this feature has apparently been removed from Chrome experiments. Looking at the implementation issue I can't find why, when, nor if they plan to still work on it.
Allaround answered 19/8, 2019 at 2:28 Comment(9)
Thanks very much @Kaiido, this is a cool answer, and you'll get the bounty if I get no better answer (e.g. getting time without workaround, if that's possible). There is just one quite troubling thing: what I see using my Chrome in both "before vs. RAF callback start:" and "before vs. RAF stamp:", is a gradually decreasing number, e.g., 14 ms, 12, 8, 5, 2, then again, 15, 13, etc. Since the interval is random, this should be random too, right? Do you have any explanation for this? And/or do you perhaps have any way of clearly demonstrating that these numbers truly reflects the repaint time?Needlework
Two more minor notes, though these are not really important. First, I highly doubt that the "jitter" you mention has any effect: as I already mentioned in another comment, for (i = 0; i < 19; i++) { console.log(performance.now()); } gives consecutive numbers with sub-millisecond precision, which seems to prove that performance.now() has at least ms precision. Second, I cannot use local modifications because the entire purpose of this repaint measure is to be used in online psychological experiments, where each user has his own PC. (Tho I typically do not allow using any browser except Chrome.)Needlework
@Needlework for the jitter you are completely correct and this made me realize that the rAF timeStamp in case of early call is simply completely wrong. Also, I guess you'd be better use at least the monkey-patch of requestPostAnimationFrame available at the end of the answer. However for the degrading it was kind of normal, we weren't running a random interval no, the interval while set to a random value was the same at each iteration, so a linear variation was to be expected. I fixed it in my answer for you.Allaround
Wow. Okay, regarding the randomness: yeah, my bad, I didn't realize it was just called once, thanks for correcting.Needlework
As for the rest, awesome, and I already accepted this answer. Still, would you please take a glance at my given solution (in the question), if I correctly implemented your functions (from your second to last snippet)? Basically, I just start each display with a 100 ms "warm-up" of chromeWorkaroundLoop(), and after display I switch it off by needed = false - this way the loop rAF does not interfere with the rest of the script.Needlework
(During that 100, there will be nothing else happening anyway, so it is no issue. Also, I see no reason to ever call another rAF or rPAF recursively, because I'm always only interested in a single display time; and these single display times are seconds apart.)Needlework
note also that I call the show() functions right before the rPAF function - and so expect the rPAF_now to return the actual display time of the displays initiated by those show() functions - that's the correct way, right?Needlework
@Needlework yes, that's the correct way indeed. rPAF_now should be the time the closest to the painting operation we can have. Your warmup implementation is on point, and you correctly lower the flag when it needs to be. Well done. (Now, if you wish to know approximately how long a painting took, you'd need to wrap your calling method in an rAF callback: jsfiddle.net/wx17byL6, but I'm not sure you are interested in this, and if you are, then you might want to let your users run Performance recording from their browser's dev-tools.Allaround
Awesome. The painting time is also cool to see as a test, but yeah I won't need that. Anyway, you solved this entire annoying issue I've had for years - thanks again!!Needlework

© 2022 - 2024 — McMap. All rights reserved.