Implements Windows system tracing.

content/browser/tracing/tracing_controller_impl.cc

Index: content/browser/tracing/tracing_controller_impl.cc
diff --git a/content/browser/tracing/tracing_controller_impl.cc b/content/browser/tracing/tracing_controller_impl.cc
index 120a00787f4ad64adfbd2cfe2ba2dd94ec9f0a08..9d925054300739f187588120d1d0e2ca717a2399 100644
--- a/content/browser/tracing/tracing_controller_impl.cc
+++ b/content/browser/tracing/tracing_controller_impl.cc
@@ -20,6 +20,13 @@
 #include "chromeos/dbus/debug_daemon_client.h"
 #endif
 
+#if defined(OS_WIN)
+#include "base/values.h"
+#include "base/json/json_string_value_serializer.h"
+#include "base/win/event_trace_controller.h"
+#include "base/win/event_trace_consumer.h"
+#endif
+
 using base::debug::TraceLog;
 
 namespace content {
@@ -29,6 +36,155 @@ namespace {
 base::LazyInstance<TracingControllerImpl>::Leaky g_controller =
     LAZY_INSTANCE_INITIALIZER;
 
+#if defined(OS_WIN)
+
+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]);
+}
+
+class EtwSystemEventConsumer :
+    public base::win::EtwTraceConsumerBase<EtwSystemEventConsumer> {
+ public:
+  typedef base::Callback<void(const scoped_refptr<base::RefCountedString>&)>
+      OutputCallback;
+
+  EtwSystemEventConsumer() : thread_("EtwConsumerThread") {
+    thread_.Start();

[nduca, 2014/02/18 22:17:13]

you should probably kill the thread when things stop, too. 

maybe instead of having thread_ being a by-value member, make it be a
scoped_ptr() that you create and destroy only for the lifetime of the trace

[etienneb, 2014/02/19 17:14:52]

I cannot kill the thread until the events isn't flushed.
Any thoughs on that?

On 2014/02/18 22:17:13, nduca wrote:

+  }
+
+  void RequestStartSystemTracing() {
+    events_.reset(new base::ListValue());
+    thread_.message_loop()->PostTask(
+        FROM_HERE,
+        base::Bind(&EtwSystemEventConsumer::TraceAndConsumeOnThread,
+                   base::Unretained(this)));
+  }
+
+  void RequestStopSystemTracing(const OutputCallback& callback) {
+    thread_.message_loop()->PostTask(FROM_HERE,
+        base::Bind(&EtwSystemEventConsumer::StopSystemTracingOnThread,
+                   base::Unretained(this), callback));
+  }
+
+  void AppendEventToBuffer(EVENT_TRACE* event) {
+    using base::Value;
+    using base::StringPrintf;
+
+    scoped_ptr<base::DictionaryValue> value(new base::DictionaryValue());
+
+    // Add header fields to the event.
+    value->Set("ts", base::Value::CreateStringValue(
+        StringPrintf("%08X%08X",
+                     event->Header.TimeStamp.HighPart,
+                     event->Header.TimeStamp.LowPart)));
+
+    value->Set("guid", base::Value::CreateStringValue(
+        GuidToString(event->Header.Guid)));
+
+    // TODO(etienneb): CreateIntegerValue are deprecated.
+    value->Set("op", Value::CreateIntegerValue(event->Header.Class.Type));
+    value->Set("ver", Value::CreateIntegerValue(event->Header.Class.Version));
+    value->Set("pid", Value::CreateIntegerValue(event->Header.ProcessId));
+    value->Set("tid", Value::CreateIntegerValue(event->Header.ProcessId));
+    value->Set("cpu", Value::CreateIntegerValue(
+        event->BufferContext.ProcessorNumber));
+
+    // TODO(etienneb): fix it!!!!!
+    value->Set("is64", Value::CreateIntegerValue(1));
+
+    // Encode the payload bytes in hexadecimal.
+    std::string payload =
+          StringToLowerASCII(base::HexEncode(event->MofData, event->MofLength));
+    value->Set("payload", base::Value::CreateStringValue(payload));
+
+    // Append it to the events buffer.
+    events_->Append(value.release());
+  }
+
+  static void ProcessEvent(EVENT_TRACE* event);
+  static EtwSystemEventConsumer* Get();
+
+  bool StartNTKernelSessionTracing() {

[nduca, 2014/02/18 22:17:13]

can this be a private member and you just make there be only one public start
function that first checks that kernel tracing can be started, and only then
start the thread?

[etienneb, 2014/02/19 17:14:52]

I kept them separate to be able to update: is_system_tracing_.

On 2014/02/18 22:17:13, nduca wrote:

+    // 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 = 1;  // flush every second.
+    p.BufferSize = 16;  // 16 K buffers.
+    p.LogFileNameOffset = 0;
+    p.EnableFlags = enabled_flags;
+
+    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 StopNTKernelSessionTracing() {
+    HRESULT hr = base::win::EtwTraceController::Stop(
+        KERNEL_LOGGER_NAME, &properties_);
+    return SUCCEEDED(hr);
+  }
+
+ private:
+
+  void TraceAndConsumeOnThread() {
+    HRESULT hr = OpenRealtimeSession(KERNEL_LOGGER_NAME);
+    if (FAILED(hr))
+      return;
+    Consume();
+    Close();
+  }
+
+  void StopSystemTracingOnThread(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"));
+    header->Set("content", events_.release());
+
+    // Serialize the results as a JSon string.
+    std::string output;
+    JSONStringValueSerializer serializer(&output);
+    serializer.set_pretty_print(true);
+    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));
+  }
+
+  scoped_ptr<base::ListValue> events_;
+  base::Thread thread_;
+  TRACEHANDLE session_handle_;
+  base::win::EtwTraceProperties properties_;
+};
+
+base::LazyInstance<EtwSystemEventConsumer>::Leaky g_etw_consumer =

