Implements Windows system tracing.

content/browser/tracing/tracing_controller_impl.cc

 // Copyright 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"
 #include "base/debug/trace_event.h"
 #include "base/file_util.h"
 #include "base/json/string_escape.h"
 #include "base/strings/string_number_conversions.h"
 #include "content/browser/tracing/trace_message_filter.h"
 #include "content/browser/tracing/tracing_ui.h"
 #include "content/common/child_process_messages.h"
 #include "content/public/browser/browser_message_filter.h"
 #include "content/public/common/content_switches.h"
 
 #if defined(OS_CHROMEOS)
 #include "chromeos/dbus/dbus_thread_manager.h"
 #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 {
 
 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();
+  }
+
+  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) {

[fdoray, 2014/02/19 16:18:08]

Should be private.

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

Done.

+    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));

[fdoray, 2014/02/19 16:18:08]

Too much indentation. Should be 4 spaces.

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

Done.

+    value->Set("payload", base::Value::CreateStringValue(payload));

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

oh also should  base64 encode?

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

Done.

+
+    // Append it to the events buffer.
+    events_->Append(value.release());
+  }
+
+  static void ProcessEvent(EVENT_TRACE* event);
+  static EtwSystemEventConsumer* Get();
+
+  bool StartNTKernelSessionTracing() {
+    // 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.

[dsinclair, 2014/02/19 16:29:39]

Should these be moved to constants instead of having comments?

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

Done.

+    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:
+

[fdoray, 2014/02/19 16:18:08]

No empty line.

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

Done.

+  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 =
+    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() {
   return TracingControllerImpl::GetInstance();
 }
 
 class TracingControllerImpl::ResultFile {
  public:
   explicit ResultFile(const base::FilePath& path);
   void Write(const scoped_refptr<base::RefCountedString>& events_str_ptr) {
@@ skipping 80 matching lines @@
 void TracingControllerImpl::ResultFile::CloseTask(
     const base::Closure& callback) {
   if (!file_)
     return;
 
   const char* trailevents = "]";
   size_t written = fwrite(trailevents, strlen(trailevents), 1, file_);
   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);
 
     written = fwrite(json_string.data(), json_string.size(), 1, file_);
     DCHECK(written == 1);
 
     system_trace_ = NULL;
   }
 
   const char* trailout = "}";
@@ skipping 84 matching lines @@
   if (pending_get_categories_done_callback_.is_null())
     TraceLog::GetInstance()->AddClockSyncMetadataEvent();
 #endif
 
   options_ = options;
   int trace_options = (options & RECORD_CONTINUOUSLY) ?
       TraceLog::RECORD_CONTINUOUSLY : TraceLog::RECORD_UNTIL_FULL;
   if (options & ENABLE_SAMPLING) {
     trace_options |= TraceLog::ENABLE_SAMPLING;
   }
+
 #if defined(OS_CHROMEOS)
   if (options & ENABLE_SYSTRACE) {
     DCHECK(!is_system_tracing_);
     chromeos::DBusThreadManager::Get()->GetDebugDaemonClient()->
       StartSystemTracing();
     is_system_tracing_ = true;
   }
 #endif
 
 #if defined(OS_WIN)
   if (options & ENABLE_SYSTRACE) {
     DCHECK(!is_system_tracing_);
-    is_system_tracing_ = true;
+    is_system_tracing_ =
+        EtwSystemEventConsumer::Get()->StartNTKernelSessionTracing();
+    EtwSystemEventConsumer::Get()->RequestStartSystemTracing();
   }
 #endif
 
   base::Closure on_enable_recording_done_callback =
       base::Bind(&TracingControllerImpl::OnEnableRecordingDone,
                  base::Unretained(this),
                  category_filter, trace_options, callback);
   BrowserThread::PostTask(BrowserThread::FILE, FROM_HERE,
       base::Bind(&TracingControllerImpl::SetEnabledOnFileThread,
                  base::Unretained(this),
@@ skipping 423 matching lines @@
     chromeos::DBusThreadManager::Get()->GetDebugDaemonClient()->
       RequestStopSystemTracing(
           base::Bind(&TracingControllerImpl::OnEndSystemTracingAcked,
                      base::Unretained(this)));
     return;
   }
 #endif
 
 #if defined(OS_WIN)
   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
 
   // Trigger callback if one is set.
   if (!pending_get_categories_done_callback_.is_null()) {
     pending_get_categories_done_callback_.Run(known_category_groups_);
     pending_get_categories_done_callback_.Reset();
   } else if (result_file_) {
     result_file_->Close(
         base::Bind(&TracingControllerImpl::OnResultFileClosed,
                    base::Unretained(this)));
   }
 }
 
 void TracingControllerImpl::OnResultFileClosed() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
   if (!result_file_)
     return;
 
   if (!pending_disable_recording_done_callback_.is_null()) {
     pending_disable_recording_done_callback_.Run(result_file_->path());
     pending_disable_recording_done_callback_.Reset();
   }
   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));
 
   if (result_file_)
     result_file_->WriteSystemTrace(events_str_ptr);
 
   DCHECK(!is_system_tracing_);
   OnDisableRecordingComplete();
 }
@@ skipping 170 matching lines @@
   is_monitoring_ = is_monitoring;
 #if !defined(OS_ANDROID)
   for (std::set<TracingUI*>::iterator it = tracing_uis_.begin();
        it != tracing_uis_.end(); it++) {
     (*it)->OnMonitoringStateChanged(is_monitoring);
   }
 #endif
 }
 
 }  // namespace content