content/browser/tracing/etw_system_event_consumer_win.cc

// 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_system_event_consumer_win.h"

#include <stdint.h>

#include "base/base64.h"
#include "base/json/json_string_value_serializer.h"
#include "base/lazy_instance.h"
#include "base/memory/singleton.h"
#include "base/strings/stringprintf.h"
#include "base/time/time.h"
#include "base/trace_event/trace_event_impl.h"
#include "content/public/browser/browser_thread.h"

namespace content {

namespace {

const char kETWTracingAgentName[] = "etw";
const char kETWTraceLabel[] = "systemTraceEvents";

const int kEtwBufferSizeInKBytes = 16;
const int kEtwBufferFlushTimeoutInSeconds = 1;

std::string GuidToString(const GUID& guid) {
  return base::StringPrintf("%08X-%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

EtwSystemEventConsumer::EtwSystemEventConsumer()
    : thread_("EtwConsumerThread") {
}

EtwSystemEventConsumer::~EtwSystemEventConsumer() {
}

std::string EtwSystemEventConsumer::GetTracingAgentName() {
  return kETWTracingAgentName;
}

std::string EtwSystemEventConsumer::GetTraceEventLabel() {
  return kETWTraceLabel;
}

bool EtwSystemEventConsumer::StartAgentTracing(
    const base::trace_event::TraceConfig& trace_config) {
  // Activate kernel tracing.
  if (!StartKernelSessionTracing())
    return false;

  // Start the consumer thread and start consuming events.
  thread_.Start();
  thread_.message_loop()->PostTask(
      FROM_HERE,
      base::Bind(&EtwSystemEventConsumer::TraceAndConsumeOnThread,
                 base::Unretained(this)));

  return true;
}

void EtwSystemEventConsumer::StopAgentTracing(
    const StopAgentTracingCallback& callback) {
  // Deactivate kernel tracing.
  if (!StopKernelSessionTracing()) {
    LOG(FATAL) << "Could not stop system tracing.";
  }

  // Stop consuming and flush events.
  thread_.message_loop()->PostTask(FROM_HERE,
      base::Bind(&EtwSystemEventConsumer::FlushOnThread,
                 base::Unretained(this),
                 callback));
}

void EtwSystemEventConsumer::OnStopSystemTracingDone(
    const StopAgentTracingCallback& callback,
    const scoped_refptr<base::RefCountedString>& result) {

  // Stop the consumer thread.
  thread_.Stop();

  // Pass the serialized events.
  callback.Run(GetTracingAgentName(), GetTraceEventLabel(), result);
}

bool EtwSystemEventConsumer::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 EtwSystemEventConsumer::StopKernelSessionTracing() {
  HRESULT hr = base::win::EtwTraceController::Stop(
      KERNEL_LOGGER_NAME, &properties_);
  return SUCCEEDED(hr);
}

// static
EtwSystemEventConsumer* EtwSystemEventConsumer::GetInstance() {
  return base::Singleton<EtwSystemEventConsumer>::get();
}

// static
void EtwSystemEventConsumer::ProcessEvent(EVENT_TRACE* event) {
  EtwSystemEventConsumer::GetInstance()->AppendEventToBuffer(event);
}

void EtwSystemEventConsumer::AddSyncEventToBuffer() {
  // Sync the clocks.
  base::Time walltime = base::Time::NowFromSystemTime();
  base::TimeTicks now = base::TimeTicks::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.
  scoped_ptr<base::DictionaryValue> value(new base::DictionaryValue());
  value->Set("guid", new base::StringValue("ClockSync"));
  value->Set("walltime", new base::StringValue(
      base::StringPrintf("%08X%08X",
                         walltime_in_us.HighPart,
                         walltime_in_us.LowPart)));
  value->Set("tick", new base::StringValue(
      base::StringPrintf("%08X%08X",
                         now_in_us.HighPart,
                         now_in_us.LowPart)));

  // Append it to the events buffer.
  events_->Append(value.release());
}

void EtwSystemEventConsumer::AppendEventToBuffer(EVENT_TRACE* event) {
  using base::FundamentalValue;

  scoped_ptr<base::DictionaryValue> value(new base::DictionaryValue());

  // Add header fields to the event.
  LARGE_INTEGER ts_us;
  ts_us.QuadPart = event->Header.TimeStamp.QuadPart / 10;
  value->Set("ts", new base::StringValue(
      base::StringPrintf("%08X%08X", ts_us.HighPart, ts_us.LowPart)));

  value->Set("guid", new base::StringValue(GuidToString(event->Header.Guid)));

  value->Set("op", new FundamentalValue(event->Header.Class.Type));
  value->Set("ver", new FundamentalValue(event->Header.Class.Version));
  value->Set("pid",
             new FundamentalValue(static_cast<int>(event->Header.ProcessId)));
  value->Set("tid",
             new FundamentalValue(static_cast<int>(event->Header.ThreadId)));
  value->Set("cpu", new FundamentalValue(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->Set("payload", new base::StringValue(payload));

  // Append it to the events buffer.
  events_->Append(value.release());
}

void EtwSystemEventConsumer::TraceAndConsumeOnThread() {
  // 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 EtwSystemEventConsumer::FlushOnThread(
    const StopAgentTracingCallback& callback) {
  // Add the header information to the stream.
  scoped_ptr<base::DictionaryValue> header(new base::DictionaryValue());
  header->Set("name", new base::StringValue("ETW"));

  // Release and pass the events buffer.
  header->Set("content", events_.release());

  // Serialize the results as a JSon string.
  std::string output;
  JSONStringValueSerializer serializer(&output);
  serializer.Serialize(*header.get());

  // Pass the result to the UI Thread.
  scoped_refptr<base::RefCountedString> result =
      base::RefCountedString::TakeString(&output);
  BrowserThread::PostTask(
      BrowserThread::UI, FROM_HERE,
      base::Bind(&EtwSystemEventConsumer::OnStopSystemTracingDone,
                 base::Unretained(this),
                 callback,
                 result));
}

}  // namespace content