Exact time of display: requestAnimationFrame usage

Question

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>

Answer 1

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).

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, 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 browsers that do not yet implement this proposal, or if this proposal never does it through the specs, you can try to monkeyPatch it using a MessageEvent, which should be the first thing to fire at the next event loop. However, since there is no way for us to know if we are inside an rAF callback already, except by running an infinite rAF loop, this monkey-patch will not be callable from inside an rAF callback.

// monkey-patches requestPostAnimationFrame
//!\ Can not be called from inside a requestAnimationFrame callback
function monkeyPatchRequestPostAnimationFrame() {
  console.warn('using a MessageEvent workaround');
  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();
}

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);
  }
};

But if you don't care about battery drainage and need to have it callable from inside rAF here it is:

// monkey-patches requestPostAnimationFrame
// runs an infinite rAF loop for it to be callable inside rAF
function monkeyPatchRequestPostAnimationFrame() {
  console.warn('using a MessageEvent workaround');
  const channel = new MessageChannel();
  const callbacks = [];
  let timestamp = 0;
  let called = false;
  channel.port2.onmessage = e => {
    const toCall = callbacks.slice();
    callbacks.length = 0;
    toCall.forEach(fn => {
      try {
        fn(timestamp);
      } catch (e) {}
    });
    // loop in here so that we fire after other rAF loops
    requestAnimationFrame(loop);
  };
  function loop(time) {
    timestamp = time;
    channel.port1.postMessage('');
  }
  window.requestPostAnimationFrame = function(callback) {
    if (typeof callback !== 'function') {
      throw new TypeError('Argument 1 is not callable');
    }
    callbacks.push(callback);
  };
  loop();  
}

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

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);
  });
}

item_display();