New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 823274 link

Starred by 1 user

Issue metadata

Status: WontFix
Owner:
Xoogler
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: Bug



Sign in to add a comment

Investigate timer firing before the deadline

Project Member Reported by altimin@chromium.org, Mar 19 2018

Issue description

There are reports of timer firing before the specified deadline: https://chromium-review.googlesource.com/c/chromium/src/+/938667


 
Owner: kraynov@chromium.org
Status: Assigned (was: Available)
Will take a look
I've grabbed a trace with https://chromium-review.googlesource.com/938667 and there's the hack to extract the data we want (copy-paste in dev console when trace is openned):

model = document.getElementsByTagName('tr-ui-timeline-track-view')[0].model_;
timerTicks = [];
for (const process of Object.values(model.processes)) {
  for (const thread of Object.values(process.threads)) {
    for (const slice of thread.sliceGroup.slices) {
      if (slice.category !== 'media') {
        continue;
      }
      if (slice.title === 'PERIODIC ScheduleTimeupdateEvent' ||
          slice.title === 'RESTART TimeupdateEvent') {
        traceTime = slice.start;
        chromeTime = slice.args.now;
        timerTicks.push({traceTime, chromeTime});
      }
    }
  }
}
console.log('Original events:');
console.log(timerTicks);
traceOffset = timerTicks[0].traceTime;
chromeOffset = timerTicks[0].chromeTime;
for (const tick of timerTicks) {
  tick.traceTime -= traceOffset;
  tick.chromeTime -= chromeOffset;
  tick.chromeTime /= 1000;
}
console.log('Normalised time events:');
for (const tick of timerTicks) {
  console.log('Trace: ' + tick.traceTime + ' \t Chrome: ' + tick.chromeTime);
}

Results for trace provided:

Trace: 0 			 Chrome: 0
Trace: 250.07299995422363 	 Chrome: 250.072
Trace: 500.0690002441406 	 Chrome: 500.068
Trace: 750.0640001296997 	 Chrome: 750.064
Trace: 1000.1090002059937 	 Chrome: 1000.109
Trace: 1250.0769996643066 	 Chrome: 1250.077
Trace: 1500.0469999313354 	 Chrome: 1500.047
Trace: 1750.3509998321533 	 Chrome: 1750.351
Trace: 2000.0559997558594 	 Chrome: 2000.056
Trace: 2250.079999923706 	 Chrome: 2250.08
Trace: 2500.0880002975464 	 Chrome: 2500.087
Trace: 2750.0369997024536 	 Chrome: 2750.037
Trace: 3000.050000190735 	 Chrome: 3000.049
Trace: 3250.1040000915527 	 Chrome: 3250.103
Trace: 3500.069999694824 	 Chrome: 3500.069
Trace: 3750.0769996643066 	 Chrome: 3750.077
Trace: 4000.0769996643066 	 Chrome: 4000.077
Trace: 4250.086000442505 	 Chrome: 4250.085
Trace: 4500.059000015259 	 Chrome: 4500.059
Trace: 4750.067000389099 	 Chrome: 4750.067
Trace: 5000.052000045776 	 Chrome: 5000.051
Trace: 5250.1759996414185 	 Chrome: 5250.175
Trace: 5500.072999954224 	 Chrome: 5500.073
Trace: 5750.015000343323 	 Chrome: 5750.015
Trace: 6000.069999694824 	 Chrome: 6000.07
Trace: 6250.074999809265 	 Chrome: 6250.075
Trace: 6500.046000480652 	 Chrome: 6500.046
Trace: 6750.069000244141 	 Chrome: 6750.068
Trace: 7000.0740003585815 	 Chrome: 7000.073
Trace: 7250.0509996414185 	 Chrome: 7250.051
Trace: 7500.074999809265 	 Chrome: 7500.075
Trace: 7750.076000213623 	 Chrome: 7750.076
Trace: 8000.102999687195 	 Chrome: 8000.102
Trace: 8250.180000305176 	 Chrome: 8250.18
Trace: 8500.098999977112 	 Chrome: 8500.098

