base: Print sub-second resolution timestamps

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

Committed: https://crrev.com/543a3be1be43bf23fbca2140ad90d18ee7ec6655
Cr-Commit-Position: refs/heads/master@{#435254}

[djkurtz, 2016-11-23 11:03:24]

Description was changed from

==========
base: Print microsecond 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 clock_gettime to fetch a nanosecond resolution
timestamps, and use print out to microsecond resolution.

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
==========

to

==========
base: Print microsecond 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 clock_gettime to fetch a nanosecond resolution
timestamps, and use print out to microsecond resolution.

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
==========

[djkurtz, 2016-11-23 11:03:24]

djkurtz@google.com changed reviewers:
+ dianders@google.com, drinkcat@google.com, jcliang@chromium.org,
mcolbert@chromium.org, vapier@chromium.org

[Mark Mentovai, 2016-11-23 14:33:06]

mark@chromium.org changed reviewers:
+ mark@chromium.org

[Mark Mentovai, 2016-11-23 14:33:06]

https://codereview.chromium.org/2528613002/diff/1/base/logging.cc
File base/logging.cc (right):

https://codereview.chromium.org/2528613002/diff/1/base/logging.cc#newcode768
base/logging.cc:768: struct timespec tp = {0};
No need to initialize (same goes for local_time a few lines below).

https://codereview.chromium.org/2528613002/diff/1/base/logging.cc#newcode769
base/logging.cc:769: clock_gettime(CLOCK_REALTIME, &tp);
Not available on WIndows! Take a look at how we solved this in mini_chromium:
https://chromium.googlesource.com/chromium/mini_chromium/+/9f129335dbe57ae9a3...

[Daniel Kurtz, 2016-11-23 16:31:03]

https://codereview.chromium.org/2528613002/diff/1/base/logging.cc
File base/logging.cc (right):

https://codereview.chromium.org/2528613002/diff/1/base/logging.cc#newcode769
base/logging.cc:769: clock_gettime(CLOCK_REALTIME, &tp);
On 2016/11/23 14:33:06, Mark Mentovai wrote:
> Not available on WIndows! Take a look at how we solved this in mini_chromium:
>
https://chromium.googlesource.com/chromium/mini_chromium/+/9f129335dbe57ae9a3...

Any idea why mini_chromium already uses usec timestamps, but chromium does not?

I looked in the git log, and it has been that way since Initial release of
mini_chromium.

[Mark Mentovai, 2016-11-23 16:39:24]

Daniel Kurtz wrote:
> https://codereview.chromium.org/2528613002/diff/1/base/logging.cc
> File base/logging.cc (right):
> 
> https://codereview.chromium.org/2528613002/diff/1/base/logging.cc#newcode769
> base/logging.cc:769: clock_gettime(CLOCK_REALTIME, &tp);
> On 2016/11/23 14:33:06, Mark Mentovai wrote:
> > Not available on WIndows! Take a look at how we solved this in
mini_chromium:
> >
>
https://chromium.googlesource.com/chromium/mini_chromium/+/9f129335dbe57ae9a3...
> 
> Any idea why mini_chromium already uses usec timestamps, but chromium does
not?

 No reason different than what’s motivating your change. I found sub-second
precision useful.

[Daniel Kurtz, 2016-11-24 03:09:38]

The CQ bit was checked by djkurtz@chromium.org to run a CQ dry run

[Daniel Kurtz, 2016-11-24 03:09:53]

https://codereview.chromium.org/2528613002/diff/1/base/logging.cc
File base/logging.cc (right):

https://codereview.chromium.org/2528613002/diff/1/base/logging.cc#newcode769
base/logging.cc:769: clock_gettime(CLOCK_REALTIME, &tp);
On 2016/11/23 14:33:06, Mark Mentovai wrote:
> Not available on WIndows! Take a look at how we solved this in mini_chromium:
>
https://chromium.googlesource.com/chromium/mini_chromium/+/9f129335dbe57ae9a3...

Done.

[commit-bot: I haz the power, 2016-11-24 03:10:20]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-11-24 03:44:58]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-11-24 03:44:59]

Dry run: Try jobs failed on following builders:
  win_chromium_compile_dbg_ng on master.tryserver.chromium.win (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_comp...)

[Daniel Kurtz, 2016-11-24 09:32:55]

The CQ bit was checked by djkurtz@chromium.org to run a CQ dry run

[commit-bot: I haz the power, 2016-11-24 09:33:22]

Dry run: CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-11-24 11:34:12]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-11-24 11:34:13]

