Implements Windows system tracing.

This CL brings the tracing information into the resulting JSon.

As tracing needs administrator rights, we assume that Chrome is launched
as administrator.

To be able to view events, the traceviewer part must land first.
see: https://codereview.appspot.com/51300043/

BUG=

Review URL: https://codereview.chromium.org/171143002

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@255818 0039d316-1c4b-4281-b951-d872f2087c98

content/browser/tracing/etw_system_event_consumer_win.cc

+// Copyright 2014 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 "content/browser/tracing/etw_system_event_consumer_win.h"
+
+#include "base/base64.h"
+#include "base/debug/trace_event_impl.h"
+#include "base/json/json_string_value_serializer.h"
+#include "base/lazy_instance.h"
+#include "base/memory/singleton.h"
+#include "base/strings/stringprintf.h"
+#include "base/time/time.h"
+#include "content/public/browser/browser_thread.h"
+
+namespace content {
+
+namespace {
+
+const int kEtwBufferSizeInKBytes = 16;
+const int kEtwBufferFlushTimeoutInSeconds = 1;
+
+std::string GuidToString(const GUID& guid) {
+  return base::StringPrintf("%08X-%04X-%04X-%02X%02X-%02X%02X%02X%02X%02X%02X",
+      guid.Data1, guid.Data2, guid.Data3,
+      guid.Data4[0], guid.Data4[1], guid.Data4[2], guid.Data4[3],
+      guid.Data4[4], guid.Data4[5], guid.Data4[6], guid.Data4[7]);
+}
+
+}  // namespace
+
+EtwSystemEventConsumer::EtwSystemEventConsumer()
+    : thread_("EtwConsumerThread") {
+}
+
+EtwSystemEventConsumer::~EtwSystemEventConsumer() {
+}
+
+bool EtwSystemEventConsumer::StartSystemTracing() {
+
+  // Activate kernel tracing.
+  if (!StartKernelSessionTracing())
+    return false;
+
+  // Start the consumer thread and start consuming events.
+  thread_.Start();
+  thread_.message_loop()->PostTask(
+      FROM_HERE,
+      base::Bind(&EtwSystemEventConsumer::TraceAndConsumeOnThread,
+                 base::Unretained(this)));
+
+  return true;
+}
+
+void EtwSystemEventConsumer::StopSystemTracing(const OutputCallback& callback) {
+  // Deactivate kernel tracing.
+  if (!StopKernelSessionTracing()) {
+    LOG(FATAL) << "Could not stop system tracing.";
+  }
+
+  // Stop consuming and flush events.
+  OutputCallback on_stop_system_tracing_done_callback =
+      base::Bind(&EtwSystemEventConsumer::OnStopSystemTracingDone,
+                 base::Unretained(this),
+                 callback);
+  thread_.message_loop()->PostTask(FROM_HERE,
+      base::Bind(&EtwSystemEventConsumer::FlushOnThread,
+                 base::Unretained(this), on_stop_system_tracing_done_callback));
+}
+
+void EtwSystemEventConsumer::OnStopSystemTracingDone(
+    const OutputCallback& callback,
+    const scoped_refptr<base::RefCountedString>& result) {
+
+  // Stop the consumer thread.
+  thread_.Stop();
+
+  // Pass the serialized events.
+  callback.Run(result);
+}
+
+bool EtwSystemEventConsumer::StartKernelSessionTracing() {
+  // Enabled flags (tracing facilities).
+  uint32 enabled_flags = EVENT_TRACE_FLAG_IMAGE_LOAD |
+                         EVENT_TRACE_FLAG_PROCESS |
+                         EVENT_TRACE_FLAG_THREAD |
+                         EVENT_TRACE_FLAG_CSWITCH;
+
+  EVENT_TRACE_PROPERTIES& p = *properties_.get();
+  p.LogFileMode = EVENT_TRACE_REAL_TIME_MODE;
+  p.FlushTimer = kEtwBufferFlushTimeoutInSeconds;
+  p.BufferSize = kEtwBufferSizeInKBytes;
+  p.LogFileNameOffset = 0;
+  p.EnableFlags = enabled_flags;
+  p.Wnode.ClientContext = 1;  // QPC timer accuracy.
+
+  HRESULT hr = base::win::EtwTraceController::Start(
+      KERNEL_LOGGER_NAME, &properties_, &session_handle_);
+  if (FAILED(hr)) {
+    VLOG(1) << "StartRealtimeSession() failed with " << hr << ".";
+    return false;
+  }
+
+  return true;
+}
+
+bool EtwSystemEventConsumer::StopKernelSessionTracing() {
+  HRESULT hr = base::win::EtwTraceController::Stop(
+      KERNEL_LOGGER_NAME, &properties_);
+  return SUCCEEDED(hr);
+}
+
+// static
+EtwSystemEventConsumer* EtwSystemEventConsumer::GetInstance() {
+  return Singleton<EtwSystemEventConsumer>::get();
+}
+
+// static
+void EtwSystemEventConsumer::ProcessEvent(EVENT_TRACE* event) {
+  EtwSystemEventConsumer::GetInstance()->AppendEventToBuffer(event);
+}
+
+void EtwSystemEventConsumer::AddSyncEventToBuffer() {
+  // Sync the clocks.
+  base::Time walltime = base::Time::NowFromSystemTime();
+  base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
+
+  LARGE_INTEGER walltime_in_us;
+  walltime_in_us.QuadPart = walltime.ToInternalValue();
+  LARGE_INTEGER now_in_us;
+  now_in_us.QuadPart = now.ToInternalValue();
+
+  // Add fields to the event.
+  scoped_ptr<base::DictionaryValue> value(new base::DictionaryValue());
+  value->Set("guid", new base::StringValue("ClockSync"));
+  value->Set("walltime", new base::StringValue(
+      base::StringPrintf("%08X%08X",
+                         walltime_in_us.HighPart,
+                         walltime_in_us.LowPart)));
+  value->Set("tick", new base::StringValue(
+      base::StringPrintf("%08X%08X",
+                         now_in_us.HighPart,
+                         now_in_us.LowPart)));
+
+  // Append it to the events buffer.
+  events_->Append(value.release());
+}
+
+void EtwSystemEventConsumer::AppendEventToBuffer(EVENT_TRACE* event) {
+  using base::FundamentalValue;
+
+  scoped_ptr<base::DictionaryValue> value(new base::DictionaryValue());
+
+  // Add header fields to the event.
+  LARGE_INTEGER ts_us;
+  ts_us.QuadPart = event->Header.TimeStamp.QuadPart / 10;
+  value->Set("ts", new base::StringValue(
+      base::StringPrintf("%08X%08X", ts_us.HighPart, ts_us.LowPart)));
+
+  value->Set("guid", new base::StringValue(GuidToString(event->Header.Guid)));
+
+  value->Set("op", new FundamentalValue(event->Header.Class.Type));
+  value->Set("ver", new FundamentalValue(event->Header.Class.Version));
+  value->Set("pid",
+             new FundamentalValue(static_cast<int>(event->Header.ProcessId)));
+  value->Set("tid",
+             new FundamentalValue(static_cast<int>(event->Header.ThreadId)));
+  value->Set("cpu", new FundamentalValue(event->BufferContext.ProcessorNumber));
+
+  // Base64 encode the payload bytes.
+  base::StringPiece buffer(static_cast<const char*>(event->MofData),
+                           event->MofLength);
+  std::string payload;
+  base::Base64Encode(buffer, &payload);
+  value->Set("payload", new base::StringValue(payload));
+
+  // Append it to the events buffer.
+  events_->Append(value.release());
+}
+
+void EtwSystemEventConsumer::TraceAndConsumeOnThread() {
+  // Create the events buffer.
+  events_.reset(new base::ListValue());
+
+  // Output a clock sync event.
+  AddSyncEventToBuffer();
+
+  HRESULT hr = OpenRealtimeSession(KERNEL_LOGGER_NAME);
+  if (FAILED(hr))
+    return;
+  Consume();
+  Close();
+}
+
+void EtwSystemEventConsumer::FlushOnThread(const OutputCallback& callback) {
+  // Add the header information to the stream.
+  scoped_ptr<base::DictionaryValue> header(new base::DictionaryValue());
+  header->Set("name", base::Value::CreateStringValue("ETW"));
+
+  // Release and pass the events buffer.
+  header->Set("content", events_.release());
+
+  // Serialize the results as a JSon string.
+  std::string output;
+  JSONStringValueSerializer serializer(&output);
+  serializer.Serialize(*header.get());
+
+  // Pass the result to the UI Thread.
+  scoped_refptr<base::RefCountedString> result =
+      base::RefCountedString::TakeString(&output);
+  BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
+                          base::Bind(callback, result));
+}
+
+}  // namespace content

