Investigate timer firing before the deadline |
||
Issue descriptionThere are reports of timer firing before the specified deadline: https://chromium-review.googlesource.com/c/chromium/src/+/938667
,
Mar 22 2018
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().
,
Mar 22 2018
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
,
Mar 26 2018
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
,
Mar 27 2018
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 |
||
Comment 1 by kraynov@chromium.org
, Mar 22 2018Status: Assigned (was: Available)