Update from https://crrev.com/327068

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 <cmath>
 
 #include "base/base_switches.h"
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/debug/leak_annotations.h"
-#include "base/float_util.h"
 #include "base/format_macros.h"
 #include "base/json/string_escape.h"
 #include "base/lazy_instance.h"
 #include "base/memory/singleton.h"
 #include "base/message_loop/message_loop.h"
 #include "base/process/process_metrics.h"
 #include "base/stl_util.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_split.h"
 #include "base/strings/string_tokenizer.h"
 #include "base/strings/string_util.h"
 #include "base/strings/stringprintf.h"
 #include "base/strings/utf_string_conversions.h"
 #include "base/synchronization/cancellation_flag.h"
 #include "base/synchronization/waitable_event.h"
 #include "base/sys_info.h"
 #include "base/third_party/dynamic_annotations/dynamic_annotations.h"
 #include "base/threading/platform_thread.h"
 #include "base/threading/thread_id_name_manager.h"
+#include "base/threading/worker_pool.h"
 #include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "base/trace_event/trace_event_synthetic_delay.h"
 
 #if defined(OS_WIN)
+#include "base/trace_event/trace_event_etw_export_win.h"
 #include "base/trace_event/trace_event_win.h"
 #endif
 
 class DeleteTraceLogForTesting {
  public:
   static void Delete() {
     Singleton<base::trace_event::TraceLog,
               LeakySingletonTraits<base::trace_event::TraceLog>>::OnExit(0);
   }
 };
