Add logging support for base::Time* types.

Add logging support for base::Time* types.

Define operator<<(ostream&,Time) to permit Time, TimeDelta and TimeTicks
types to be used in logging assertions such as DCHECK_EQ().

BUG=425941
TEST=base_unittests

Committed: https://crrev.com/fa874fd422dd79886729d6884b032b44572c43ee
Cr-Commit-Position: refs/heads/master@{#301815}

[Adam Rice, 2014-10-22 10:29:53]

ricea@chromium.org changed reviewers:
+ mmenke@chromium.org

[mmenke, 2014-10-22 18:42:38]

LGTM

[Adam Rice, 2014-10-23 00:48:55]

ricea@chromium.org changed reviewers:
+ rvargas@chromium.org

[Adam Rice, 2014-10-23 00:48:56]

+rvargas for base/ OWNERS.

[rvargas (doing something else), 2014-10-23 02:36:39]

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc
File base/time/time.cc (right):

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc#newcod...
base/time/time.cc:278: // This function formats a TimeTicks object as if it was
a Time object.
Shouldn't we log TimeTicks as a TimeDelta instead?

[Adam Rice, 2014-10-23 03:42:02]

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc
File base/time/time.cc (right):

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc#newcod...
base/time/time.cc:278: // This function formats a TimeTicks object as if it was
a Time object.
On 2014/10/23 02:36:38, rvargas wrote:
> Shouldn't we log TimeTicks as a TimeDelta instead?

TimeDeltas are normally logged to 4 digits of precision, which is probably fine
for users of TimeDeltas, however users of TimeTicks are likely only interested
in the least significant digits.

So I formatted them as seconds since (or before) the arbitrary origin of
TimeTicks, to 6 decimal places.

[rvargas (doing something else), 2014-10-23 19:30:44]

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc
File base/time/time.cc (right):

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc#newcod...
base/time/time.cc:278: // This function formats a TimeTicks object as if it was
a Time object.
On 2014/10/23 03:42:02, Adam Rice wrote:
> On 2014/10/23 02:36:38, rvargas wrote:
> > Shouldn't we log TimeTicks as a TimeDelta instead?
> 
> TimeDeltas are normally logged to 4 digits of precision, which is probably
fine
> for users of TimeDeltas, however users of TimeTicks are likely only interested
> in the least significant digits.
> 
> So I formatted them as seconds since (or before) the arbitrary origin of
> TimeTicks, to 6 decimal places.

But TimeTicks expressed as a random date doesn't say much. It will drift
significantly from a real date and we would be adding a lot of extra significant
bits in front of the measurement.

I was having a hard time Yesterday trying to come up with real cases (not a
synthetic test) where logging the actual value of a TimeTick is useful beyond
the basic [positive|negative|zero|larger than another one].

Formatted as year/day/seconds is certainly misleading because it is not a date,
an even if I see that one value is 2 minutes older than the other one, it may be
8 hours in wall time :(

Maybe we should just give up and return the "real" value as an int.

[Adam Rice, 2014-10-24 04:05:39]

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc
File base/time/time.cc (right):

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc#newcod...
base/time/time.cc:278: // This function formats a TimeTicks object as if it was
a Time object.
On 2014/10/23 19:30:43, rvargas wrote:
> On 2014/10/23 03:42:02, Adam Rice wrote:
> > On 2014/10/23 02:36:38, rvargas wrote:
> > > Shouldn't we log TimeTicks as a TimeDelta instead?
> > 
> > TimeDeltas are normally logged to 4 digits of precision, which is probably
> fine
> > for users of TimeDeltas, however users of TimeTicks are likely only
interested
> > in the least significant digits.
> > 
> > So I formatted them as seconds since (or before) the arbitrary origin of
> > TimeTicks, to 6 decimal places.
> 
> But TimeTicks expressed as a random date doesn't say much. It will drift
> significantly from a real date and we would be adding a lot of extra
significant
> bits in front of the measurement.
> 
> I was having a hard time Yesterday trying to come up with real cases (not a
> synthetic test) where logging the actual value of a TimeTick is useful beyond
> the basic [positive|negative|zero|larger than another one].
> 
> Formatted as year/day/seconds is certainly misleading because it is not a
date,
> an even if I see that one value is 2 minutes older than the other one, it may
be
> 8 hours in wall time :(
> 
> Maybe we should just give up and return the "real" value as an int.

In the "rounding error" and "monotonic clock failed to be monotonic" cases,
seeing the actual value may be useful. In particular, it may be useful in
telling the difference between those two cases.

I don't like unit-less time values because I don't want to have to hunt through
source code to find out what a number is supposed to mean. I would be happy with
calling them "bogoseconds" or something like that.

[rvargas (doing something else), 2014-10-24 23:24:18]

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc
File base/time/time.cc (right):

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc#newcod...
base/time/time.cc:278: // This function formats a TimeTicks object as if it was
a Time object.
On 2014/10/24 04:05:39, Adam Rice wrote:
> On 2014/10/23 19:30:43, rvargas wrote:
> > On 2014/10/23 03:42:02, Adam Rice wrote:
> > > On 2014/10/23 02:36:38, rvargas wrote:
> > > > Shouldn't we log TimeTicks as a TimeDelta instead?
> > > 
> > > TimeDeltas are normally logged to 4 digits of precision, which is probably
> > fine
> > > for users of TimeDeltas, however users of TimeTicks are likely only
> interested
> > > in the least significant digits.
> > > 
> > > So I formatted them as seconds since (or before) the arbitrary origin of
> > > TimeTicks, to 6 decimal places.
> > 
> > But TimeTicks expressed as a random date doesn't say much. It will drift
> > significantly from a real date and we would be adding a lot of extra
> significant
> > bits in front of the measurement.
> > 
> > I was having a hard time Yesterday trying to come up with real cases (not a
> > synthetic test) where logging the actual value of a TimeTick is useful
beyond
> > the basic [positive|negative|zero|larger than another one].
> > 
> > Formatted as year/day/seconds is certainly misleading because it is not a
> date,
> > an even if I see that one value is 2 minutes older than the other one, it
may
> be
> > 8 hours in wall time :(
> > 
> > Maybe we should just give up and return the "real" value as an int.
> 
> In the "rounding error" and "monotonic clock failed to be monotonic" cases,
> seeing the actual value may be useful. In particular, it may be useful in
> telling the difference between those two cases.

The second one sounds like a TimeTicks unit test not something that should be a
concern of general tests... the first one, I guess we are actually saying the
same thing, that the most useful test output is actually to use the raw value,
without approximations or translations :)

> 
> I don't like unit-less time values because I don't want to have to hunt
through
> source code to find out what a number is supposed to mean. I would be happy
with
> calling them "bogoseconds" or something like that.

oh, I don't mind what units we display, bogo-microseconds is as good as anything
else (isn't that what we use?). But surely tests (outside of time_unittests)
pretending that TimeTicks numbers have a concrete meaning are at the very least
misleading.

[Adam Rice, 2014-10-28 05:43:12]

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc
File base/time/time.cc (right):

https://codereview.chromium.org/669083002/diff/20001/base/time/time.cc#newcod...
base/time/time.cc:278: // This function formats a TimeTicks object as if it was
a Time object.
On 2014/10/24 23:24:18, rvargas (out until nov 4) wrote:
> On 2014/10/24 04:05:39, Adam Rice wrote:
> > On 2014/10/23 19:30:43, rvargas wrote:
> > > On 2014/10/23 03:42:02, Adam Rice wrote:
> > > > On 2014/10/23 02:36:38, rvargas wrote:
> > > > > Shouldn't we log TimeTicks as a TimeDelta instead?
> > > > 
> > > > TimeDeltas are normally logged to 4 digits of precision, which is
probably
> > > fine
> > > > for users of TimeDeltas, however users of TimeTicks are likely only
> > interested
> > > > in the least significant digits.
> > > > 
> > > > So I formatted them as seconds since (or before) the arbitrary origin of
> > > > TimeTicks, to 6 decimal places.
> > > 
> > > But TimeTicks expressed as a random date doesn't say much. It will drift
> > > significantly from a real date and we would be adding a lot of extra
> > significant
> > > bits in front of the measurement.
> > > 
> > > I was having a hard time Yesterday trying to come up with real cases (not
a
> > > synthetic test) where logging the actual value of a TimeTick is useful
> beyond
> > > the basic [positive|negative|zero|larger than another one].
> > > 
> > > Formatted as year/day/seconds is certainly misleading because it is not a
> > date,
> > > an even if I see that one value is 2 minutes older than the other one, it
> may
> > be
> > > 8 hours in wall time :(
> > > 
> > > Maybe we should just give up and return the "real" value as an int.
> > 
> > In the "rounding error" and "monotonic clock failed to be monotonic" cases,
> > seeing the actual value may be useful. In particular, it may be useful in
> > telling the difference between those two cases.
> 
> The second one sounds like a TimeTicks unit test not something that should be
a
> concern of general tests... the first one, I guess we are actually saying the
> same thing, that the most useful test output is actually to use the raw value,
> without approximations or translations :)
> 
> > 
> > I don't like unit-less time values because I don't want to have to hunt
> through
> > source code to find out what a number is supposed to mean. I would be happy
> with
> > calling them "bogoseconds" or something like that.
> 
> oh, I don't mind what units we display, bogo-microseconds is as good as
anything
> else (isn't that what we use?). But surely tests (outside of time_unittests)
> pretending that TimeTicks numbers have a concrete meaning are at the very
least
> misleading.

Okay, I changed it to "bogo-microseconds".

I see the purpose of these as output operators as being 99% to make DCHECK_OP()
calls work, with maybe 1% for adding in short-term LOG() statements to track
down tricky timing-related bugs.

Tests not directly concerned with time which use time-related functionality are
suspicious in my opinion, although some seem harmless enough (eg.
https://code.google.com/p/chromium/codesearch#chromium/src/net/base/net_log_u...
) and will get slightly more intelligable logging if and when they fail.

[rvargas (doing something else), 2014-10-29 09:03:52]

lgtm

[Adam Rice, 2014-10-29 10:23:58]

The CQ bit was checked by ricea@chromium.org

[commit-bot: I haz the power, 2014-10-29 10:24:50]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/669083002/60001

[commit-bot: I haz the power, 2014-10-29 11:35:54]

Committed patchset #4 (id:60001)

[commit-bot: I haz the power, 2014-10-29 11:36:42]

Patchset 4 (id:??) landed as
https://crrev.com/fa874fd422dd79886729d6884b032b44572c43ee
Cr-Commit-Position: refs/heads/master@{#301815}