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 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", base::Value::CreateStringValue("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