'Trace' means the time in milliseconds when trace event has been recorded.
'Chrome' means time returned by CurrentTimeTicks().
trace_Thu_Mar_22_2018_1.55.07_PM.json.gz
1.9 MB Download
Here's my trace showing some early events. 

Here's a sheet that breaks down the times (googler only)
https://docs.google.com/spreadsheets/d/13dxH6meTsVRHIO_RjzdUzxbDYDUtEb1fTLeJTP9Y70E/edit#gid=0
trace_timeupdateTimerTrace.json.gz
71.1 KB Download
The problem is (apparently) rooted in how we calculate a timer slack.

@chcunningham normally timer starts in StartPlaybackProgressTimer() function and that moment was NOT traced in
https://chromium-review.googlesource.com/938667

Timer is expected to tick this way:
Where: t - time, p - period, s - slack (expected to be >= 0)
t0:                 Start repeating
t1 = t0 + 1*p + s1: Tick
t2 = t0 + 2*p + s2: Tick
t3 = t0 + 3*p + s3: Tick
t4 = t0 + 4*p + s4: Tick
t5 = t0 + 5*p + s5: Tick
...

So if we calculate slack starting from t1 (since t0 wasn't traced):
t1 = t0 + 1*p + s1:        First event recorded, also t0 = t1 - p - s1
t2 = t1 + 1*p + (s2 - s1): Tick
t3 = t1 + 2*p + (s3 - s1): Tick
t4 = t1 + 3*p + (s4 - s1): Tick
t5 = t1 + 4*p + (s5 - s1): Tick
Hence, if s1 != 0 all subsequent (sX - s1) "slacks" will get a random sign.

Please take a look into (hopefully) proper slack calculation:
https://chromium-review.googlesource.com/980612

@altimin Should we add a test case? Would it be easy with virtual time?
https://cs.chromium.org/chromium/src/third_party/WebKit/Source/platform/TimerTest.cpp
Status: WontFix (was: Assigned)
We (me and @chcunningham) have verified that timer works as explained in the Comment #4.
CL to test that https://chromium-review.googlesource.com/980612

Summary in more structured way:

1. TaskRunnerTimer::StartRepeating sets a periodic timer scheduling events to happen at the specific times in future.

   P  = <period>
   T0 = <when StartRepeating called>
   T1 = T0 + P
   T2 = T0 + 2*P
   ...
   TN = T0 + N*P
   ...

   However, actual time when event dispatches is slightly later than the time scheduled (call it "slack").
   Doing so early is incorrect behaviour and we haven't observed one (but maybe it deserves a unittest).

2. Define tN = TN + sN, where slack sN >= 0.

   tN - t(N-1) >= P is NOT a correct assumption.
   So it means we CAN'T assume that duration between adjacent events is always greater or equal than a period.

   Proof:
   a. Let tN - t(N-1) >= P
   b. T0 + N*P + sN - T0 - (N-1)*P - s(N-1) >= P
   c. P + sN - s(N-1) >= P
   d. sN - s(N-1) >= 0
   e. sN >= s(N-1) is clearly wrong (we don't know any relation of them).
   f. Statement (a) is wrong (sign is undefined for that inequality).

3. Why not to create a timer which strictly leaves the period duration between events?
   It will accumulate the error, that's why.

   T1 = T0 + P + s1
   T2 = T1 + P + s2 = T0 + 2*P + (s1 + s2)
   ...
   TN = T(N-1) + P + sN = T0 + N*P + (s1 + ... + sN)
   ...

   So such timer wouldn't be suitable for some tasks. If you really need one, reach out Blink timer owners.

Hope it resolves the mistery of duration between periodic timer events.
Feel free to re-open this bug if any questions.

Sign in to add a comment