Add support for TraceEvent before the native library is loaded.

base/debug/trace_event_impl.cc

Index: base/debug/trace_event_impl.cc
diff --git a/base/debug/trace_event_impl.cc b/base/debug/trace_event_impl.cc
index 137cb02b4aa771c75fc94903074b9bd6fdb3ddfe..a56cae394dea871efdede66fcde1e48973b40a7c 100644
--- a/base/debug/trace_event_impl.cc
+++ b/base/debug/trace_event_impl.cc
@@ -73,7 +73,7 @@ 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.
@@ -1738,6 +1738,12 @@ void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
   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) {
@@ -1745,24 +1751,44 @@ void TraceLog::ConvertTraceEventsToTraceFormat(
   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);
@@ -1855,6 +1881,19 @@ void TraceLog::FlushButLeaveBufferIntact(
                                   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);
@@ -1895,6 +1934,26 @@ TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     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;
@@ -1913,7 +1972,6 @@ TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     id ^= process_id_hash_;
 
   TimeTicks now = OffsetTimestamp(timestamp);
-  TimeTicks thread_now = ThreadNow();
 
   ThreadLocalEventBuffer* thread_local_event_buffer = NULL;
   // A ThreadLocalEventBuffer needs the message loop
@@ -1985,7 +2043,7 @@ TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
     }
 
     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);
@@ -2034,7 +2092,8 @@ TraceEventHandle TraceLog::AddTraceEventWithThreadIdAndTimestamp(
   }
 
   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;
 }