| OLD | NEW |
| (Empty) |
| 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 <stdint.h> | |
| 8 | |
| 9 #include "base/base64.h" | |
| 10 #include "base/json/json_string_value_serializer.h" | |
| 11 #include "base/lazy_instance.h" | |
| 12 #include "base/memory/singleton.h" | |
| 13 #include "base/strings/stringprintf.h" | |
| 14 #include "base/thread_task_runner_handle.h" | |
| 15 #include "base/time/time.h" | |
| 16 #include "base/trace_event/trace_event_impl.h" | |
| 17 #include "content/public/browser/browser_thread.h" | |
| 18 | |
| 19 namespace content { | |
| 20 | |
| 21 namespace { | |
| 22 | |
| 23 const char kETWTracingAgentName[] = "etw"; | |
| 24 const char kETWTraceLabel[] = "systemTraceEvents"; | |
| 25 | |
| 26 const int kEtwBufferSizeInKBytes = 16; | |
| 27 const int kEtwBufferFlushTimeoutInSeconds = 1; | |
| 28 | |
| 29 std::string GuidToString(const GUID& guid) { | |
| 30 return base::StringPrintf("%08X-%04X-%04X-%02X%02X-%02X%02X%02X%02X%02X%02X", | |
| 31 guid.Data1, guid.Data2, guid.Data3, | |
| 32 guid.Data4[0], guid.Data4[1], guid.Data4[2], guid.Data4[3], | |
| 33 guid.Data4[4], guid.Data4[5], guid.Data4[6], guid.Data4[7]); | |
| 34 } | |
| 35 | |
| 36 } // namespace | |
| 37 | |
| 38 EtwSystemEventConsumer::EtwSystemEventConsumer() | |
| 39 : thread_("EtwConsumerThread") { | |
| 40 } | |
| 41 | |
| 42 EtwSystemEventConsumer::~EtwSystemEventConsumer() { | |
| 43 } | |
| 44 | |
| 45 std::string EtwSystemEventConsumer::GetTracingAgentName() { | |
| 46 return kETWTracingAgentName; | |
| 47 } | |
| 48 | |
| 49 std::string EtwSystemEventConsumer::GetTraceEventLabel() { | |
| 50 return kETWTraceLabel; | |
| 51 } | |
| 52 | |
| 53 void EtwSystemEventConsumer::StartAgentTracing( | |
| 54 const base::trace_event::TraceConfig& trace_config, | |
| 55 const StartAgentTracingCallback& callback) { | |
| 56 // Activate kernel tracing. | |
| 57 if (!StartKernelSessionTracing()) { | |
| 58 base::ThreadTaskRunnerHandle::Get()->PostTask( | |
| 59 FROM_HERE, | |
| 60 base::Bind(callback, GetTracingAgentName(), false /* success */)); | |
| 61 return; | |
| 62 } | |
| 63 | |
| 64 // Start the consumer thread and start consuming events. | |
| 65 thread_.Start(); | |
| 66 thread_.message_loop()->PostTask( | |
| 67 FROM_HERE, | |
| 68 base::Bind(&EtwSystemEventConsumer::TraceAndConsumeOnThread, | |
| 69 base::Unretained(this))); | |
| 70 | |
| 71 base::ThreadTaskRunnerHandle::Get()->PostTask( | |
| 72 FROM_HERE, | |
| 73 base::Bind(callback, GetTracingAgentName(), true /* success */)); | |
| 74 } | |
| 75 | |
| 76 void EtwSystemEventConsumer::StopAgentTracing( | |
| 77 const StopAgentTracingCallback& callback) { | |
| 78 // Deactivate kernel tracing. | |
| 79 if (!StopKernelSessionTracing()) { | |
| 80 LOG(FATAL) << "Could not stop system tracing."; | |
| 81 } | |
| 82 | |
| 83 // Stop consuming and flush events. | |
| 84 thread_.message_loop()->PostTask(FROM_HERE, | |
| 85 base::Bind(&EtwSystemEventConsumer::FlushOnThread, | |
| 86 base::Unretained(this), | |
| 87 callback)); | |
| 88 } | |
| 89 | |
| 90 void EtwSystemEventConsumer::OnStopSystemTracingDone( | |
| 91 const StopAgentTracingCallback& callback, | |
| 92 const scoped_refptr<base::RefCountedString>& result) { | |
| 93 | |
| 94 // Stop the consumer thread. | |
| 95 thread_.Stop(); | |
| 96 | |
| 97 // Pass the serialized events. | |
| 98 callback.Run(GetTracingAgentName(), GetTraceEventLabel(), result); | |
| 99 } | |
| 100 | |
| 101 bool EtwSystemEventConsumer::StartKernelSessionTracing() { | |
| 102 // Enabled flags (tracing facilities). | |
| 103 uint32_t enabled_flags = EVENT_TRACE_FLAG_IMAGE_LOAD | | |
| 104 EVENT_TRACE_FLAG_PROCESS | EVENT_TRACE_FLAG_THREAD | | |
| 105 EVENT_TRACE_FLAG_CSWITCH; | |
| 106 | |
| 107 EVENT_TRACE_PROPERTIES& p = *properties_.get(); | |
| 108 p.LogFileMode = EVENT_TRACE_REAL_TIME_MODE; | |
| 109 p.FlushTimer = kEtwBufferFlushTimeoutInSeconds; | |
| 110 p.BufferSize = kEtwBufferSizeInKBytes; | |
| 111 p.LogFileNameOffset = 0; | |
| 112 p.EnableFlags = enabled_flags; | |
| 113 p.Wnode.ClientContext = 1; // QPC timer accuracy. | |
| 114 | |
| 115 HRESULT hr = base::win::EtwTraceController::Start( | |
| 116 KERNEL_LOGGER_NAME, &properties_, &session_handle_); | |
| 117 | |
| 118 // It's possible that a previous tracing session has been orphaned. If so | |
| 119 // try stopping and restarting it. | |
| 120 if (hr == HRESULT_FROM_WIN32(ERROR_ALREADY_EXISTS)) { | |
| 121 VLOG(1) << "Session already exists, stopping and restarting it."; | |
| 122 hr = base::win::EtwTraceController::Stop( | |
| 123 KERNEL_LOGGER_NAME, &properties_); | |
| 124 if (FAILED(hr)) { | |
| 125 VLOG(1) << "EtwTraceController::Stop failed with " << hr << "."; | |
| 126 return false; | |
| 127 } | |
| 128 | |
| 129 // The session was successfully shutdown so try to restart it. | |
| 130 hr = base::win::EtwTraceController::Start( | |
| 131 KERNEL_LOGGER_NAME, &properties_, &session_handle_); | |
| 132 } | |
| 133 | |
| 134 if (FAILED(hr)) { | |
| 135 VLOG(1) << "EtwTraceController::Start failed with " << hr << "."; | |
| 136 return false; | |
| 137 } | |
| 138 | |
| 139 return true; | |
| 140 } | |
| 141 | |
| 142 bool EtwSystemEventConsumer::StopKernelSessionTracing() { | |
| 143 HRESULT hr = base::win::EtwTraceController::Stop( | |
| 144 KERNEL_LOGGER_NAME, &properties_); | |
| 145 return SUCCEEDED(hr); | |
| 146 } | |
| 147 | |
| 148 // static | |
| 149 EtwSystemEventConsumer* EtwSystemEventConsumer::GetInstance() { | |
| 150 return base::Singleton<EtwSystemEventConsumer>::get(); | |
| 151 } | |
| 152 | |
| 153 // static | |
| 154 void EtwSystemEventConsumer::ProcessEvent(EVENT_TRACE* event) { | |
| 155 EtwSystemEventConsumer::GetInstance()->AppendEventToBuffer(event); | |
| 156 } | |
| 157 | |
| 158 void EtwSystemEventConsumer::AddSyncEventToBuffer() { | |
| 159 // Sync the clocks. | |
| 160 base::Time walltime = base::Time::NowFromSystemTime(); | |
| 161 base::TimeTicks now = base::TimeTicks::Now(); | |
| 162 | |
| 163 LARGE_INTEGER walltime_in_us; | |
| 164 walltime_in_us.QuadPart = walltime.ToInternalValue(); | |
| 165 LARGE_INTEGER now_in_us; | |
| 166 now_in_us.QuadPart = now.ToInternalValue(); | |
| 167 | |
| 168 // Add fields to the event. | |
| 169 std::unique_ptr<base::DictionaryValue> value(new base::DictionaryValue()); | |
| 170 value->Set("guid", new base::StringValue("ClockSync")); | |
| 171 value->Set("walltime", new base::StringValue( | |
| 172 base::StringPrintf("%08X%08X", | |
| 173 walltime_in_us.HighPart, | |
| 174 walltime_in_us.LowPart))); | |
| 175 value->Set("tick", new base::StringValue( | |
| 176 base::StringPrintf("%08X%08X", | |
| 177 now_in_us.HighPart, | |
| 178 now_in_us.LowPart))); | |
| 179 | |
| 180 // Append it to the events buffer. | |
| 181 events_->Append(value.release()); | |
| 182 } | |
| 183 | |
| 184 void EtwSystemEventConsumer::AppendEventToBuffer(EVENT_TRACE* event) { | |
| 185 using base::FundamentalValue; | |
| 186 | |
| 187 std::unique_ptr<base::DictionaryValue> value(new base::DictionaryValue()); | |
| 188 | |
| 189 // Add header fields to the event. | |
| 190 LARGE_INTEGER ts_us; | |
| 191 ts_us.QuadPart = event->Header.TimeStamp.QuadPart / 10; | |
| 192 value->Set("ts", new base::StringValue( | |
| 193 base::StringPrintf("%08X%08X", ts_us.HighPart, ts_us.LowPart))); | |
| 194 | |
| 195 value->Set("guid", new base::StringValue(GuidToString(event->Header.Guid))); | |
| 196 | |
| 197 value->Set("op", new FundamentalValue(event->Header.Class.Type)); | |
| 198 value->Set("ver", new FundamentalValue(event->Header.Class.Version)); | |
| 199 value->Set("pid", | |
| 200 new FundamentalValue(static_cast<int>(event->Header.ProcessId))); | |
| 201 value->Set("tid", | |
| 202 new FundamentalValue(static_cast<int>(event->Header.ThreadId))); | |
| 203 value->Set("cpu", new FundamentalValue(event->BufferContext.ProcessorNumber)); | |
| 204 | |
| 205 // Base64 encode the payload bytes. | |
| 206 base::StringPiece buffer(static_cast<const char*>(event->MofData), | |
| 207 event->MofLength); | |
| 208 std::string payload; | |
| 209 base::Base64Encode(buffer, &payload); | |
| 210 value->Set("payload", new base::StringValue(payload)); | |
| 211 | |
| 212 // Append it to the events buffer. | |
| 213 events_->Append(value.release()); | |
| 214 } | |
| 215 | |
| 216 void EtwSystemEventConsumer::TraceAndConsumeOnThread() { | |
| 217 // Create the events buffer. | |
| 218 events_.reset(new base::ListValue()); | |
| 219 | |
| 220 // Output a clock sync event. | |
| 221 AddSyncEventToBuffer(); | |
| 222 | |
| 223 HRESULT hr = OpenRealtimeSession(KERNEL_LOGGER_NAME); | |
| 224 if (FAILED(hr)) | |
| 225 return; | |
| 226 Consume(); | |
| 227 Close(); | |
| 228 } | |
| 229 | |
| 230 void EtwSystemEventConsumer::FlushOnThread( | |
| 231 const StopAgentTracingCallback& callback) { | |
| 232 // Add the header information to the stream. | |
| 233 std::unique_ptr<base::DictionaryValue> header(new base::DictionaryValue()); | |
| 234 header->Set("name", new base::StringValue("ETW")); | |
| 235 | |
| 236 // Release and pass the events buffer. | |
| 237 header->Set("content", events_.release()); | |
| 238 | |
| 239 // Serialize the results as a JSon string. | |
| 240 std::string output; | |
| 241 JSONStringValueSerializer serializer(&output); | |
| 242 serializer.Serialize(*header.get()); | |
| 243 | |
| 244 // Pass the result to the UI Thread. | |
| 245 scoped_refptr<base::RefCountedString> result = | |
| 246 base::RefCountedString::TakeString(&output); | |
| 247 BrowserThread::PostTask( | |
| 248 BrowserThread::UI, FROM_HERE, | |
| 249 base::Bind(&EtwSystemEventConsumer::OnStopSystemTracingDone, | |
| 250 base::Unretained(this), | |
| 251 callback, | |
| 252 result)); | |
| 253 } | |
| 254 | |
| 255 } // namespace content | |
| OLD | NEW |