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

base/trace_event/trace_event_impl.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "base/trace_event/trace_event_impl.h"
 
 #include <algorithm>
 
 #include "base/base_switches.h"
 #include "base/bind.h"
@@ skipping 1894 matching lines @@
   if (thread_is_in_trace_event_.Get())
     return handle;
 
   AutoThreadLocalBoolean thread_is_in_trace_event(&thread_is_in_trace_event_);
 
   DCHECK(name);
 
   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;
   // A ThreadLocalEventBuffer needs the message loop
   // - to know when the thread exits;
   // - to handle the final flush.
   // For a thread without a message loop or the message loop may be blocked, the
   // trace events will be added into the main buffer directly.
   if (!thread_blocks_message_loop_.Get() && MessageLoop::current()) {
     thread_local_event_buffer = thread_local_event_buffer_.Get();
@@ skipping 52 matching lines @@
 
     TraceEvent* trace_event = NULL;
     if (thread_local_event_buffer) {
       trace_event = thread_local_event_buffer->AddTraceEvent(&handle);
     } else {
       lock.EnsureAcquired();
       trace_event = AddEventToThreadSharedChunkWhileLocked(&handle, true);
     }
 
     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);
 
 #if defined(OS_ANDROID)
       trace_event->SendToATrace();
 #endif
     }
 
     if (trace_options() & kInternalEchoToConsole) {
       console_message = EventToConsoleMessage(
@@ skipping 17 matching lines @@
     if (event_name_matches) {
       if (!watch_event_callback_copy.is_null())
         watch_event_callback_copy.Run();
     }
   }
 
   if (*category_group_enabled & ENABLED_FOR_EVENT_CALLBACK) {
     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,
                      num_args, arg_names, arg_types, arg_values,
                      flags);
     }
   }
 
+  // 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);
 
   return handle;
 }
 
 // May be called when a COMPELETE event ends and the unfinished event has been
 // recycled (phase == TRACE_EVENT_PHASE_END and trace_event == NULL).
 std::string TraceLog::EventToConsoleMessage(unsigned char phase,
                                             const TimeTicks& timestamp,
@@ skipping 539 matching lines @@
 }
 
 ScopedTraceBinaryEfficient::~ScopedTraceBinaryEfficient() {
   if (*category_group_enabled_) {
     TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION(category_group_enabled_,
                                                 name_, event_handle_);
   }
 }
 
 }  // namespace trace_event_internal