calltracemanager.cc

Go to the documentation of this file.

#include "ion/profile/calltracemanager.h"

#include <fstream>  // NOLINT

#include "ion/analytics/benchmark.h"
#include "ion/analytics/benchmarkutils.h"
#include "ion/base/serialize.h"
#include "ion/base/stringutils.h"
#include "ion/port/threadutils.h"
#include "ion/profile/timelinenode.h"
#include "ion/profile/timelinethread.h"
#include "ion/profile/tracerecorder.h"
#include "third_party/jsoncpp/include/json/json.h"

namespace ion {
namespace profile {

namespace {

struct ChunkInfo {
  uint32 id;
  uint32 type;
  uint32 length;
  uint32 start_time;
  uint32 end_time;
  uint32 part_count;
};

struct PartInfo {
  uint32 type;
  uint32 offset;
  uint32 length;
};

static uint32 UpToNearestFour(uint32 n) {
  if (n % 4 == 0) {
    return n;
  }
  return n + (4 - (n % 4));
}

class Part {
 public:
  virtual ~Part() {}

  virtual uint32 GetRawSizeInBytes() const = 0;

  virtual void AppendToString(std::string* output) const = 0;

  uint32 GetAlignedSizeInBytes() const {
    return UpToNearestFour(GetRawSizeInBytes());
  }
};

struct Chunk {
  void AddPart(uint32 type, Part* part) {
    DCHECK(part);

    PartInfo info;
    info.type = type;
    info.length = part->GetRawSizeInBytes();
    info.offset = 0;
    for (size_t i = 0; i < parts.size(); i++) {
      info.offset += parts[i]->GetAlignedSizeInBytes();
    }
    part_headers.push_back(info);
    parts.push_back(part);
  }

  void AppendToString(uint32 id, uint32 type, std::string* output) {
    DCHECK(parts.size() == part_headers.size());

    ChunkInfo info;
    info.part_count = static_cast<uint32>(parts.size());
    info.id = id;
    info.type = type;
    info.length = static_cast<uint32>(sizeof(ChunkInfo)) +
        static_cast<uint32>(sizeof(PartInfo)) * info.part_count;
    for (size_t i = 0; i < parts.size(); i++) {
      info.length += parts[i]->GetAlignedSizeInBytes();
    }
    info.start_time = -1;
    info.end_time = -1;

    base::AppendBytes(output, info);
    for (size_t i = 0; i < part_headers.size(); i++) {
      base::AppendBytes(output, part_headers[i]);
    }
    for (size_t i = 0; i < parts.size(); i++) {
      parts[i]->AppendToString(output);
    }
  }

  std::vector<PartInfo> part_headers;
  std::vector<Part*> parts;
};

class StringTable : public Part {
 public:
  StringTable()
      : include_null_(true) {}

  explicit StringTable(bool include_null)
      : include_null_(include_null) {}

  void AddString(const std::string& str) {
    const std::vector<std::string> split = base::SplitString(str, "\n");
    for (size_t i = 0; i < split.size(); ++i) {
      table_.push_back(split[i]);
    }
  }

  uint32 GetRawSizeInBytes() const override {
    size_t raw_size_in_bytes = 0;
    for (size_t i = 0; i < table_.size(); ++i) {
      const size_t string_length = table_[i].length();
      if (include_null_) {
        raw_size_in_bytes += string_length + 1;
      } else {
        raw_size_in_bytes += string_length;
      }
    }
    return static_cast<uint32>(raw_size_in_bytes);
  }

  uint32 GetTableSize() const { return static_cast<uint32>(table_.size()); }

  void AppendToString(std::string* output) const override {
    for (size_t i = 0; i < table_.size(); ++i) {
      output->append(table_[i]);
      if (include_null_) {
        char ch = 0;
        base::AppendBytes(output, ch);
      }
    }

    uint32 extra = GetAlignedSizeInBytes() - GetRawSizeInBytes();
    for (uint32 i = 0; i < extra; ++i) {
      char ch = 0;
      base::AppendBytes(output, ch);
    }
  }

  std::vector<std::string>* GetMutableTable() { return &table_; }

 private:
  std::vector<std::string> table_;
  const bool include_null_;
};

struct EventBuffer : public Part {
 public:
  uint32 GetRawSizeInBytes() const override {
    return static_cast<uint32>(buffer.length());
  }

  void AppendToString(std::string* output) const override {
    output->append(buffer);
  }