[nduca, 2014/02/18 22:17:13]

how about having tracing controller own this instance? tracing controller is
itself a singelton...

[etienneb, 2014/02/19 17:14:52]

The ProcessEvent is called by a windows callback.
Thus, we need to use the TracingControllerSingleton to get the TracingConsumer
singleton.

This way, we do not need to expose the consumer through the controller.

I saw that as the Controller "use" the ETWController/ETWConsumer.

On 2014/02/18 22:17:13, nduca wrote:

+    LAZY_INSTANCE_INITIALIZER;
+
+EtwSystemEventConsumer* EtwSystemEventConsumer::Get() {
+  return g_etw_consumer.Pointer();
+}
+
+void EtwSystemEventConsumer::ProcessEvent(EVENT_TRACE* event) {
+  EtwSystemEventConsumer::Get()->AppendEventToBuffer(event);
+}
+
+#endif  // OS_WIN
+
 }  // namespace
 
 TracingController* TracingController::GetInstance() {
@@ -129,9 +285,15 @@ void TracingControllerImpl::ResultFile::CloseTask(
   DCHECK(written == 1);
 
   if (system_trace_) {
+#if defined(OS_WIN)
+    // TODO(etienneb): This is ugly patch on windows. We should keep Value for
+    //    all OS instead of String to represent system traces.
+    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);
 
@@ -236,6 +398,7 @@ bool TracingControllerImpl::EnableRecording(
   if (options & ENABLE_SAMPLING) {
     trace_options |= TraceLog::ENABLE_SAMPLING;
   }
+
 #if defined(OS_CHROMEOS)
   if (options & ENABLE_SYSTRACE) {
     DCHECK(!is_system_tracing_);
@@ -248,7 +411,9 @@ bool TracingControllerImpl::EnableRecording(
 #if defined(OS_WIN)
   if (options & ENABLE_SYSTRACE) {
     DCHECK(!is_system_tracing_);
-    is_system_tracing_ = true;
+    is_system_tracing_ =
+        EtwSystemEventConsumer::Get()->StartNTKernelSessionTracing();
+    g_etw_consumer.Pointer()->RequestStartSystemTracing();
   }
 #endif
 
@@ -692,7 +857,15 @@ void TracingControllerImpl::OnDisableRecordingComplete() {
 
 #if defined(OS_WIN)

[nduca, 2014/02/18 22:17:13]

lets pull out this and the cros one to

if (is_system_tracing_) {
 BeginToStopSystemTracing();
 return;
}

Then there's only one if for system tracing. The ifdefs can be inside the
function body.

[etienneb, 2014/02/19 17:14:52]

Done.

   if (is_system_tracing_) {
+    // Disable system tracing.
+    EtwSystemEventConsumer::Get()->StopNTKernelSessionTracing();
     is_system_tracing_ = false;
+
+    // Request events to be flushed.
+    EtwSystemEventConsumer::Get()->RequestStopSystemTracing(
+        base::Bind(&TracingControllerImpl::OnEndSystemTracingAcked,
+                   base::Unretained(this)));
+    return;
   }
 #endif
 
@@ -720,7 +893,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));