Add support for TraceEvent before the native library is loaded.

base/debug/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/debug/trace_event_impl.h"
 
 #include <algorithm>
 
 #include "base/base_switches.h"
 #include "base/bind.h"
@@ skipping 55 matching lines @@
 const char kEnableSampling[] = "enable-sampling";
 const char kEnableSystrace[] = "enable-systrace";
 
 // Controls the number of trace events we will buffer in-memory
 // before throwing them away.
 const size_t kTraceBufferChunkSize = TraceBufferChunk::kTraceBufferChunkSize;
 const size_t kTraceEventVectorBigBufferChunks =
     512000000 / kTraceBufferChunkSize;
 const size_t kTraceEventVectorBufferChunks = 256000 / kTraceBufferChunkSize;
 const size_t kTraceEventRingBufferChunks = kTraceEventVectorBufferChunks / 4;
-const size_t kTraceEventBatchChunks = 1000 / kTraceBufferChunkSize;
+const size_t kTraceEventBatch = 1000;
 // Can store results for 30 seconds with 1 ms sampling interval.
 const size_t kMonitorTraceEventBufferChunks = 30000 / kTraceBufferChunkSize;
 // ECHO_TO_CONSOLE needs a small buffer to hold the unfinished COMPLETE events.
 const size_t kEchoToConsoleTraceEventBufferChunks = 256;
 
 const int kThreadFlushTimeoutMs = 3000;
 
 #if !defined(OS_NACL)
 // These categories will cause deadlock when ECHO_TO_CONSOLE. crbug.com/325575.
 const char kEchoToConsoleCategoryFilter[] = "-ipc,-task";
@@ skipping 1644 matching lines @@
     flush_message_loop_proxy_->PostDelayedTask(
         FROM_HERE,
         Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation),
         TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs));
     return;
   }
 
   FinishFlush(generation);
 }
 
+struct TraceEventTimestampComparator {
+  bool operator()(const TraceEvent* event1, const TraceEvent* event2) const {
+    return event1->timestamp() < event2->timestamp();
+  }
+};
+
 void TraceLog::ConvertTraceEventsToTraceFormat(
     scoped_ptr<TraceBuffer> logged_events,
     const TraceLog::OutputCallback& flush_output_callback) {
 
   if (flush_output_callback.is_null())
     return;
 
-  // The callback need to be called at least once even if there is no events
-  // to let the caller know the completion of flush.
+  // Note that the TraceEvent frontend expects the trace events to be sorted.

[dsinclair, 2015/01/27 14:43:30]

This seems like it's adding a lot of extra work. We have iterate the chunks, and
to the buffer, sort the buffer and then iterate the buffer where as before we
just walked over the chunks.

Why can Add custom send events out of order? As soon as tracing starts can it
not send all of it's events through? Or do the still end up slightly out of
order?  We're doing a lot of work here for that special case.

[Benoit L, 2015/02/09 16:34:00]

Done.

+  // An extra sort is needed here due to clients that might break the order by
+  // manually pushing additional trace events at random times (see uses of
+  // AddCustomTraceEvent()).
+  std::vector<const TraceEvent*> trace_events;
+
+  for (size_t buffer_index = 0;; ++buffer_index) {
+    const TraceBufferChunk* chunk = logged_events->NextChunk();
+    if (!chunk)
+      break;
+
+    for (size_t chunk_index = 0; chunk_index < chunk->size(); ++chunk_index)
+      trace_events.push_back(chunk->GetEventAt(chunk_index));
+  }
+
+  std::stable_sort(trace_events.begin(), trace_events.end(),

[dsinclair, 2015/01/27 14:43:30]

This seems like it could be expensive if we have to run the sort on each of the
buffers.

[Benoit L, 2015/02/09 16:34:00]

Done.

+                   TraceEventTimestampComparator());
+
+  // The callback needs to be called at least once even if there is no events to
+  // let the caller know the completion of flush.
   bool has_more_events = true;
+  std::vector<const TraceEvent*>::const_iterator it = trace_events.begin();

[dsinclair, 2015/01/27 14:43:30]

The change to use an iterator seems unrelated to this CL, can you pull it out
into a separate CL?

[Benoit L, 2015/02/09 16:34:01]

Done.

+
   do {
-    scoped_refptr<RefCountedString> json_events_str_ptr =
+    const scoped_refptr<RefCountedString> json_events_str_ptr =
         new RefCountedString();
 
-    for (size_t i = 0; i < kTraceEventBatchChunks; ++i) {
-      const TraceBufferChunk* chunk = logged_events->NextChunk();
-      if (!chunk) {
+    for (size_t i = 0; i < kTraceEventBatch; ++i) {
+      if (it == trace_events.end()) {
         has_more_events = false;
         break;
       }
-      for (size_t j = 0; j < chunk->size(); ++j) {
-        if (i > 0 || j > 0)
-          json_events_str_ptr->data().append(",\n");
-        chunk->GetEventAt(j)->AppendAsJSON(&(json_events_str_ptr->data()));
-      }
+
+      (*it)->AppendAsJSON(&json_events_str_ptr->data());
+      ++it;
+
+      if (it != trace_events.end() && i + 1 < kTraceEventBatch)
+        json_events_str_ptr->data().append(",\n");
     }
 
     flush_output_callback.Run(json_events_str_ptr, has_more_events);
   } while (has_more_events);
 }
 
 void TraceLog::FinishFlush(int generation) {
   scoped_ptr<TraceBuffer> previous_logged_events;
   OutputCallback flush_output_callback;
 
@@ skipping 72 matching lines @@
       logged_events_->ReturnChunk(thread_shared_chunk_index_,
                                   thread_shared_chunk_.Pass());
     }
     previous_logged_events = logged_events_->CloneForIteration().Pass();
   }  // release lock
 
   ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
                                   flush_output_callback);
 }
 
