Add logging support for base::Time* types.

base/time/time.cc

Index: base/time/time.cc
diff --git a/base/time/time.cc b/base/time/time.cc
index f7313565a3e80542599fc597642b9594a4f426db..18155e89cc3e35b34c93037fe6ea72e3312b3d4b 100644
--- a/base/time/time.cc
+++ b/base/time/time.cc
@@ -4,12 +4,15 @@
 
 #include "base/time/time.h"
 
+#include <ios>
 #include <limits>
 #include <ostream>
+#include <sstream>
 
 #include "base/float_util.h"
 #include "base/lazy_instance.h"
 #include "base/logging.h"
+#include "base/strings/stringprintf.h"
 #include "base/third_party/nspr/prtime.h"
 
 namespace base {
@@ -94,6 +97,10 @@ int64 TimeDelta::InMicroseconds() const {
   return delta_;
 }
 
+std::ostream& operator<<(std::ostream& os, TimeDelta time_delta) {
+  return os << time_delta.InSecondsF() << "s";
+}
+
 // Time -----------------------------------------------------------------------
 
 // static
@@ -230,6 +237,20 @@ bool Time::FromStringInternal(const char* time_string,
   return true;
 }
 
+std::ostream& operator<<(std::ostream& os, Time time) {
+  Time::Exploded exploded;
+  time.UTCExplode(&exploded);
+  // Use StringPrintf because iostreams formatting is painful.
+  return os << StringPrintf("%04d-%02d-%02d %02d:%02d:%02d.%03d UTC",
+                            exploded.year,
+                            exploded.month,
+                            exploded.day_of_month,
+                            exploded.hour,
+                            exploded.minute,
+                            exploded.second,
+                            exploded.millisecond);
+}
+
 // Local helper class to hold the conversion from Time to TickTime at the
 // time of the Unix epoch.
 class UnixEpochSingleton {
@@ -253,6 +274,13 @@ TimeTicks TimeTicks::UnixEpoch() {
   return leaky_unix_epoch_singleton_instance.Get().unix_epoch();
 }
 
+std::ostream& operator<<(std::ostream& os, TimeTicks time_ticks) {
+  // This function formats a TimeTicks object as if it was a Time object.

[rvargas (doing something else), 2014/10/23 02:36:38]

Shouldn't we log TimeTicks as a TimeDelta instead?

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

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:43]

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]

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]

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 :)
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]

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.

+  const Time as_time =
+      Time::UnixEpoch() + (time_ticks - TimeTicks::UnixEpoch());
+  return os << as_time;
+}
+
 // Time::Exploded -------------------------------------------------------------
 
 inline bool is_in_range(int value, int lo, int hi) {