@@ skipping 18 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 kTraceEventBufferSizeInBytes = 100 * 1024;
 // 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 551 matching lines @@
       StringAppendF(out, "%" PRIu64, static_cast<uint64>(value.as_uint));
       break;
     case TRACE_VALUE_TYPE_INT:
       StringAppendF(out, "%" PRId64, static_cast<int64>(value.as_int));
       break;
     case TRACE_VALUE_TYPE_DOUBLE: {
       // FIXME: base/json/json_writer.cc is using the same code,
       //        should be made into a common method.
       std::string real;
       double val = value.as_double;
-      if (IsFinite(val)) {
+      if (std::isfinite(val)) {
         real = DoubleToString(val);
         // Ensure that the number has a .0 if there's no decimal or 'e'.  This
         // makes sure that when we read the JSON back, it's interpreted as a
         // real rather than an int.
         if (real.find('.') == std::string::npos &&
             real.find('e') == std::string::npos &&
             real.find('E') == std::string::npos) {
           real.append(".0");
         }
         // The JSON spec requires that non-integer values in the range (-1,1)
         // have a zero before the decimal point - ".52" is not valid, "0.52" is.
         if (real[0] == '.') {
           real.insert(0, "0");
         } else if (real.length() > 1 && real[0] == '-' && real[1] == '.') {
           // "-.1" bad "-0.1" good
           real.insert(1, "0");
         }
-      } else if (IsNaN(val)){
+      } else if (std::isnan(val)){
         // The JSON spec doesn't allow NaN and Infinity (since these are
         // objects in EcmaScript).  Use strings instead.
         real = "\"NaN\"";
       } else if (val < 0) {
         real = "\"-Infinity\"";
       } else {
         real = "\"Infinity\"";
       }
       StringAppendF(out, "%s", real.c_str());
       break;
@@ skipping 524 matching lines @@
       process_sort_index_(0),
       process_id_hash_(0),
       process_id_(0),
       watch_category_(0),
       trace_options_(kInternalRecordUntilFull),
       sampling_thread_handle_(0),
       category_filter_(CategoryFilter::kDefaultCategoryFilterString),
       event_callback_category_filter_(
           CategoryFilter::kDefaultCategoryFilterString),
       thread_shared_chunk_index_(0),
-      generation_(0) {
+      generation_(0),
+      use_worker_thread_(false) {
   // Trace is enabled or disabled on one thread while other threads are
   // accessing the enabled flag. We don't care whether edge-case events are
   // traced or not, so we allow races on the enabled flag to keep the trace
   // macros fast.
   // TODO(jbates): ANNOTATE_BENIGN_RACE_SIZED crashes windows TSAN bots:
   // ANNOTATE_BENIGN_RACE_SIZED(g_category_group_enabled,
   //                            sizeof(g_category_group_enabled),
   //                           "trace_event category enabled");
   for (int i = 0; i < MAX_CATEGORY_GROUPS; ++i) {
     ANNOTATE_BENIGN_RACE(&g_category_group_enabled[i],
@@ skipping 61 matching lines @@
   const char* category_group = g_category_groups[category_index];
   if (mode_ == RECORDING_MODE &&
       category_filter_.IsCategoryGroupEnabled(category_group))
     enabled_flag |= ENABLED_FOR_RECORDING;
   else if (mode_ == MONITORING_MODE &&
       category_filter_.IsCategoryGroupEnabled(category_group))
     enabled_flag |= ENABLED_FOR_MONITORING;
   if (event_callback_ &&
       event_callback_category_filter_.IsCategoryGroupEnabled(category_group))
     enabled_flag |= ENABLED_FOR_EVENT_CALLBACK;
+#if defined(OS_WIN)
+  if (base::trace_event::TraceEventETWExport::isETWExportEnabled())
+    enabled_flag |= ENABLED_FOR_ETW_EXPORT;
+#endif
+
   g_category_group_enabled[category_index] = enabled_flag;
 }
 
 void TraceLog::UpdateCategoryGroupEnabledFlags() {
   size_t category_index = base::subtle::NoBarrier_Load(&g_category_index);
   for (size_t i = 0; i < category_index; i++)
     UpdateCategoryGroupEnabledFlag(i);
 }
 
 void TraceLog::UpdateSyntheticDelaysFromCategoryFilter() {
@@ skipping 371 matching lines @@
 // Flush() works as the following:
 // 1. Flush() is called in threadA whose message loop is saved in
 //    flush_message_loop_proxy_;
 // 2. If thread_message_loops_ is not empty, threadA posts task to each message
 //    loop to flush the thread local buffers; otherwise finish the flush;
 // 3. FlushCurrentThread() deletes the thread local event buffer:
 //    - The last batch of events of the thread are flushed into the main buffer;
 //    - The message loop will be removed from thread_message_loops_;
 //    If this is the last message loop, finish the flush;
 // 4. If any thread hasn't finish its flush in time, finish the flush.
-void TraceLog::Flush(const TraceLog::OutputCallback& cb) {
+void TraceLog::Flush(const TraceLog::OutputCallback& cb,
+                     bool use_worker_thread) {
+  use_worker_thread_ = use_worker_thread;
   if (IsEnabled()) {
     // Can't flush when tracing is enabled because otherwise PostTask would
     // - generate more trace events;
     // - deschedule the calling thread on some platforms causing inaccurate
     //   timing of the trace events.
     scoped_refptr<RefCountedString> empty_result = new RefCountedString;
     if (!cb.is_null())
       cb.Run(empty_result, false);
     LOG(WARNING) << "Ignored TraceLog::Flush called when tracing is enabled";
     return;
@@ skipping 33 matching lines @@
     flush_message_loop_proxy_->PostDelayedTask(
         FROM_HERE,
         Bind(&TraceLog::OnFlushTimeout, Unretained(this), generation),
         TimeDelta::FromMilliseconds(kThreadFlushTimeoutMs));
     return;
   }
 
   FinishFlush(generation);
 }
 
+// Usually it runs on a different thread.
 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.
   bool has_more_events = true;
   do {
     scoped_refptr<RefCountedString> json_events_str_ptr =
         new RefCountedString();
 
-    for (size_t i = 0; i < kTraceEventBatchChunks; ++i) {
+    while (json_events_str_ptr->size() < kTraceEventBufferSizeInBytes) {
       const TraceBufferChunk* chunk = logged_events->NextChunk();
-      if (!chunk) {
-        has_more_events = false;
+      has_more_events = chunk != NULL;
+      if (!chunk)
         break;
-      }
       for (size_t j = 0; j < chunk->size(); ++j) {
-        if (i > 0 || j > 0)
+        if (json_events_str_ptr->size())
           json_events_str_ptr->data().append(",\n");
         chunk->GetEventAt(j)->AppendAsJSON(&(json_events_str_ptr->data()));
       }
     }
-
     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;
 
   if (!CheckGeneration(generation))
     return;
 
   {
     AutoLock lock(lock_);
 
     previous_logged_events.swap(logged_events_);
     UseNextTraceBuffer();
     thread_message_loops_.clear();
 
     flush_message_loop_proxy_ = NULL;
     flush_output_callback = flush_output_callback_;
     flush_output_callback_.Reset();
   }
 
+  if (use_worker_thread_ &&
+      WorkerPool::PostTask(
+          FROM_HERE,
+          Bind(&TraceLog::ConvertTraceEventsToTraceFormat,
+               Passed(&previous_logged_events),
+               flush_output_callback),
+          true)) {
+    return;
+  }
+
   ConvertTraceEventsToTraceFormat(previous_logged_events.Pass(),
                                   flush_output_callback);
 }
 
 // Run in each thread holding a local event buffer.
 void TraceLog::FlushCurrentThread(int generation) {
   {
     AutoLock lock(lock_);
     if (!CheckGeneration(generation) || !flush_message_loop_proxy_.get()) {
       // This is late. The corresponding flush has finished.
@@ skipping 103 matching lines @@
   // 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);
   DCHECK(!timestamp.is_null());
 
   if (flags & TRACE_EVENT_FLAG_MANGLE_ID)
-    id ^= process_id_hash_;
+    id = MangleEventId(id);
 
   TimeTicks offset_event_timestamp = OffsetTimestamp(timestamp);
   TimeTicks now = flags & TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP ?
       OffsetNow() : offset_event_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.
@@ skipping 42 matching lines @@
                                new_name) != existing_names.end();
         if (!found) {
           if (existing_names.size())
             existing_name->second.push_back(',');
           existing_name->second.append(new_name);
         }
       }
     }
   }
 
+#if defined(OS_WIN)
+  // This is done sooner rather than later, to avoid creating the event and
+  // acquiring the lock, which is not needed for ETW as it's already threadsafe.
+  if (*category_group_enabled & ENABLED_FOR_ETW_EXPORT)
+    TraceEventETWExport::AddEvent(phase, category_group_enabled, name, id,
+                                  num_args, arg_names, arg_types, arg_values,
+                                  convertable_values);
+#endif  // OS_WIN
+
   std::string console_message;
   if (*category_group_enabled &
       (ENABLED_FOR_RECORDING | ENABLED_FOR_MONITORING)) {
     OptionalAutoLock lock(&lock_);
 
     TraceEvent* trace_event = NULL;
     if (thread_local_event_buffer) {
       trace_event = thread_local_event_buffer->AddTraceEvent(&handle);
     } else {
       lock.EnsureAcquired();
@@ skipping 186 matching lines @@
   watch_event_callback_ = callback;
 }
 
 void TraceLog::CancelWatchEvent() {
   AutoLock lock(lock_);
   subtle::NoBarrier_Store(&watch_category_, 0);
   watch_event_name_ = "";
   watch_event_callback_.Reset();
 }
 
+uint64 TraceLog::MangleEventId(uint64 id) {
+  return id ^ process_id_hash_;
+}
+
 void TraceLog::AddMetadataEventsWhileLocked() {
   lock_.AssertAcquired();
 
 #if !defined(OS_NACL)  // NaCl shouldn't expose the process id.
   InitializeMetadataEvent(AddEventToThreadSharedChunkWhileLocked(NULL, false),
                           0,
                           "num_cpus", "number",
                           base::SysInfo::NumberOfProcessors());
 #endif
 
@@ skipping 412 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