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
 100   // It's possible that a previous tracing session has been orphaned. If so
 101   // try stopping and restarting it.
 102   if (hr == HRESULT_FROM_WIN32(ERROR_ALREADY_EXISTS)) {
 103     VLOG(1) << "Session already exists, stopping and restarting it.";
 104     hr = base::win::EtwTraceController::Stop(
 105         KERNEL_LOGGER_NAME, &properties_);
 106     if (FAILED(hr)) {
 107       VLOG(1) << "EtwTraceController::Stop failed with " << hr << ".";
 108       return false;
 109     }
 110
 111     // The session was successfully shutdown so try to restart it.
 112     hr = base::win::EtwTraceController::Start(
 113         KERNEL_LOGGER_NAME, &properties_, &session_handle_);
 114   }
 115
 116   if (FAILED(hr)) {
 117     VLOG(1) << "EtwTraceController::Start failed with " << hr << ".";
 118     return false;
 119   }
 120
 121   return true;
 122 }
 123
 124 bool EtwSystemEventConsumer::StopKernelSessionTracing() {
 125   HRESULT hr = base::win::EtwTraceController::Stop(
 126       KERNEL_LOGGER_NAME, &properties_);
 127   return SUCCEEDED(hr);
 128 }
 129
 130 // static
 131 EtwSystemEventConsumer* EtwSystemEventConsumer::GetInstance() {
 132   return Singleton<EtwSystemEventConsumer>::get();
 133 }
 134
 135 // static
 136 void EtwSystemEventConsumer::ProcessEvent(EVENT_TRACE* event) {
 137   EtwSystemEventConsumer::GetInstance()->AppendEventToBuffer(event);
 138 }
 139
 140 void EtwSystemEventConsumer::AddSyncEventToBuffer() {
 141   // Sync the clocks.
 142   base::Time walltime = base::Time::NowFromSystemTime();
 143   base::TimeTicks now = base::TimeTicks::NowFromSystemTraceTime();
 144
 145   LARGE_INTEGER walltime_in_us;
 146   walltime_in_us.QuadPart = walltime.ToInternalValue();
 147   LARGE_INTEGER now_in_us;
 148   now_in_us.QuadPart = now.ToInternalValue();
 149
 150   // Add fields to the event.
 151   scoped_ptr<base::DictionaryValue> value(new base::DictionaryValue());
 152   value->Set("guid", new base::StringValue("ClockSync"));
 153   value->Set("walltime", new base::StringValue(
 154       base::StringPrintf("%08X%08X",
 155                          walltime_in_us.HighPart,
 156                          walltime_in_us.LowPart)));
 157   value->Set("tick", new base::StringValue(
 158       base::StringPrintf("%08X%08X",
 159                          now_in_us.HighPart,
 160                          now_in_us.LowPart)));
 161
 162   // Append it to the events buffer.
 163   events_->Append(value.release());
 164 }
 165
 166 void EtwSystemEventConsumer::AppendEventToBuffer(EVENT_TRACE* event) {
 167   using base::FundamentalValue;
 168
 169   scoped_ptr<base::DictionaryValue> value(new base::DictionaryValue());
 170
 171   // Add header fields to the event.
 172   LARGE_INTEGER ts_us;
 173   ts_us.QuadPart = event->Header.TimeStamp.QuadPart / 10;
 174   value->Set("ts", new base::StringValue(
 175       base::StringPrintf("%08X%08X", ts_us.HighPart, ts_us.LowPart)));
 176
 177   value->Set("guid", new base::StringValue(GuidToString(event->Header.Guid)));
 178
 179   value->Set("op", new FundamentalValue(event->Header.Class.Type));
 180   value->Set("ver", new FundamentalValue(event->Header.Class.Version));
 181   value->Set("pid",
 182              new FundamentalValue(static_cast<int>(event->Header.ProcessId)));
 183   value->Set("tid",
 184              new FundamentalValue(static_cast<int>(event->Header.ThreadId)));
 185   value->Set("cpu", new FundamentalValue(event->BufferContext.ProcessorNumber));
 186
 187   // Base64 encode the payload bytes.
 188   base::StringPiece buffer(static_cast<const char*>(event->MofData),
 189                            event->MofLength);
 190   std::string payload;
 191   base::Base64Encode(buffer, &payload);
 192   value->Set("payload", new base::StringValue(payload));
 193
 194   // Append it to the events buffer.
 195   events_->Append(value.release());
 196 }
 197
 198 void EtwSystemEventConsumer::TraceAndConsumeOnThread() {
 199   // Create the events buffer.
 200   events_.reset(new base::ListValue());
 201
 202   // Output a clock sync event.
 203   AddSyncEventToBuffer();
 204
 205   HRESULT hr = OpenRealtimeSession(KERNEL_LOGGER_NAME);
 206   if (FAILED(hr))
 207     return;
 208   Consume();
 209   Close();
 210 }
 211
 212 void EtwSystemEventConsumer::FlushOnThread(const OutputCallback& callback) {
 213   // Add the header information to the stream.
 214   scoped_ptr<base::DictionaryValue> header(new base::DictionaryValue());
 215   header->Set("name", new base::StringValue("ETW"));
 216
 217   // Release and pass the events buffer.
 218   header->Set("content", events_.release());
 219
 220   // Serialize the results as a JSon string.
 221   std::string output;
 222   JSONStringValueSerializer serializer(&output);
 223   serializer.Serialize(*header.get());
 224
 225   // Pass the result to the UI Thread.
 226   scoped_refptr<base::RefCountedString> result =
 227       base::RefCountedString::TakeString(&output);
 228   BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
 229                           base::Bind(callback, result));
 230 }
 231
 232 }  // namespace content