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/debug/trace_event_impl.h"
9#include "base/json/json_string_value_serializer.h"
10#include "base/lazy_instance.h"
11#include "base/memory/singleton.h"
12#include "base/strings/stringprintf.h"
13#include "base/time/time.h"
14#include "content/public/browser/browser_thread.h"
15
16namespace content {
17
18namespace {
19
20const int kEtwBufferSizeInKBytes = 16;
21const int kEtwBufferFlushTimeoutInSeconds = 1;
22
23std::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
32EtwSystemEventConsumer::EtwSystemEventConsumer()
33    : thread_("EtwConsumerThread") {
34}
35
36EtwSystemEventConsumer::~EtwSystemEventConsumer() {
37}
38
39bool 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
55void 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
71void 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
82bool 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
107bool EtwSystemEventConsumer::StopKernelSessionTracing() {
108  HRESULT hr = base::win::EtwTraceController::Stop(
109      KERNEL_LOGGER_NAME, &properties_);
110  return SUCCEEDED(hr);
111}
112
113// static
114EtwSystemEventConsumer* EtwSystemEventConsumer::GetInstance() {
115  return Singleton<EtwSystemEventConsumer>::get();
116}
117
118// static
119void EtwSystemEventConsumer::ProcessEvent(EVENT_TRACE* event) {
120  EtwSystemEventConsumer::GetInstance()->AppendEventToBuffer(event);
121}
122
123void 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
149void 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
181void 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
195void 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
216