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

Issue 638472 link

Starred by 2 users

Issue metadata

Status: Verified
Owner:
Last visit > 30 days ago
Closed: Dec 2016
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

Use sub-second timestamps for powerd, chrome, ui, etc logs

Project Member Reported by djkurtz@chromium.org, Aug 17 2016

Issue description

The Android Debug Tool Extension [0] is very powerful tool for viewing logs in feedback reports.

[0] https://chrome.google.com/webstore/a/google.com/detail/android-bug-tool-extensio/mbbaofdfoekifkfpgehgffcpagbbjkmj

This tool has a "Combined" mode that interleaves timestamped log entries from multiple log files.  This is a great way to visualize what is happening across the entire system at a glance.

However, one big draw-back at present, is that, since chrome/ui/powerd logs only have whole-second precision, these logs are not interleaved accurately with respect to kernel (syslog), netlog, and other logs that have sub-second timestamps.
 

Comment 1 by vapier@google.com, Aug 17 2016

I wonder if it's just rsyslog that needs updating with its output format. I think CrOS daemons use libbase for logging which in turn uses standard syslog(). we don't set or pass timestamps directly anywhere.
Cc: danakj@chromium.org thestig@chromium.org dcheng@chromium.org thakis@chromium.org mark@chromium.org
Labels: -Pri-3 Pri-2
Owner: djkurtz@chromium.org
Status: Started (was: Available)
From base/logging.c:

// writes the common header info to the stream
void LogMessage::Init(const char* file, int line) {
  ...
  if (g_log_timestamp) {
    time_t t = time(nullptr);
    struct tm local_time = {0};
#ifdef _MSC_VER
    localtime_s(&local_time, &t);
#else
    localtime_r(&t, &local_time);
#endif
    struct tm* tm_time = &local_time;
    stream_ << std::setfill('0')
            << std::setw(2) << 1 + tm_time->tm_mon
            << std::setw(2) << tm_time->tm_mday
            << '/'
            << std::setw(2) << tm_time->tm_hour
            << std::setw(2) << tm_time->tm_min
            << std::setw(2) << tm_time->tm_sec
            << ':';
  }

So, time returns time in seconds, and that's all Chrome uses.
This looks quite easy to fix, by using clock_gettime() instead.
CL to use clock_gettime(): https://codereview.chromium.org/2528613002/
Project Member

Comment 4 by bugdroid1@chromium.org, Nov 30 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/543a3be1be43bf23fbca2140ad90d18ee7ec6655

commit 543a3be1be43bf23fbca2140ad90d18ee7ec6655
Author: djkurtz <djkurtz@chromium.org>
Date: Wed Nov 30 14:17:34 2016

base: Print sub-second resolution timestamps

Currently Chrome logs time in full seconds.
On Chrome OS, all other loggers use at least microsecond resolution.
This makes it hard to compare Chrome timestamps to other system events.

Instead, have Chrome use gettimeofday() on POSIX to fetch microsecond resolution timestamps, and GetLocalTime() on Windows to fetch millisecond resolution timestamps

Note: the Windows implementation is adapted from mini_chromium:
    https://chromium.googlesource.com/chromium/mini_chromium/+/9f129335dbe57ae9a3...

BUG= chromium:638472 
TEST=tail -F /var/log/chrome/chrome shows microsecond timestamps, like:
 [1:1:1123/185804.213359:VERBOSE1:zygote_main_linux.cc(599)] ZygoteMain: initializing 2 fork delegates

R=dcheng
NOPRESUBMIT=true

Review-Url: https://codereview.chromium.org/2528613002
Cr-Commit-Position: refs/heads/master@{#435254}

[modify] https://crrev.com/543a3be1be43bf23fbca2140ad90d18ee7ec6655/base/logging.cc

Labels: Merge-Request-56
Labels: Merge-Approved-56

Comment 7 by dimu@chromium.org, Dec 1 2016

Labels: -Merge-Request-56 Hotlist-Merge-Approved
Your change meets the bar and is auto-approved for M56 (branch: 2924)
Project Member

Comment 8 by bugdroid1@chromium.org, Dec 3 2016

Labels: -merge-approved-56 merge-merged-2924
The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/689d0f35b7686e94fa928da10126c15ef881cb4b

commit 689d0f35b7686e94fa928da10126c15ef881cb4b
Author: djkurtz <djkurtz@chromium.org>
Date: Sat Dec 03 02:15:42 2016

base: Print sub-second resolution timestamps

Currently Chrome logs time in full seconds.
On Chrome OS, all other loggers use at least microsecond resolution.
This makes it hard to compare Chrome timestamps to other system events.

Instead, have Chrome use gettimeofday() on POSIX to fetch microsecond resolution timestamps, and GetLocalTime() on Windows to fetch millisecond resolution timestamps

Note: the Windows implementation is adapted from mini_chromium:
    https://chromium.googlesource.com/chromium/mini_chromium/+/9f129335dbe57ae9a3...

BUG= chromium:638472 
TEST=tail -F /var/log/chrome/chrome shows microsecond timestamps, like:
 [1:1:1123/185804.213359:VERBOSE1:zygote_main_linux.cc(599)] ZygoteMain: initializing 2 fork delegates

R=dcheng
NOPRESUBMIT=true
NOTRY=true
TBR=mark

Review-Url: https://codereview.chromium.org/2528613002
Cr-Commit-Position: refs/heads/master@{#435254}
(cherry picked from commit 543a3be1be43bf23fbca2140ad90d18ee7ec6655)

Review-Url: https://codereview.chromium.org/2536203005
Cr-Commit-Position: refs/branch-heads/2924@{#314}
Cr-Branched-From: 3a87aecc31cd1ffe751dd72c04e5a96a1fc8108a-refs/heads/master@{#433059}

[modify] https://crrev.com/689d0f35b7686e94fa928da10126c15ef881cb4b/base/logging.cc

Status: Fixed (was: Started)

Comment 10 by son...@google.com, Feb 6 2017

Status: Verified (was: Fixed)
Verified on build 9202.17.0

Sign in to add a comment