Dry run: Try jobs failed on following builders:
  blimp_linux_dbg on master.tryserver.chromium.linux (JOB_TIMED_OUT, no build
URL)
  cast_shell_linux on master.tryserver.chromium.linux (JOB_TIMED_OUT, no build
URL)
  chromeos_daisy_chromium_compile_only_ng on master.tryserver.chromium.linux
(JOB_TIMED_OUT, no build URL)
  chromeos_x86-generic_chromium_compile_only_ng on
master.tryserver.chromium.linux (JOB_TIMED_OUT, no build URL)
  chromium_presubmit on master.tryserver.chromium.linux (JOB_TIMED_OUT, no build
URL)
  linux_chromium_asan_rel_ng on master.tryserver.chromium.linux (JOB_TIMED_OUT,
no build URL)
  linux_chromium_chromeos_compile_dbg_ng on master.tryserver.chromium.linux
(JOB_TIMED_OUT, no build URL)
  linux_chromium_chromeos_ozone_rel_ng on master.tryserver.chromium.linux
(JOB_TIMED_OUT, no build URL)
  linux_chromium_chromeos_rel_ng on master.tryserver.chromium.linux
(JOB_TIMED_OUT, no build URL)
  linux_chromium_clobber_rel_ng on master.tryserver.chromium.linux
(JOB_TIMED_OUT, no build URL)
  linux_chromium_compile_dbg_ng on master.tryserver.chromium.linux
(JOB_TIMED_OUT, no build URL)
  linux_chromium_rel_ng on master.tryserver.chromium.linux (JOB_TIMED_OUT, no
build URL)

[Daniel Kurtz, 2016-11-29 03:32:21]

On 2016/11/24 03:09:53, Daniel Kurtz wrote:
> https://codereview.chromium.org/2528613002/diff/1/base/logging.cc
> File base/logging.cc (right):
> 
> https://codereview.chromium.org/2528613002/diff/1/base/logging.cc#newcode769
> base/logging.cc:769: clock_gettime(CLOCK_REALTIME, &tp);
> On 2016/11/23 14:33:06, Mark Mentovai wrote:
> > Not available on WIndows! Take a look at how we solved this in
mini_chromium:
> >
>
https://chromium.googlesource.com/chromium/mini_chromium/+/9f129335dbe57ae9a3...
> 
> Done.

Mark, does this look good now?

[Mark Mentovai, 2016-11-29 18:53:36]

LGTM

This only gives milliseconds on Windows, not microseconds. Revise the CL
description to say so (or just say “fractional seconds” or “sub-second
resolution.”)

The resolution on Windows may actually be as coarse as 15ms here.

[Daniel Kurtz, 2016-11-30 04:19:40]

Description was changed from

==========
base: Print microsecond 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 clock_gettime to fetch a nanosecond resolution
timestamps, and use print out to microsecond resolution.

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
==========

to

==========
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
==========

[Daniel Kurtz, 2016-11-30 04:20:20]

On 2016/11/29 18:53:36, Mark Mentovai wrote:
> LGTM
> 
> This only gives milliseconds on Windows, not microseconds. Revise the CL
> description to say so (or just say “fractional seconds” or “sub-second
> resolution.”)
> 
> The resolution on Windows may actually be as coarse as 15ms here.

I actually did change this on my local branch.
Unfortunately, git cl upload does not update the CL description.
Makes me miss gerrit...

[Daniel Kurtz, 2016-11-30 04:20:24]

The CQ bit was checked by djkurtz@chromium.org

[commit-bot: I haz the power, 2016-11-30 04:20:53]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-11-30 06:22:03]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-11-30 06:22:04]

Try jobs failed on following builders:
  blimp_linux_dbg on master.tryserver.chromium.linux (JOB_TIMED_OUT, no build
URL)
  cast_shell_linux on master.tryserver.chromium.linux (JOB_TIMED_OUT, no build
URL)
  chromeos_amd64-generic_chromium_compile_only_ng on
master.tryserver.chromium.linux (JOB_TIMED_OUT, no build URL)
  chromeos_daisy_chromium_compile_only_ng on master.tryserver.chromium.linux
(JOB_TIMED_OUT, no build URL)
  chromium_presubmit on master.tryserver.chromium.linux (JOB_TIMED_OUT, no build
URL)
  linux_chromium_asan_rel_ng on master.tryserver.chromium.linux (JOB_TIMED_OUT,
no build URL)
  linux_chromium_chromeos_rel_ng on master.tryserver.chromium.linux
(JOB_TIMED_OUT, no build URL)
  linux_chromium_compile_dbg_ng on master.tryserver.chromium.linux
