Incorrect timestamps of console log messages produced with Console API
Reported by
woxxom@gmail.com,
Aug 22 2017
|
|||||||||||||||
Issue description
UserAgent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.101 Safari/537.36
Steps to reproduce the problem:
1. open devtools, enable timestamps in its options for console
2. run the following code
var d = new Date(); d = d.toLocaleTimeString('fr') + '.' + ('00' + d.getMilliseconds()).slice(-3); console.warn(d); d;
3. repeat step#2 a few times with random pauses between repetitions like no pause, .5 second, 1 sec, 2 sec, 5 sec
What is the expected behavior?
* All timestamps should be monotonously increasing
* All timestamps on the left should be almost equal to the current system time displayed on the right within a few milliseconds
What went wrong?
* console.warn timestamps (those with yellow triangle) are incorrect:
* non-monotonous (smaller than the previous) timestamp when the command was executed without pause
* different from the next timestamp which is shown by devtools directly (without Console API)
* up to the 2 seconds difference in modern builds including canary
* up to the 1 hour difference in old builds from the bisect info below
Did this work before? Yes 38.0.2107.0
Chrome version: 60.0.3112.101 Channel: n/a
OS Version: 6.1 (Windows 7, Windows Server 2008 R2)
Flash Version: Shockwave Flash 26.0 r0
* Broken by default in 38.0.2111.0 - timestamp difference is approximately 1 hour
Bisect info: 286925 (good) - 286930 (bad)
https://chromium.googlesource.com/chromium/src/+log/c618c920..1d76598c?pretty=fuller
Suspecting r286928 "Use HighResNow whenever possible on Windows"
* Alleviated in 39.0.2151.0 - timestamp difference is within 2 seconds, usually 0.5 - 1 second
Bisect info: 293530 (bad) - 293790 (good)
https://chromium.googlesource.com/chromium/src/+log/dcad7f48..8c59383c?pretty=fuller
The CL range is too big for me to suspect with any certainty.
* Broken since at least 35.0.1913.0 - the first build with devtools timestamps in console
Reproducing requires forcing highres timers via command line:
chrome --enable-high-resolution-time
* Still present in Canary - timestamp difference is within 2 seconds, usually 0.5 - 1 second
,
Aug 23 2017
Able to reproduce this issue on Mac 10.12.6, Win-10 and Ubuntu 14.04 using chrome reported version #60.0.3112.101 and latest canary #62.0.3193.0. This is a non-regression issue as it is observed from M45 old builds. Hence, marking it as untriaged to get more inputs from dev team. Thanks...!!
,
Aug 28 2017
,
Sep 4 2017
,
Sep 21 2017
Thanks for amazing report! Do you use remote debugging our it's reproducible for regular docked DevTools? We calculate timestamp for evaluated in console command internally in DevTools using Date.now(), then we sent message to backend and call Date.now() in page context there. I'll investigate a little more to reproduce this issue and final the root of it.
,
Sep 21 2017
Regular built-in page devtools via F12 key.
,
Sep 21 2017
I believe that I fixed it during preparation work for top level async support in console. Could you confirm that issue is still reproducible in latest Canary?
,
Sep 21 2017
My Windows 7 box got updated recently, which apparently fixed the underlying HighRes timer bug, and now I can't reproduce the bug neither in r293790 nor in Canary. So it might be prudent to ask the test team to re-verify as they were able to confirm the bug in the first place.
,
Sep 21 2017
Looking at the screenshot above, I see the bug has been transferred from the timestamps produced via Console API (yellow lines are correct now) to timestamps produced by devtools itself (lines after the yellow ones are incorrect now). Each yellow line uses "console.warn(d)", the next line uses just "d".
,
Oct 16 2017
,
Sep 27
1. DevTools process captures current time (timeA) and print message with command and send this command to be executed on another process. 2. Another process generates two events: a) console.warn event and capture time there (timeB) b) command execution finished, this event gets time on DevTools process side (timeC). If we assume that both processes have synced time. Then: timeB = timeA + (time to send command from DevTools process to backend process). timeC = timeB + (time to send response from backend process to DevTools process). Based on assumption that communication takes > 0 ms, times should be ordered in console. If it is not true it means that DevTools process and backend process have slightly different source of time and most likely it is related to some OS specific stuff. At the same time I can not reproduce it on Linux and on Mac, unfortunately I do not have Windows machine. So I am going to close this one as WontFix, thanks for great report and feel free to reopen this issue or file another one with your use case, maybe we can try find some other solution.
,
Sep 27
FWIW the difference is under 5ms in the current Chrome, which may be considered GOOD, so I did a reverse bisect: https://chromium.googlesource.com/chromium/src/+log/7f473239..4bef8ee3?pretty=fuller Suspecting V8 update r499266, namely 11ba497cd887b6cdedba403d540094433082b33b "Delegate getting current wall-clock time to the Platform interface" Landed in 63.0.3203.0 Starting with Chrome 63 the timestamp gap has been gradually decreasing down to the current <=5ms so I guess there might have been other related changes. |
|||||||||||||||
►
Sign in to add a comment |
|||||||||||||||
Comment 1 by manoranj...@chromium.org
, Aug 22 2017