content/browser/tracing/etw_system_event_consumer_win.h

+// Copyright 2014 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.
+
+#ifndef CONTENT_BROWSER_TRACING_TRACING_CONSUMER_WIN_H_
+#define CONTENT_BROWSER_TRACING_TRACING_CONSUMER_WIN_H_
+
+#include "base/bind.h"
+#include "base/memory/ref_counted_memory.h"
+#include "base/threading/thread.h"
+#include "base/values.h"
+#include "base/win/event_trace_consumer.h"
+#include "base/win/event_trace_controller.h"
+
+template <typename Type>
+struct DefaultSingletonTraits;
+
+namespace content {
+
+class EtwSystemEventConsumer :
+    public base::win::EtwTraceConsumerBase<EtwSystemEventConsumer> {
+ public:
+  typedef base::Callback<void(const scoped_refptr<base::RefCountedString>&)>
+      OutputCallback;
+
+  bool StartSystemTracing();
+  void StopSystemTracing(const OutputCallback& callback);
+
+  // Retrieve the ETW consumer instance.
+  static EtwSystemEventConsumer* GetInstance();
+
+ private:
+  // This allows constructor and destructor to be private and usable only
+  // by the Singleton class.
+  friend struct DefaultSingletonTraits<EtwSystemEventConsumer>;
+
+  // Constructor.
+  EtwSystemEventConsumer();
+  virtual ~EtwSystemEventConsumer();
+
+  void AddSyncEventToBuffer();
+  void AppendEventToBuffer(EVENT_TRACE* event);
+
+  // Static override of EtwTraceConsumerBase::ProcessEvent.
+  // @param event the raw ETW event to process.
+  friend class base::win::EtwTraceConsumerBase<EtwSystemEventConsumer>;
+  static void ProcessEvent(EVENT_TRACE* event);
+
+  // Request the ETW trace controller to activate the kernel tracing.
+  // returns true on success, false if the kernel tracing isn't activated.
+  bool StartKernelSessionTracing();
+
+  // Request the ETW trace controller to deactivate the kernel tracing.
+  // @param callback the callback to call with the consumed events.
+  // @returns true on success, false if an error occurred.
+  bool StopKernelSessionTracing();
+
+  void OnStopSystemTracingDone(
+    const OutputCallback& callback,
+    const scoped_refptr<base::RefCountedString>& result);
+
+  void TraceAndConsumeOnThread();
+  void FlushOnThread(const OutputCallback& callback);
+
+  scoped_ptr<base::ListValue> events_;
+  base::Thread thread_;
+  TRACEHANDLE session_handle_;
+  base::win::EtwTraceProperties properties_;
+
+  DISALLOW_COPY_AND_ASSIGN(EtwSystemEventConsumer);
+};
+
+}  // namespace content
+
+#endif  // CONTENT_BROWSER_TRACING_TRACING_CONSUMER_WIN_H_

