root/content/browser/tracing/etw_system_event_consumer_win.cc

DEFINITIONS

1. GuidToString
2. StartSystemTracing
3. StopSystemTracing
4. OnStopSystemTracingDone
5. StartKernelSessionTracing
6. StopKernelSessionTracing
7. GetInstance
8. ProcessEvent
9. AddSyncEventToBuffer
10. AppendEventToBuffer
11. TraceAndConsumeOnThread
12. FlushOnThread

// 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 "base/base64.h"
#include "base/debug/trace_event_impl.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 "content/public/browser/browser_thread.h"

namespace content {

namespace {

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() {
}

bool EtwSystemEventConsumer::StartSystemTracing() {

  // 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::StopSystemTracing(const OutputCallback& callback) {
  // Deactivate kernel tracing.
  if (!StopKernelSessionTracing()) {
    LOG(FATAL) << "Could not stop system tracing.";
  }

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

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

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

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

bool EtwSystemEventConsumer::StartKernelSessionTracing() {
  // Enabled flags (tracing facilities).
  uint32 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_);
  if (FAILED(hr)) {
    VLOG(1) << "StartRealtimeSession() 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 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::NowFromSystemTraceTime();

  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 OutputCallback& callback) {
  // Add the header information to the stream.
  scoped_ptr<base::DictionaryValue> header(new base::DictionaryValue());
  header->Set("name", base::Value::CreateStringValue("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(callback, result));
}

}  // namespace content