(JOB_TIMED_OUT, no build URL)
  linux_chromium_rel_ng on master.tryserver.chromium.linux (JOB_TIMED_OUT, no
build URL)

[djkurtz, 2016-11-30 06:27:42]

The CQ bit was checked by djkurtz@google.com

[commit-bot: I haz the power, 2016-11-30 06:28:25]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-11-30 07:51:46]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2016-11-30 07:51:47]

Try jobs failed on following builders:
  chromium_presubmit on master.tryserver.chromium.linux (JOB_FAILED,
http://build.chromium.org/p/tryserver.chromium.linux/builders/chromium_presub...)

[Daniel Kurtz, 2016-11-30 08:15:09]

On 2016/11/30 07:51:47, commit-bot: I haz the power wrote:
> Try jobs failed on following builders:
>   chromium_presubmit on master.tryserver.chromium.linux (JOB_FAILED,
>
http://build.chromium.org/p/tryserver.chromium.linux/builders/chromium_presub...)

The patch is choking on the presubmit:
"The base directory requires source formatting. Please run git cl format base"

Running git cl format base makes the code much less readable, by squashing all
of the stream << parameters onto fewer lines:
-    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
-            << '.'
-            << std::setw(6) << tv.tv_usec
-            << ':';
+    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 << '.' << std::setw(6)
+            << tv.tv_usec << ':';


How can we bypass the presubmit for this patch?

[Mark Mentovai, 2016-11-30 11:35:21]

On 2016/11/30 04:20:20, Daniel Kurtz wrote:
> On 2016/11/29 18:53:36, Mark Mentovai wrote:
> > LGTM
> > 
> > This only gives milliseconds on Windows, not microseconds. Revise the CL
> > description to say so (or just say “fractional seconds” or “sub-second
> > resolution.”)
> > 
> > The resolution on Windows may actually be as coarse as 15ms here.
> 
> I actually did change this on my local branch.
> Unfortunately, git cl upload does not update the CL description.
> Makes me miss gerrit...

“git cl description”

or edit it on codereview.chromium.org

[Mark Mentovai, 2016-11-30 11:36:38]

On 2016/11/30 08:15:09, Daniel Kurtz wrote:
> On 2016/11/30 07:51:47, commit-bot: I haz the power wrote:
> > Try jobs failed on following builders:
> >   chromium_presubmit on master.tryserver.chromium.linux (JOB_FAILED,
> >
>
http://build.chromium.org/p/tryserver.chromium.linux/builders/chromium_presub...)
> 
> The patch is choking on the presubmit:
> "The base directory requires source formatting. Please run git cl format base"
> 
> Running git cl format base makes the code much less readable, by squashing all
> of the stream << parameters onto fewer lines:
> -    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
> -            << '.'
> -            << std::setw(6) << tv.tv_usec
> -            << ':';
> +    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 << '.' << std::setw(6)
> +            << tv.tv_usec << ':';
> 
> 
> How can we bypass the presubmit for this patch?

Append NOPRESUBMIT=true to the description.

[Daniel Kurtz, 2016-11-30 14:16:28]

Description was changed from

==========
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
==========

to

==========
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
==========

[Daniel Kurtz, 2016-11-30 14:16:37]

The CQ bit was checked by djkurtz@chromium.org

[commit-bot: I haz the power, 2016-11-30 14:16:54]

CQ is trying da patch. Follow status at
 
https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...

[commit-bot: I haz the power, 2016-11-30 14:17:39]

CQ is committing da patch.

Bot data: {"patchset_id": 40001, "attempt_start_ts": 1480515397385090,
"parent_rev": "17912d131e2b32b6e1ad706820369e9500aaeb4c", "commit_rev":
"4fd6169c14b91c4fe7400985ba9a2790121f1291"}

[commit-bot: I haz the power, 2016-11-30 14:18:05]

Description was changed from

==========
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
==========

to

==========
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
==========

[commit-bot: I haz the power, 2016-11-30 14:18:07]

Committed patchset #3 (id:40001)

[commit-bot: I haz the power, 2016-11-30 14:21:14]

Description was changed from

==========
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
==========

to

==========
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

Committed: https://crrev.com/543a3be1be43bf23fbca2140ad90d18ee7ec6655
Cr-Commit-Position: refs/heads/master@{#435254}
==========

[commit-bot: I haz the power, 2016-11-30 14:21:15]

Patchset 3 (id:??) landed as
https://crrev.com/543a3be1be43bf23fbca2140ad90d18ee7ec6655
Cr-Commit-Position: refs/heads/master@{#435254}