content/browser/tracing/tracing_controller_impl.cc

-// Copyright 2013 The Chromium Authors. All rights reserved.
+// Copyright (c) 2013 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 "content/browser/tracing/tracing_controller_impl.h"
 
 #include "base/bind.h"
@@ -20,6 +19,10 @@
 #include "chromeos/dbus/debug_daemon_client.h"
 #endif
 
+#if defined(OS_WIN)
+#include "content/browser/tracing/etw_system_event_consumer_win.h"
+#endif
+
 using base::debug::TraceLog;
 
 namespace content {
@@ -101,7 +104,7 @@ void TracingControllerImpl::ResultFile::WriteTask(
   if (!file_ || !events_str_ptr->data().size())
     return;
 
-  // If there is already a result in the file, then put a commma
+  // If there is already a result in the file, then put a comma
   // before the next batch of results.
   if (has_at_least_one_result_) {
     size_t written = fwrite(",", 1, 1, file_);
@@ -129,9 +132,15 @@ void TracingControllerImpl::ResultFile::CloseTask(
   DCHECK(written == 1);
 
   if (system_trace_) {
+#if defined(OS_WIN)
+    // The Windows kernel events are kept into a JSon format stored as string
+    // and must not be escaped.
+    std::string json_string = system_trace_->data();
+#else
     std::string json_string = base::GetQuotedJSONString(system_trace_->data());
+#endif
 
-    const char* systemTraceHead = ", \"systemTraceEvents\": ";
+    const char* systemTraceHead = ",\n\"systemTraceEvents\": ";
     written = fwrite(systemTraceHead, strlen(systemTraceHead), 1, file_);
     DCHECK(written == 1);
 
@@ -158,7 +167,7 @@ TracingControllerImpl::TracingControllerImpl() :
     maximum_trace_buffer_percent_full_(0),
     // Tracing may have been enabled by ContentMainRunner if kTraceStartup
     // is specified in command line.
-#if defined(OS_CHROMEOS)
+#if defined(OS_CHROMEOS) || defined(OS_WIN)
     is_system_tracing_(false),
 #endif
     is_recording_(TraceLog::GetInstance()->IsEnabled()),
@@ -234,21 +243,27 @@ bool TracingControllerImpl::EnableRecording(
   int trace_options = (options & RECORD_CONTINUOUSLY) ?
       TraceLog::RECORD_CONTINUOUSLY : TraceLog::RECORD_UNTIL_FULL;
   if (options & ENABLE_SAMPLING) {
-    trace_options |=  TraceLog::ENABLE_SAMPLING;
+    trace_options |= TraceLog::ENABLE_SAMPLING;
   }
-#if defined(OS_CHROMEOS)
+
   if (options & ENABLE_SYSTRACE) {
+#if defined(OS_CHROMEOS)
     DCHECK(!is_system_tracing_);
     chromeos::DBusThreadManager::Get()->GetDebugDaemonClient()->
       StartSystemTracing();
     is_system_tracing_ = true;
-  }
+#elif defined(OS_WIN)
+    DCHECK(!is_system_tracing_);
+    is_system_tracing_ =
+        EtwSystemEventConsumer::GetInstance()->StartSystemTracing();
 #endif
+  }
+
 
   base::Closure on_enable_recording_done_callback =
       base::Bind(&TracingControllerImpl::OnEnableRecordingDone,
                  base::Unretained(this),
-                 category_filter,trace_options, callback);
+                 category_filter, trace_options, callback);
   BrowserThread::PostTask(BrowserThread::FILE, FROM_HERE,
       base::Bind(&TracingControllerImpl::SetEnabledOnFileThread,
                  base::Unretained(this),
@@ -425,7 +440,7 @@ void TracingControllerImpl::GetMonitoringStatus(
     TracingController::Options* out_options) {
   *out_enabled = is_monitoring_;
   *out_category_filter =
-    TraceLog::GetInstance()->GetCurrentCategoryFilter().ToString();
+      TraceLog::GetInstance()->GetCurrentCategoryFilter().ToString();
   *out_options = options_;
 }
 
@@ -668,19 +683,33 @@ void TracingControllerImpl::OnDisableRecordingComplete() {
 
 #if defined(OS_CHROMEOS)
   if (is_system_tracing_) {
+    // Disable system tracing.
+    is_system_tracing_ = false;
+
     // Disable system tracing now that the local trace has shutdown.
     // This must be done last because we potentially need to push event
     // records into the system event log for synchronizing system event
     // timestamps with chrome event timestamps--and since the system event
     // log is a ring-buffer (on linux) adding them at the end is the only
     // way we're confident we'll have them in the final result.
-    is_system_tracing_ = false;
     chromeos::DBusThreadManager::Get()->GetDebugDaemonClient()->
       RequestStopSystemTracing(
           base::Bind(&TracingControllerImpl::OnEndSystemTracingAcked,
                      base::Unretained(this)));
     return;
   }
+#elif defined(OS_WIN)
+  if (is_system_tracing_) {
+    // Disable system tracing.
+    is_system_tracing_ = false;
+
+
+    // Stop kernel tracing and flush events.
+    EtwSystemEventConsumer::GetInstance()->StopSystemTracing(
+        base::Bind(&TracingControllerImpl::OnEndSystemTracingAcked,
+                   base::Unretained(this)));
+    return;
+  }
 #endif
 
   // Trigger callback if one is set.
@@ -707,7 +736,7 @@ void TracingControllerImpl::OnResultFileClosed() {
   result_file_.reset();
 }
 
-#if defined(OS_CHROMEOS)
+#if defined(OS_CHROMEOS) || defined(OS_WIN)
 void TracingControllerImpl::OnEndSystemTracingAcked(
     const scoped_refptr<base::RefCountedString>& events_str_ptr) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
@@ -873,21 +902,18 @@ void TracingControllerImpl::OnWatchEventMatched() {
     watch_event_callback_.Run();
 }
 
-void TracingControllerImpl::RegisterTracingUI(TracingUI* tracing_ui)
-{
+void TracingControllerImpl::RegisterTracingUI(TracingUI* tracing_ui) {
   DCHECK(tracing_uis_.find(tracing_ui) == tracing_uis_.end());
   tracing_uis_.insert(tracing_ui);
 }
 
-void TracingControllerImpl::UnregisterTracingUI(TracingUI* tracing_ui)
-{
+void TracingControllerImpl::UnregisterTracingUI(TracingUI* tracing_ui) {
   std::set<TracingUI*>::iterator it = tracing_uis_.find(tracing_ui);
   DCHECK(it != tracing_uis_.end());
   tracing_uis_.erase(it);
 }
 
-void TracingControllerImpl::OnMonitoringStateChanged(bool is_monitoring)
-{
+void TracingControllerImpl::OnMonitoringStateChanged(bool is_monitoring) {
   if (is_monitoring_ == is_monitoring)
     return;
 

content/browser/tracing/tracing_controller_impl.h

-// Copyright 2013 The Chromium Authors. All rights reserved.
+// Copyright (c) 2013 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.
 
@@ -116,7 +116,7 @@ class TracingControllerImpl : public TracingController {
   void OnDisableRecordingComplete();
   void OnResultFileClosed();
 
-#if defined(OS_CHROMEOS)
+#if defined(OS_CHROMEOS) || defined(OS_WIN)
   void OnEndSystemTracingAcked(
       const scoped_refptr<base::RefCountedString>& events_str_ptr);
 #endif
@@ -161,7 +161,7 @@ class TracingControllerImpl : public TracingController {
   TraceMessageFilterSet pending_trace_buffer_percent_full_filters_;
   float maximum_trace_buffer_percent_full_;
 
-#if defined(OS_CHROMEOS)
+#if defined(OS_CHROMEOS) || defined(OS_WIN)
   bool is_system_tracing_;
 #endif
   bool is_recording_;

content/content_browser.gypi

@@ -1235,6 +1235,8 @@
     'browser/theme_helper_mac.h',
     'browser/tracing/trace_message_filter.cc',
     'browser/tracing/trace_message_filter.h',
+    'browser/tracing/etw_system_event_consumer_win.cc',
+    'browser/tracing/etw_system_event_consumer_win.h',
     'browser/tracing/tracing_controller_impl.cc',
     'browser/tracing/tracing_controller_impl.h',
     'browser/tracing/tracing_ui.cc',