+TraceEventHandle TraceLog::AddCustomTraceEvent(
+    char phase,
+    const unsigned char* category_group_enabled,
+    const char* name,
+    int thread_id,
+    const TimeTicks& timestamp,
+    const TimeTicks& thread_time) {
+  return AddTraceEventInternal(
+      phase, category_group_enabled, name, trace_event_internal::kNoEventId,
+      thread_id, timestamp, thread_time, 0, NULL, NULL, NULL, NULL,
+      TRACE_EVENT_FLAG_COPY | TRACE_EVENT_FLAG_DONT_REPORT_OVERHEAD);
+}
+
 void TraceLog::UseNextTraceBuffer() {
   logged_events_.reset(CreateTraceBuffer());
   subtle::NoBarrier_AtomicIncrement(&generation_, 1);
   thread_shared_chunk_.reset();
   thread_shared_chunk_index_ = 0;
 }
 
 TraceEventHandle TraceLog::AddTraceEvent(
     char phase,
     const unsigned char* category_group_enabled,
@@ skipping 20 matching lines @@
     const char* name,
     unsigned long long id,
     int thread_id,
     const TimeTicks& timestamp,
     int num_args,
     const char** arg_names,
     const unsigned char* arg_types,
     const unsigned long long* arg_values,
     const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
     unsigned char flags) {
+  return AddTraceEventInternal(
+      phase, category_group_enabled, name, id, thread_id, timestamp,
+      ThreadNow(), num_args, arg_names, arg_types, arg_values,
+      convertable_values, flags);
+}
+
+TraceEventHandle TraceLog::AddTraceEventInternal(
+    char phase,
+    const unsigned char* category_group_enabled,
+    const char* name,
+    unsigned long long id,
+    int thread_id,
+    const TimeTicks& timestamp,
+    const TimeTicks& thread_time,
+    int num_args,
+    const char** arg_names,
+    const unsigned char* arg_types,
+    const unsigned long long* arg_values,
+    const scoped_refptr<ConvertableToTraceFormat>* convertable_values,
+    unsigned char flags) {
   TraceEventHandle handle = { 0, 0, 0 };
   if (!*category_group_enabled)
     return handle;
 
   // Avoid re-entrance of AddTraceEvent. This may happen in GPU process when
   // ECHO_TO_CONSOLE is enabled: AddTraceEvent -> LOG(ERROR) ->
   // GpuProcessLogMessageHandler -> PostPendingTask -> TRACE_EVENT ...
   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 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();
     if (thread_local_event_buffer &&
@@ skipping 51 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,
+      trace_event->Initialize(thread_id, now, thread_time, 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) {
@@ skipping 28 matching lines @@
       event_callback(now,
                      phase == TRACE_EVENT_PHASE_COMPLETE ?
                          TRACE_EVENT_PHASE_BEGIN : phase,
                      category_group_enabled, name, id,
                      num_args, arg_names, arg_types, arg_values,
                      flags);
     }
   }
 
   if (thread_local_event_buffer)
-    thread_local_event_buffer->ReportOverhead(now, thread_now);
+    if (!(flags & TRACE_EVENT_FLAG_DONT_REPORT_OVERHEAD))

[dsinclair, 2015/01/27 14:43:30]

Why would we want to skip reporting the overhead? Seems like we'll just end up
hiding causes of slowness in the tracing system.

[Benoit L, 2015/02/09 16:34:01]

Done.

+      thread_local_event_buffer->ReportOverhead(now, thread_time);
 
   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,
                                             TraceEvent* trace_event) {
   AutoLock thread_info_lock(thread_info_lock_);
@@ skipping 537 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