  std::string buffer;
};

}  // namespace

ScopedTracer::ScopedTracer(TraceRecorder* recorder, int id)
    : recorder_(recorder) {
  DCHECK(recorder_ && id);
  recorder_->EnterScope(id);
}

ScopedTracer::~ScopedTracer() {
  DCHECK(recorder_);
  recorder_->LeaveScope();
}

ScopedFrameTracer::ScopedFrameTracer(TraceRecorder* recorder, uint32 id)
    : recorder_(recorder) {
  DCHECK(recorder_);
  recorder_->EnterFrame(id);
}

ScopedFrameTracer::~ScopedFrameTracer() {
  DCHECK(recorder_);
  recorder_->LeaveFrame();
}

CallTraceManager::CallTraceManager()
    : trace_recorder_(GetAllocator()),
      named_trace_recorders_(GetAllocator()),
      recorder_list_(GetAllocator()),
      buffer_size_(0),
      scope_event_map_(GetAllocator()),
      reverse_scope_event_map_(GetAllocator()) {
}

CallTraceManager::CallTraceManager(size_t buffer_size)
    : trace_recorder_(GetAllocator()),
      named_trace_recorders_(GetAllocator()),
      recorder_list_(GetAllocator()),
      buffer_size_(buffer_size),
      scope_event_map_(GetAllocator()),
      reverse_scope_event_map_(GetAllocator()) {
}

CallTraceManager::~CallTraceManager() {
  base::LockGuard lock(&mutex_);

  if (!timeline_metrics_.empty()) {
    ion::analytics::Benchmark benchmark = RunTimelineMetrics();
    ion::analytics::OutputBenchmarkPretty("Timeline Metrics", false, benchmark,
                                          std::cout);
  }

  for (size_t i = 0; i < recorder_list_.size(); ++i) {
    delete recorder_list_[i];
    recorder_list_[i] = NULL;
  }
}

TraceRecorder* CallTraceManager::GetTraceRecorder() {
  void* ptr = port::GetThreadLocalStorage(trace_recorder_.GetKey());
  if (ptr) {
    return *static_cast<TraceRecorder**>(ptr);
  } else {
    TraceRecorder** recorder = trace_recorder_.Get();
    *recorder = AllocateTraceRecorder();
    return *recorder;
  }
}

TraceRecorder* CallTraceManager::GetNamedTraceRecorder(
    NamedTraceRecorderType name) {
  DCHECK(name < kNumNamedTraceRecorders);
  NamedTraceRecorderArray* recorders = named_trace_recorders_.Get();
  TraceRecorder* recorder = recorders->recorders[name];
  if (recorder) {
    return recorder;
  }
  recorder = AllocateTraceRecorder();
  switch (name) {
    case kRecorderGpu:
      recorder->SetThreadName("GPU");
      break;
    case kRecorderVSync:
      recorder->SetThreadName("VSync");
      break;
    default:
      LOG(WARNING) << "Unknown name(" << name << ") for named TraceRecorder.";
  }
  recorders->recorders[name] = recorder;
  return recorder;
}

TraceRecorder* CallTraceManager::AllocateTraceRecorder() {
  TraceRecorder* recorder = NULL;
  if (buffer_size_ == 0) {
    recorder = new (GetAllocator()) TraceRecorder(this);
  } else {
    recorder = new (GetAllocator()) TraceRecorder(this, buffer_size_);
  }
  {
    base::LockGuard lock(&mutex_);
    recorder_list_.push_back(recorder);
  }
  return recorder;
}

int CallTraceManager::GetScopeEnterEvent(const char* string_id) {
  base::LockGuard lock(&mutex_);

  ScopeEventMap::const_iterator it = scope_event_map_.find(string_id);
  if (it != scope_event_map_.end()) {
    return it->second;
  }

  const int new_event_id =
      static_cast<int>(kCustomScopeEvent + GetNumScopeEvents());
  scope_event_map_.insert(
      std::make_pair(static_cast<const void*>(string_id), new_event_id));
  reverse_scope_event_map_.insert(std::make_pair(new_event_id, string_id));
  return new_event_id;
}

const char* CallTraceManager::GetScopeEnterEventName(uint32 event_id) const {
  return reverse_scope_event_map_.at(event_id);
}

int CallTraceManager::GetNumArgsForEvent(uint32 event_id) {
  static const int kBuiltinEventArgNum[] = {
      0, 5, 0, 4, 1, 1, 1, 0, 0, 2, 2, 2, 3, 1, 1, 1, 1, 1};
  if (event_id >= kCustomScopeEvent) {
    event_id = 0;
  }
  return kBuiltinEventArgNum[event_id];
}

CallTraceManager::EventArgType CallTraceManager::GetArgType(
    uint32 event_id, int arg_index) {
  CHECK(event_id < kCustomScopeEvent);

  static const int kOffsetTable[] = {
      0, 1, 6, 7, 11, 12, 13, 14, 15, 16, 18, 20, 22, 25, 26, 27, 28, 29};

  static const EventArgType kBuiltinEventArgTypes[] = {
      kArgNone,  // The zeroth event is reserved and has no arguments.
      kArgNumeric, kArgNumeric, kArgNumeric, kArgString, kArgString,
      kArgNone,
      kArgNumeric, kArgString, kArgString, kArgString,
      kArgNumeric,
      kArgNumeric,
      kArgString,
      kArgNone,
      kArgNone,
      kArgString, kArgString,
      kArgString, kArgString,
      kArgString, kArgString,
      kArgNumeric, kArgString, kArgString,
      kArgNumeric,
      kArgNumeric,
      kArgNumeric,
      kArgString,
      kArgNumeric};

  return kBuiltinEventArgTypes[kOffsetTable[event_id] + arg_index];
}

std::string CallTraceManager::SnapshotCallTraces() const {
  std::string output;

  static const uint32 magic_number = 0xdeadbeef;
  static const uint32 wtf_version = 0xe8214400;
  static const uint32 format_version = 10;

  base::AppendBytes(&output, magic_number);
  base::AppendBytes(&output, wtf_version);
  base::AppendBytes(&output, format_version);

  Json::Value flags(Json::arrayValue);
  flags.append("has_high_resolution_times");

  Json::Value icon(Json::objectValue);
  icon["uri"] = "https://maps.gstatic.com/favicon3.ico";

  Json::Value agent(Json::objectValue);
  agent["device"] = "Ion";
  agent["platform"] = "SomePlatform";
  agent["platformVersion"] = "";
  agent["type"] = "";
  agent["value"] = "";

  Json::Value context(Json::objectValue);
  context["args"] = Json::Value(Json::arrayValue);
  context["contextType"] = "script";
  context["icon"] = icon;
  context["taskId"] = "";
  context["title"] = "Ion";
  context["userAgent"] = agent;

  Json::Value json;
  json["type"] = "file_header";
  json["flags"] = flags;
  json["timebase"] = 1412611454780.701;
  json["contextInfo"] = context;

  Json::FastWriter json_writer;
  std::string json_string = json_writer.write(json);
  StringTable file_header_table(false);
  file_header_table.AddString(json_string);

  Chunk file_header;
  file_header.AddPart(0x10000, &file_header_table);
  file_header.AppendToString(2, 0x1, &output);


  StringTable def_table;
  def_table.AddString(
      "wtf.event#define\n"
      "uint16 wireId, uint16 eventClass, uint32 flags, ascii name, ascii args\n"
      "wtf.trace#discontinuity\n"
      "wtf.zone#create\n"
      "uint16 zoneId, ascii name, ascii type, ascii location\n"
      "wtf.zone#delete\n"
      "uint16 zoneId\n"
      "wtf.zone#set\n"
      "uint16 zoneId\n"
      "wtf.scope#enter\n"
      "ascii name\n"
      "wtf.scope#enterTracing\n"
      "wtf.scope#leave\n"
      "wtf.scope#appendData\n"
      "ascii name, any value\n"
      "wtf.trace#mark\n"
      "ascii name, any value\n"
      "wtf.trace#timeStamp\n"
      "ascii name, any value\n"
      "wtf.timeRange#begin\n"
      "uint32 id, ascii name, any value\n"
      "wtf.timeRange#end\n"
      "uint32 id\n"
      "wtf.timing#frameStart\n"
      "uint32 number\n"
      "wtf.timing#frameEnd\n"
      "uint32 number\n"
      "wtf.scope#appendData_url_utf8\n"
      "utf8 url\n"
      "wtf.scope#appendData_readyState_int32\n"
      "int32 readyState");

  const uint32 event_string_offset = def_table.GetTableSize();
  for (ScopeEventMap::const_iterator it = scope_event_map_.begin();
       it != scope_event_map_.end(); ++it) {
    def_table.AddString(reinterpret_cast<const char*>(it->first));
  }


  EventBuffer def_events;
  {
    std::string* event_buffer = &def_events.buffer;
    uint32 builtin[] = {
        1, 0, 1, 0, 40, 0, 1,
        1, 0, 2, 0, 32, 2, 0xffffffff,
        1, 0, 3, 0, 40, 3, 4,
        1, 0, 4, 0, 40, 5, 6,
        1, 0, 5, 0, 40, 7, 8,
        1, 0, 6, 1, 32, 9, 10,
        1, 0, 7, 1, 44, 11, 0xffffffff,
        1, 0, 8, 0, 40, 12, 0xffffffff,
        1, 0, 9, 0, 56, 13, 14,
        1, 0, 10, 0, 40, 15, 16,
        1, 0, 11, 0, 32, 17, 18,
        1, 0, 12, 0, 40, 19, 20,
        1, 0, 13, 0, 40, 21, 22,
        1, 0, 14, 0, 8, 23, 24,
        1, 0, 15, 0, 8, 25, 26,
        1, 0, 16, 0, 24, 27, 28,
        1, 0, 17, 0, 24, 29, 30
    };
    base::AppendBytes(event_buffer, builtin);

    {
      int event_counter = 0;
      uint32 temp;
      for (ScopeEventMap::const_iterator it = scope_event_map_.begin();
           it != scope_event_map_.end(); ++it) {
        temp = kDefineEvent;
        base::AppendBytes(event_buffer, temp);  // wtf.event#define
        temp = 0;
        base::AppendBytes(event_buffer, temp);  // timestamp
        temp = it->second;
        base::AppendBytes(event_buffer, temp);  // wireId
        temp = 1;
        base::AppendBytes(event_buffer, temp);  // eventClass (scope)
        temp = 0;
        base::AppendBytes(event_buffer, temp);  // flags (unused)
        temp = event_string_offset + event_counter;
        base::AppendBytes(event_buffer, temp);  // name
        temp = -1;
        base::AppendBytes(event_buffer, temp);  // args (none)
        event_counter++;
      }
    }
  }

  Chunk events_defined;
  events_defined.AddPart(0x30000, &def_table);
  events_defined.AddPart(0x20002, &def_events);
  events_defined.AppendToString(3, 0x2, &output);


  const int num_trace_threads = static_cast<int>(recorder_list_.size());
  StringTable table;
  table.AddString("script");
  table.AddString("Some_Location");
  for (int chunk_i = 0; chunk_i < num_trace_threads; ++chunk_i) {
    const int zone_id = chunk_i + 1;
    std::string location_string = "Thread_" + base::ValueToString(zone_id);
    table.AddString(location_string);
  }

  EventBuffer events;
  {
    std::string* event_buffer = &events.buffer;
    for (int chunk_i = 0; chunk_i < num_trace_threads; ++chunk_i) {
      const int zone_id = chunk_i + 1;
      uint32 temp;

      temp = kCreateZoneEvent;
      base::AppendBytes(event_buffer, temp);
      temp = 0;
      base::AppendBytes(event_buffer, temp);  // timestamp
      temp = zone_id;
      base::AppendBytes(event_buffer, temp);  // Zone id
      temp = 2 + chunk_i;
      base::AppendBytes(event_buffer, temp);  // Zone name
      temp = 0;
      base::AppendBytes(event_buffer, temp);  // Zone type
      temp = 1;
      base::AppendBytes(event_buffer, temp);  // Zone location
    }

    for (int chunk_i = 0; chunk_i < num_trace_threads; ++chunk_i) {
      TraceRecorder* rec = recorder_list_[chunk_i];
      const int zone_id = chunk_i + 1;
      uint32 temp;

      temp = kSetZoneEvent;
      base::AppendBytes(event_buffer, temp);
      temp = 0;
      base::AppendBytes(event_buffer, temp);  // timestamp
      temp = zone_id;
      base::AppendBytes(event_buffer, temp);  // Zone id

      rec->DumpTrace(event_buffer, table.GetTableSize());

      rec->DumpStrings(table.GetMutableTable());
    }
  }

  Chunk trace;
  trace.AddPart(0x30000, &table);
  trace.AddPart(0x20002, &events);
  trace.AppendToString(1, 0x2, &output);

  return output;
}

void CallTraceManager::WriteFile(const std::string& filename) const {
  if (!filename.empty()) {
    LOG(INFO) << "Writing current WTF traces to: " << filename;
    std::ofstream filestream(
        filename.c_str(), std::ios::out | std::ios::binary);
    if (filestream.good()) {
      filestream << SnapshotCallTraces();
      filestream.close();
    } else {
      LOG(WARNING) << "Failed to open " << filename
                   << " for writing WTF traces.";
    }
  }
}

Timeline CallTraceManager::BuildTimeline() const {
  std::unique_ptr<TimelineNode> root(new TimelineNode("root"));
  for (const auto recorder : recorder_list_) {
    std::unique_ptr<TimelineThread> thread(
        new TimelineThread(recorder->GetThreadName(), recorder->GetThreadId()));
    recorder->AddTraceToTimelineNode(thread.get());
    root->AddChild(std::move(thread));
  }

  return Timeline(std::move(root));
}

analytics::Benchmark CallTraceManager::RunTimelineMetrics() const {
  analytics::Benchmark benchmark;
  Timeline timeline = BuildTimeline();
  for (const auto& metric : timeline_metrics_)
    metric->Run(timeline, &benchmark);
  return benchmark;
}

}  // namespace profile
}  // namespace ion