Use real time instead of event time to compute trace event overhead

base/trace_event/trace_event_impl.cc

Index: base/trace_event/trace_event_impl.cc
diff --git a/base/trace_event/trace_event_impl.cc b/base/trace_event/trace_event_impl.cc
index 95cf06d5a576c061eda861c74f923de6c50b9eef..82535edb9d330e8f8435bf4554d49af4ab4a2eaa 100644
--- a/base/trace_event/trace_event_impl.cc
+++ b/base/trace_event/trace_event_impl.cc
@@ -1912,7 +1912,8 @@ TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
   if (flags & TRACE_EVENT_FLAG_MANGLE_ID)
     id ^= process_id_hash_;
 
-  TimeTicks now = OffsetTimestamp(timestamp);
+  TimeTicks offset_event_timestamp = OffsetTimestamp(timestamp);
+  TimeTicks now = OffsetNow();

[nduca, 2015/02/13 19:13:44]

is this causing us to read the clock twice on every trace event? :(

[Xianzhu, 2015/02/13 19:27:26]

Yes :(

Possible ways to avoid this:
- check if overhead category is enabled before reading the clock;
- add a flag to indicate whether the event's timestamp is not now.

sg?

   TimeTicks thread_now = ThreadNow();
 
   ThreadLocalEventBuffer* thread_local_event_buffer = NULL;
@@ -1985,8 +1986,8 @@ TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     }
 
     if (trace_event) {
-      trace_event->Initialize(thread_id, now, thread_now, phase,
-                              category_group_enabled, name, id,
+      trace_event->Initialize(thread_id, offset_event_timestamp, thread_now,
+                              phase, category_group_enabled, name, id,
                               num_args, arg_names, arg_types, arg_values,
                               convertable_values, flags);
 
@@ -2024,7 +2025,7 @@ TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     EventCallback event_callback = reinterpret_cast<EventCallback>(
         subtle::NoBarrier_Load(&event_callback_));
     if (event_callback) {
-      event_callback(now,
+      event_callback(offset_event_timestamp,
                      phase == TRACE_EVENT_PHASE_COMPLETE ?
                          TRACE_EVENT_PHASE_BEGIN : phase,
                      category_group_enabled, name, id,
@@ -2033,6 +2034,9 @@ TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     }
   }
 
+  // Use |now| instead of |offset_event_timestamp| to compute overhead, because
+  // event timestamp may be not the real time that we started to add the event
+  // (e.g. event with zero timestamp or that was generated some time ago).
   if (thread_local_event_buffer)
     thread_local_event_buffer->ReportOverhead(now, thread_now);