| // Copyright 2014 The Chromium Authors. All rights reserved. |
| // Use of this source code is governed by a BSD-style license that can be |
| // found in the LICENSE file. |
| |
| #include "content/browser/tracing/etw_tracing_agent_win.h" |
| |
| #include <stdint.h> |
| |
| #include <utility> |
| |
| #include "base/base64.h" |
| #include "base/json/json_string_value_serializer.h" |
| #include "base/lazy_instance.h" |
| #include "base/single_thread_task_runner.h" |
| #include "base/strings/stringprintf.h" |
| #include "base/task/post_task.h" |
| #include "base/threading/thread_task_runner_handle.h" |
| #include "base/time/time.h" |
| #include "base/trace_event/trace_config.h" |
| #include "base/trace_event/trace_event_impl.h" |
| #include "base/values.h" |
| #include "content/public/browser/browser_task_traits.h" |
| #include "content/public/browser/browser_thread.h" |
| #include "services/service_manager/public/cpp/connector.h" |
| |
| namespace content { |
| |
| namespace { |
| |
| EtwTracingAgent* g_etw_tracing_agent = nullptr; |
| |
| const char kETWTraceLabel[] = "systemTraceEvents"; |
| |
| const int kEtwBufferSizeInKBytes = 16; |
| const int kEtwBufferFlushTimeoutInSeconds = 1; |
| |
| std::string GuidToString(const GUID& guid) { |
| return base::StringPrintf("%08lX-%04X-%04X-%02X%02X-%02X%02X%02X%02X%02X%02X", |
| guid.Data1, guid.Data2, guid.Data3, guid.Data4[0], |
| guid.Data4[1], guid.Data4[2], guid.Data4[3], |
| guid.Data4[4], guid.Data4[5], guid.Data4[6], |
| guid.Data4[7]); |
| } |
| |
| } // namespace |
| |
| EtwTracingAgent::EtwTracingAgent(service_manager::Connector* connector) |
| : BaseAgent(connector, |
| kETWTraceLabel, |
| tracing::mojom::TraceDataType::OBJECT, |
| false /* supports_explicit_clock_sync */, |
| base::kNullProcessId), |
| tracing_task_runner_(base::CreateSequencedTaskRunnerWithTraits( |
| {base::MayBlock(), base::TaskPriority::USER_VISIBLE})), |
| is_tracing_(false) { |
| DCHECK(!g_etw_tracing_agent); |
| g_etw_tracing_agent = this; |
| } |
| |
| EtwTracingAgent::~EtwTracingAgent() { |
| if (is_tracing_) |
| StopKernelSessionTracing(); |
| g_etw_tracing_agent = nullptr; |
| } |
| |
| void EtwTracingAgent::StartTracing(const std::string& config, |
| base::TimeTicks coordinator_time, |
| Agent::StartTracingCallback callback) { |
| base::trace_event::TraceConfig trace_config(config); |
| // Activate kernel tracing. |
| if (!trace_config.IsSystraceEnabled() || !StartKernelSessionTracing()) { |
| std::move(callback).Run(false /* success */); |
| return; |
| } |
| is_tracing_ = true; |
| |
| // Tracing agents, e.g. this, live as long as BrowserMainLoop lives and so |
| // using base::Unretained here is safe. |
| tracing_task_runner_->PostTask( |
| FROM_HERE, |
| base::BindOnce(&EtwTracingAgent::TraceAndConsumeOnTracingSequence, |
| base::Unretained(this))); |
| std::move(callback).Run(true /* success */); |
| } |
| |
| void EtwTracingAgent::StopAndFlush(tracing::mojom::RecorderPtr recorder) { |
| DCHECK(is_tracing_); |
| // Deactivate kernel tracing. |
| if (!StopKernelSessionTracing()) { |
| LOG(FATAL) << "Could not stop system tracing."; |
| } |
| recorder_ = std::move(recorder); |
| // Stop consuming and flush events. Tracing agents, e.g. this, live as long as |
| // BrowserMainLoop lives and so using base::Unretained here is safe. |
| tracing_task_runner_->PostTask( |
| FROM_HERE, base::BindOnce(&EtwTracingAgent::FlushOnTracingSequence, |
| base::Unretained(this))); |
| } |
| |
| void EtwTracingAgent::OnStopSystemTracingDone(const std::string& output) { |
| recorder_->AddChunk(output); |
| recorder_.reset(); |
| is_tracing_ = false; |
| } |
| |
| bool EtwTracingAgent::StartKernelSessionTracing() { |
| // Enabled flags (tracing facilities). |
| uint32_t enabled_flags = EVENT_TRACE_FLAG_IMAGE_LOAD | |
| EVENT_TRACE_FLAG_PROCESS | EVENT_TRACE_FLAG_THREAD | |
| EVENT_TRACE_FLAG_CSWITCH; |
| |
| EVENT_TRACE_PROPERTIES& p = *properties_.get(); |
| p.LogFileMode = EVENT_TRACE_REAL_TIME_MODE; |
| p.FlushTimer = kEtwBufferFlushTimeoutInSeconds; |
| p.BufferSize = kEtwBufferSizeInKBytes; |
| p.LogFileNameOffset = 0; |
| p.EnableFlags = enabled_flags; |
| p.Wnode.ClientContext = 1; // QPC timer accuracy. |
| |
| HRESULT hr = base::win::EtwTraceController::Start( |
| KERNEL_LOGGER_NAME, &properties_, &session_handle_); |
| |
| // It's possible that a previous tracing session has been orphaned. If so |
| // try stopping and restarting it. |
| if (hr == HRESULT_FROM_WIN32(ERROR_ALREADY_EXISTS)) { |
| VLOG(1) << "Session already exists, stopping and restarting it."; |
| hr = base::win::EtwTraceController::Stop( |
| KERNEL_LOGGER_NAME, &properties_); |
| if (FAILED(hr)) { |
| VLOG(1) << "EtwTraceController::Stop failed with " << hr << "."; |
| return false; |
| } |
| |
| // The session was successfully shutdown so try to restart it. |
| hr = base::win::EtwTraceController::Start( |
| KERNEL_LOGGER_NAME, &properties_, &session_handle_); |
| } |
| |
| if (FAILED(hr)) { |
| VLOG(1) << "EtwTraceController::Start failed with " << hr << "."; |
| return false; |
| } |
| |
| return true; |
| } |
| |
| bool EtwTracingAgent::StopKernelSessionTracing() { |
| HRESULT hr = base::win::EtwTraceController::Stop( |
| KERNEL_LOGGER_NAME, &properties_); |
| return SUCCEEDED(hr); |
| } |
| |
| // static |
| EtwTracingAgent* EtwTracingAgent::GetInstance() { |
| return g_etw_tracing_agent; |
| } |
| |
| // static |
| void EtwTracingAgent::ProcessEvent(EVENT_TRACE* event) { |
| auto* instance = EtwTracingAgent::GetInstance(); |
| // Ignore events that are received after the browser is closed. |
| if (instance) |
| instance->AppendEventToBuffer(event); |
| } |
| |
| void EtwTracingAgent::AddSyncEventToBuffer() { |
| // Sync the clocks. |
| base::Time walltime = base::subtle::TimeNowFromSystemTimeIgnoringOverride(); |
| base::TimeTicks now = TRACE_TIME_TICKS_NOW(); |
| |
| LARGE_INTEGER walltime_in_us; |
| walltime_in_us.QuadPart = walltime.ToInternalValue(); |
| LARGE_INTEGER now_in_us; |
| now_in_us.QuadPart = now.ToInternalValue(); |
| |
| // Add fields to the event. |
| auto value = std::make_unique<base::DictionaryValue>(); |
| value->SetString("guid", "ClockSync"); |
| value->SetString("walltime", |
| base::StringPrintf("%08lX%08lX", walltime_in_us.HighPart, |
| walltime_in_us.LowPart)); |
| value->SetString("tick", base::StringPrintf("%08lX%08lX", now_in_us.HighPart, |
| now_in_us.LowPart)); |
| |
| // Append it to the events buffer. |
| events_->Append(std::move(value)); |
| } |
| |
| void EtwTracingAgent::AppendEventToBuffer(EVENT_TRACE* event) { |
| auto value = std::make_unique<base::DictionaryValue>(); |
| |
| // Add header fields to the event. |
| LARGE_INTEGER ts_us; |
| ts_us.QuadPart = event->Header.TimeStamp.QuadPart / 10; |
| value->SetString( |
| "ts", base::StringPrintf("%08lX%08lX", ts_us.HighPart, ts_us.LowPart)); |
| |
| value->SetString("guid", GuidToString(event->Header.Guid)); |
| |
| value->SetInteger("op", event->Header.Class.Type); |
| value->SetInteger("ver", event->Header.Class.Version); |
| value->SetInteger("pid", static_cast<int>(event->Header.ProcessId)); |
| value->SetInteger("tid", static_cast<int>(event->Header.ThreadId)); |
| value->SetInteger("cpu", event->BufferContext.ProcessorNumber); |
| |
| // Base64 encode the payload bytes. |
| base::StringPiece buffer(static_cast<const char*>(event->MofData), |
| event->MofLength); |
| std::string payload; |
| base::Base64Encode(buffer, &payload); |
| value->SetString("payload", payload); |
| |
| // Append it to the events buffer. |
| events_->Append(std::move(value)); |
| } |
| |
| void EtwTracingAgent::TraceAndConsumeOnTracingSequence() { |
| DCHECK(tracing_task_runner_->RunsTasksInCurrentSequence()); |
| |
| // Create the events buffer. |
| events_.reset(new base::ListValue()); |
| |
| // Output a clock sync event. |
| AddSyncEventToBuffer(); |
| |
| HRESULT hr = OpenRealtimeSession(KERNEL_LOGGER_NAME); |
| if (FAILED(hr)) |
| return; |
| Consume(); |
| Close(); |
| } |
| |
| void EtwTracingAgent::FlushOnTracingSequence() { |
| DCHECK(tracing_task_runner_->RunsTasksInCurrentSequence()); |
| |
| // Add the header information to the stream. |
| auto header = std::make_unique<base::DictionaryValue>(); |
| header->SetString("name", "ETW"); |
| |
| // Release and pass the events buffer. |
| header->Set("content", std::move(events_)); |
| |
| // Serialize the results as a JSon string. |
| std::string output; |
| JSONStringValueSerializer serializer(&output); |
| serializer.Serialize(*header.get()); |
| // TODO(chiniforooshan): Find a way to eliminate the extra string copy here. |
| // This is not too bad for now, since it happens only once when tracing is |
| // stopped. |
| DCHECK_EQ('{', output.front()); |
| DCHECK_EQ('}', output.back()); |
| output = output.substr(1, output.size() - 2); |
| |
| // Tracing agents, e.g. this, live as long as BrowserMainLoop lives and so |
| // using base::Unretained here is safe. |
| base::PostTaskWithTraits(FROM_HERE, {BrowserThread::UI}, |
| base::Bind(&EtwTracingAgent::OnStopSystemTracingDone, |
| base::Unretained(this), output)); |
| } |
| |
| } // namespace content |