Ensure TimeOffset is applied to timestamps of traces

Previously TraceLog::UpdateTraceEventDuration() doesn't consider
time_offset_. Added OffsetNow() and OffsetTimestamp() to avoid
TimeTicks::NowFromSystemTraceTime() in most part of TraceLog.

TEST=TraceEventTestFixture.TimeOffset
BUG=none

Review URL: https://codereview.chromium.org/52973006

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@232549 0039d316-1c4b-4281-b951-d872f2087c98

3 files changed, 53 insertions, 15 deletions

diff --git a/base/debug/trace_event_impl.cc b/base/debug/trace_event_impl.cc
index f76d9de..85f4ea4 100644
--- a/base/debug/trace_event_impl.cc
+++ b/base/debug/trace_event_impl.cc
@@ -600,6 +600,11 @@ void TraceEvent::Reset() {
     convertable_values_[i] = NULL;
 }
 
+void TraceEvent::UpdateDuration(const TimeTicks& now) {
+  DCHECK(duration_.ToInternalValue() == -1);
+  duration_ = now - timestamp_;
+}
+
 // static
 void TraceEvent::AppendValueAsJSON(unsigned char type,
                                    TraceEvent::TraceValue value,
@@ -1062,8 +1067,7 @@ void TraceLog::ThreadLocalEventBuffer::ReportOverhead(
   CheckThisIsCurrentBuffer();
 
   event_count_++;
-  TimeTicks now =
-      TimeTicks::NowFromSystemTraceTime() - trace_log_->time_offset_;
+  TimeTicks now = trace_log_->OffsetNow();
   TimeDelta overhead = now - event_timestamp;
   if (overhead.InMicroseconds() >= kOverheadReportThresholdInMicroseconds) {
     TraceEvent* trace_event = AddTraceEvent(notifier, NULL);
@@ -1074,7 +1078,7 @@ void TraceLog::ThreadLocalEventBuffer::ReportOverhead(
           TRACE_EVENT_PHASE_COMPLETE,
           &g_category_group_enabled[g_category_trace_event_overhead],
           "overhead", 0, 0, NULL, NULL, NULL, NULL, 0);
-      trace_event->UpdateDuration();
+      trace_event->UpdateDuration(now);
     }
   }
   overhead_ += overhead;
@@ -1728,7 +1732,7 @@ TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
   if (flags & TRACE_EVENT_FLAG_MANGLE_ID)
     id ^= process_id_hash_;
 
-  TimeTicks now = timestamp - time_offset_;
+  TimeTicks now = OffsetTimestamp(timestamp);
   TimeTicks thread_now = ThreadNow();
 
   NotificationHelper notifier(this);
@@ -1919,10 +1923,11 @@ void TraceLog::AddTraceEventEtw(char phase,
 void TraceLog::UpdateTraceEventDuration(TraceEventHandle handle) {
   OptionalAutoLock lock(lock_);
 
+  TimeTicks now = OffsetNow();
   TraceEvent* trace_event = GetEventByHandleInternal(handle, &lock);
   if (trace_event) {
     DCHECK(trace_event->phase() == TRACE_EVENT_PHASE_COMPLETE);
-    trace_event->UpdateDuration();
+    trace_event->UpdateDuration(now);
 #if defined(OS_ANDROID)
     trace_event->SendToATrace();
 #endif
@@ -1930,9 +1935,7 @@ void TraceLog::UpdateTraceEventDuration(TraceEventHandle handle) {
 
   if (trace_options() & ECHO_TO_CONSOLE) {
     lock.EnsureAcquired();
-    OutputEventToConsoleWhileLocked(TRACE_EVENT_PHASE_END,
-                                    TimeTicks::NowFromSystemTraceTime(),
-                                    trace_event);
+    OutputEventToConsoleWhileLocked(TRACE_EVENT_PHASE_END, now, trace_event);
   }
 
   EventCallback event_callback = reinterpret_cast<EventCallback>(
@@ -1943,11 +1946,9 @@ void TraceLog::UpdateTraceEventDuration(TraceEventHandle handle) {
     TraceEvent event_copy;
     event_copy.CopyFrom(*trace_event);
     lock.EnsureReleased();
-    DCHECK(event_copy.duration().InMicroseconds() >= 0);
     // TODO(wangxianzhu): Should send TRACE_EVENT_PHASE_COMPLETE directly to
     // clients if it is beneficial and feasible.
-    event_callback(event_copy.timestamp() + event_copy.duration(),
-                   TRACE_EVENT_PHASE_END,
+    event_callback(now, TRACE_EVENT_PHASE_END,
                    event_copy.category_group_enabled(),
                    event_copy.name(), event_copy.id(),
                    0, NULL, NULL, NULL, event_copy.flags());
diff --git a/base/debug/trace_event_impl.h b/base/debug/trace_event_impl.h
index 6af2877..196d28e 100644
--- a/base/debug/trace_event_impl.h
+++ b/base/debug/trace_event_impl.h
@@ -122,10 +122,7 @@ class BASE_EXPORT TraceEvent {
 
   void Reset();
 
-  void UpdateDuration() {
-    DCHECK(duration_.ToInternalValue() == -1);
-    duration_ = TimeTicks::NowFromSystemTraceTime() - timestamp_;
-  }
+  void UpdateDuration(const TimeTicks& now);
 
   // Serialize event data to JSON
   static void AppendEventsAsJSON(const std::vector<TraceEvent>& events,
@@ -666,6 +663,13 @@ class BASE_EXPORT TraceLog {
     return static_cast<int>(subtle::NoBarrier_AtomicIncrement(&generation_, 1));
   }
 
+  TimeTicks OffsetNow() const {
+    return OffsetTimestamp(TimeTicks::NowFromSystemTraceTime());
+  }
+  TimeTicks OffsetTimestamp(const TimeTicks& timestamp) const {
+    return timestamp - time_offset_;
+  }
+
   // This lock protects TraceLog member accesses from arbitrary threads.
   Lock lock_;
   int locked_line_;
diff --git a/base/debug/trace_event_unittest.cc b/base/debug/trace_event_unittest.cc
index a6a86c7..4d44181 100644
--- a/base/debug/trace_event_unittest.cc
+++ b/base/debug/trace_event_unittest.cc
@@ -2421,5 +2421,38 @@ TEST_F(TraceEventTestFixture, EchoToConsole) {
   g_log_buffer = NULL;
 }
 
+TEST_F(TraceEventTestFixture, TimeOffset) {
+  BeginTrace();
+  // Let TraceLog timer start from 0.
+  TimeDelta time_offset = TimeTicks::NowFromSystemTraceTime() - TimeTicks();
+  TraceLog::GetInstance()->SetTimeOffset(time_offset);
+
+  {
+    TRACE_EVENT0("all", "duration1");
+    TRACE_EVENT0("all", "duration2");
+  }
+  TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(
+      "all", "with_timestamp", 0, 0,
+      TimeTicks::NowFromSystemTraceTime().ToInternalValue());
+  TRACE_EVENT_END_WITH_ID_TID_AND_TIMESTAMP0(
+      "all", "with_timestamp", 0, 0,
+      TimeTicks::NowFromSystemTraceTime().ToInternalValue());
+
+  EndTraceAndFlush();
+
+  double end_time = static_cast<double>(
+      (TimeTicks::NowFromSystemTraceTime() - time_offset).ToInternalValue());
+  double last_timestamp = 0;
+  for (size_t i = 0; i < trace_parsed_.GetSize(); ++i) {
+    const DictionaryValue* item;
+    EXPECT_TRUE(trace_parsed_.GetDictionary(i, &item));
+    double timestamp;
+    EXPECT_TRUE(item->GetDouble("ts", &timestamp));
+    EXPECT_GE(timestamp, last_timestamp);
+    EXPECT_LE(timestamp, end_time);
+    last_timestamp = timestamp;
+  }
+}
+
 }  // namespace debug
 }  // namespace base