content/browser/tracing/etw_system_event_consumer_win.cc

   1 // Copyright 2014 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "content/browser/tracing/etw_system_event_consumer_win.h"
   6
   7 #include "base/base64.h"
   8 #include "base/json/json_string_value_serializer.h"
   9 #include "base/lazy_instance.h"
  10 #include "base/memory/singleton.h"
  11 #include "base/strings/stringprintf.h"
  12 #include "base/time/time.h"
  13 #include "base/trace_event/trace_event_impl.h"
  14 #include "content/public/browser/browser_thread.h"
  15
  16 namespace content {
  17
  18 namespace {
  19
  20 const int kEtwBufferSizeInKBytes = 16;
  21 const int kEtwBufferFlushTimeoutInSeconds = 1;
  22
  23 std::string GuidToString(const GUID& guid) {
  24   return base::StringPrintf("%08X-%04X-%04X-%02X%02X-%02X%02X%02X%02X%02X%02X",
  25       guid.Data1, guid.Data2, guid.Data3,
  26       guid.Data4[0], guid.Data4[1], guid.Data4[2], guid.Data4[3],
  27       guid.Data4[4], guid.Data4[5], guid.Data4[6], guid.Data4[7]);
  28 }
  29
  30 }  // namespace
  31
  32 EtwSystemEventConsumer::EtwSystemEventConsumer()
  33     : thread_("EtwConsumerThread") {
  34 }
  35
  36 EtwSystemEventConsumer::~EtwSystemEventConsumer() {
  37 }
  38
  39 bool EtwSystemEventConsumer::StartSystemTracing() {
  40
  41   // Activate kernel tracing.
  42   if (!StartKernelSessionTracing())
  43     return false;
  44
  45   // Start the consumer thread and start consuming events.
  46   thread_.Start();
  47   thread_.message_loop()->PostTask(
  48       FROM_HERE,
  49       base::Bind(&EtwSystemEventConsumer::TraceAndConsumeOnThread,
  50                  base::Unretained(this)));
  51
  52   return true;
  53 }
  54
  55 void EtwSystemEventConsumer::StopSystemTracing(const OutputCallback& callback) {
  56   // Deactivate kernel tracing.
  57   if (!StopKernelSessionTracing()) {
  58     LOG(FATAL) << "Could not stop system tracing.";
  59   }
  60
  61   // Stop consuming and flush events.
  62   OutputCallback on_stop_system_tracing_done_callback =
  63       base::Bind(&EtwSystemEventConsumer::OnStopSystemTracingDone,
  64                  base::Unretained(this),
  65                  callback);
  66   thread_.message_loop()->PostTask(FROM_HERE,
  67       base::Bind(&EtwSystemEventConsumer::FlushOnThread,
  68                  base::Unretained(this), on_stop_system_tracing_done_callback));
  69 }
  70
  71 void EtwSystemEventConsumer::OnStopSystemTracingDone(
  72     const OutputCallback& callback,
  73     const scoped_refptr<base::RefCountedString>& result) {
  74
  75   // Stop the consumer thread.
  76   thread_.Stop();
  77
  78   // Pass the serialized events.
  79   callback.Run(result);
  80 }
  81
  82 bool EtwSystemEventConsumer::StartKernelSessionTracing() {
  83   // Enabled flags (tracing facilities).
  84   uint32 enabled_flags = EVENT_TRACE_FLAG_IMAGE_LOAD |
  85                          EVENT_TRACE_FLAG_PROCESS |
  86                          EVENT_TRACE_FLAG_THREAD |
  87                          EVENT_TRACE_FLAG_CSWITCH;
  88
  89   EVENT_TRACE_PROPERTIES& p = *properties_.get();
  90   p.LogFileMode = EVENT_TRACE_REAL_TIME_MODE;
  91   p.FlushTimer = kEtwBufferFlushTimeoutInSeconds;
  92   p.BufferSize = kEtwBufferSizeInKBytes;
  93   p.LogFileNameOffset = 0;
  94   p.EnableFlags = enabled_flags;
  95   p.Wnode.ClientContext = 1;  // QPC timer accuracy.
  96
  97   HRESULT hr = base::win::EtwTraceController::Start(
  98       KERNEL_LOGGER_NAME, &properties_, &session_handle_);
  99   if (FAILED(hr)) {
 100     VLOG(1) << "StartRealtimeSession() failed with " << hr << ".";
 101     return false;
 102   }
 103
 104   return true;
 105 }
 106
 107 bool EtwSystemEventConsumer::StopKernelSessionTracing() {
 108   HRESULT hr = base::win::EtwTraceController::Stop(
 109       KERNEL_LOGGER_NAME, &properties_);
 110   return SUCCEEDED(hr);
 111 }
 112
 113 // static
 114 EtwSystemEventConsumer* EtwSystemEventConsumer::GetInstance() {
 115   return Singleton<EtwSystemEventConsumer>::get();
 116 }
 117
 118 // static
 119 void EtwSystemEventConsumer::ProcessEvent(EVENT_TRACE* event) {
 120   EtwSystemEventConsumer::GetInstance()->AppendEventToBuffer(event);
 121 }
 122
 123 void EtwSystemEventConsumer::AddSyncEventToBuffer() {
 124   // Sync the clocks.
 125   base::Time walltime = base::Time::NowFromSystemTime();
 126   base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
 127
 128   LARGE_INTEGER walltime_in_us;
 129   walltime_in_us.QuadPart = walltime.ToInternalValue();
 130   LARGE_INTEGER now_in_us;
 131   now_in_us.QuadPart = now.ToInternalValue();
 132
 133   // Add fields to the event.
 134   scoped_ptr<base::DictionaryValue> value(new base::DictionaryValue());
 135   value->Set("guid", new base::StringValue("ClockSync"));
 136   value->Set("walltime", new base::StringValue(
 137       base::StringPrintf("%08X%08X",
 138                          walltime_in_us.HighPart,
 139                          walltime_in_us.LowPart)));
 140   value->Set("tick", new base::StringValue(
 141       base::StringPrintf("%08X%08X",
 142                          now_in_us.HighPart,
 143                          now_in_us.LowPart)));
 144
 145   // Append it to the events buffer.
 146   events_->Append(value.release());
 147 }
 148
 149 void EtwSystemEventConsumer::AppendEventToBuffer(EVENT_TRACE* event) {
 150   using base::FundamentalValue;
 151
 152   scoped_ptr<base::DictionaryValue> value(new base::DictionaryValue());
 153
 154   // Add header fields to the event.
 155   LARGE_INTEGER ts_us;
 156   ts_us.QuadPart = event->Header.TimeStamp.QuadPart / 10;
 157   value->Set("ts", new base::StringValue(
 158       base::StringPrintf("%08X%08X", ts_us.HighPart, ts_us.LowPart)));
 159
 160   value->Set("guid", new base::StringValue(GuidToString(event->Header.Guid)));
 161
 162   value->Set("op", new FundamentalValue(event->Header.Class.Type));
 163   value->Set("ver", new FundamentalValue(event->Header.Class.Version));
 164   value->Set("pid",
 165              new FundamentalValue(static_cast<int>(event->Header.ProcessId)));
 166   value->Set("tid",
 167              new FundamentalValue(static_cast<int>(event->Header.ThreadId)));
 168   value->Set("cpu", new FundamentalValue(event->BufferContext.ProcessorNumber));
 169
 170   // Base64 encode the payload bytes.
 171   base::StringPiece buffer(static_cast<const char*>(event->MofData),
 172                            event->MofLength);
 173   std::string payload;
 174   base::Base64Encode(buffer, &payload);
 175   value->Set("payload", new base::StringValue(payload));
 176
 177   // Append it to the events buffer.
 178   events_->Append(value.release());
 179 }
 180
 181 void EtwSystemEventConsumer::TraceAndConsumeOnThread() {
 182   // Create the events buffer.
 183   events_.reset(new base::ListValue());
 184
 185   // Output a clock sync event.
 186   AddSyncEventToBuffer();
 187
 188   HRESULT hr = OpenRealtimeSession(KERNEL_LOGGER_NAME);
 189   if (FAILED(hr))
 190     return;
 191   Consume();
 192   Close();
 193 }
 194
 195 void EtwSystemEventConsumer::FlushOnThread(const OutputCallback& callback) {
 196   // Add the header information to the stream.
 197   scoped_ptr<base::DictionaryValue> header(new base::DictionaryValue());
 198   header->Set("name", new base::StringValue("ETW"));
 199
 200   // Release and pass the events buffer.
 201   header->Set("content", events_.release());
 202
 203   // Serialize the results as a JSon string.
 204   std::string output;
 205   JSONStringValueSerializer serializer(&output);
 206   serializer.Serialize(*header.get());
 207
 208   // Pass the result to the UI Thread.
 209   scoped_refptr<base::RefCountedString> result =
 210       base::RefCountedString::TakeString(&output);
 211   BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
 212                           base::Bind(callback, result));
 213 }
 214
 215 }  // namespace content