Как стать автором
Обновить

Как прикрутить трейсинг из браузера в любой проект

Время на прочтение 6 мин
Количество просмотров 9K
Всем привет!
Меня зовут Костя, я занимаюсь разработкой Яндекс.Браузера. Недавно у нас в Новосибирском офисе в Академгородке проходила небольшая C++ party, на которой я рассказывал о том, какие инструменты мы применяем при разработке браузера и что можно позаимствовать для других больших проектов, например, про ninja, OWNERS. В ходе разработки мы очень пристально следим за производительностью: загрузка CPU, потребление памяти, время выполнения различных операций и так далее. При этом активно используются различные утилиты, но также и внутренние отладочные инструменты браузера, например, внутренняя страница browser://tracing (для Яндекс.Браузера, chrome://tracing для Chromium и Chrome).
Скриншот browser://tracing


Если коротко, то на этой странице можно проследить длительность выполнения разных функций и количество вызовов в разбивке по процессам, потокам и переданным аргументам. Само собой, в этом нет никакой магии и для того, чтобы это работало, по коду требуется расставить специальные макросы. Как мне кажется, это очень удобный инструмент, который позволяет найти кучу разных проблем. Я считаю, что такой инструмент может оказаться полезным и в других проектах, так что я решил показать как можно его применить.

Зачем это нужно?


Конечно, для того, чтобы трейсить проекты существуют самые разные инструменты, но у них всех есть огромный минус — их нельзя использовать у конкретного пользователя, хотя это может быть очень важным для понимания и диагностики проблемы. Диагностику, которую собирает браузер на browser://tracing можно собирать в любой момент. Ее можно включать только на определенный период, чтобы повторить баг, а в остальные моменты она не приносит большого оверхеда.

Что нам понадобится?


В первую очередь, конечно, будут нужны исходники. По большому счету то, что нам нужно находится в папке base/trace_event внутри нее используются в том числе и другие компоненты из подпапки base, например, time, threading, synchronization и т.д. Я решил поступить очень просто и просто слинковаться с base.dll из сборки хромиума. К счастью, репозиторий хромиума у меня есть даже на домашнем компьютере, не говоря уж о рабочих. Для тех, кто хочет пойти таким же путем, тут есть ссылки на инструкции для сборки под разные платформы. Важно: для компонентной сборки нужно установить переменную окружения GYP_DEFINES=«component=shared_library».
Во-вторых нам нужны заголовочные файлы, которые можно взять здесь.
Как вариант, вместо этих двух пунктов можно сделать проще и добавить файлы из base к себе в проект.

Включаем трейсинг и пользуемся


Для начала нам нужно включить трейсинг. Для этого требуется создать фильтр категорий, который мы хотим применять. Категория — это идентификатор некоторый группы отслеживаемой операции. Категории нужны, чтобы выбирать какие группы мы хотим отслеживать в данный момент. Затем нужно вызвать метод SetEnabled у синглтона класса TraceLog.
const char kCategoryName[] = "my_category";

void StartTracing() {
  base::trace_event::CategoryFilter category_filter(kCategoryName);
  base::trace_event::TraceLog::GetInstance()->SetEnabled(
      category_filter, base::trace_event::TraceLog::RECORDING_MODE,
      base::trace_event::TraceOptions(base::trace_event::RECORD_UNTIL_FULL));
}

Теперь придумаем сложную задачу, время выполнения которой мы хотим отслеживать и добавим в нужных местах макрос TRACE_EVENT. Этот макрос разворачивается в инстанцирование объекта класса ScopedTracer, который, как можно догадаться, отчитается о длительности выполнения в рамках scope. Подробнее можно посмотреть здесь
float SomeHardcoreTask(int max_num) {
  TRACE_EVENT1(kCategoryName, "SomeHardcoreTask", "max_num", max_num);
  float x = 1.5f;
  for (int i = 0; i < max_num; ++i)
    x *= sin(x) / atan(x) * tanh(x) * sqrt(x);

  return x;
}

void SomeHardcoreAsyncTask(
    base::WaitableEvent* event,
    const base::Callback<void(float)>& out_cb) {
  TRACE_EVENT0(kCategoryName, "SomeHardcoreAsyncTask");
  for (int i : {20000000, 5000000, 80000000})
    out_cb.Run(SomeHardcoreTask(i));

  event->Signal();
}

void AsyncTaskCb(float x) {
}

void DoWork() {
  TRACE_EVENT0(kCategoryName, "DoWork");
  base::Thread thread("HardcoreTaskThread");
  thread.Start();
  base::WaitableEvent event(false, false);
  thread.message_loop_proxy()->PostDelayedTask(
      FROM_HERE,
      base::Bind(&SomeHardcoreAsyncTask,
                 &event,
                 base::Bind(&AsyncTaskCb)),
      base::TimeDelta::FromSeconds(2));

  for (int i : {10000000, 20000000, 50000000})
    std::cout << SomeHardcoreTask(i);

  event.Wait();
}


Осталась заключительная часть — нужно выключить трейсинг и сохранить результаты на диск. Сразу признаюсь, что в основном код взят отсюда
const char kTracingJsonPath[] = "D:\\trace.json";

// Функция-коллбек, которая принимает построчно результаты трейсинга и пишет их в файл.
void WriteTraceDataCollected(
    base::File* output_file,
    const scoped_refptr<base::RefCountedString>& events_str,
    bool has_more_events) {
  output_file->WriteAtCurrentPos(events_str->data().c_str(),
                                 events_str->data().length());
  if (has_more_events)
    output_file->WriteAtCurrentPos(",", 1);
}


// Останавливаем трейсинг и флашим данные на диск.
void StopTracingAndFlushToDisk() {
  base::trace_event::TraceLog::GetInstance()->SetDisabled();
  base::File output(base::FilePath::FromUTF8Unsafe(kTracingJsonPath),
                    base::File::FLAG_CREATE_ALWAYS | base::File::FLAG_WRITE);
  CHECK(output.IsValid());
  static const char kStart[] = "{\"traceEvents\":[";
  static const char kEnd[] = "]}";
  output.WriteAtCurrentPos(kStart, strlen(kStart));
  base::trace_event::TraceLog::GetInstance()->SetDisabled();
  base::trace_event::TraceLog::GetInstance()->Flush(
      base::Bind(&WriteTraceDataCollected, &output));
  output.WriteAtCurrentPos(kEnd, strlen(kEnd));
  output.Close();
}


Итак, все необходимое есть, осталось только собрать все в одну кучу.
int main() {
  StartTracing();
  DoWork();
  StopTracingAndFlushToDisk();
  return 0;
}


Весь код вместе
#define NOMINMAX

#include <iostream>

#include <base/files/file.h>
#include <base/synchronization/waitable_event.h>
#include <base/trace_event/trace_event.h>

namespace {

const char kCategoryName[] = "my_category";
const char kTracingJsonPath[] = "D:\\trace.json";

void WriteTraceDataCollected(
    base::File* output_file,
    const scoped_refptr<base::RefCountedString>& events_str,
    bool has_more_events) {
  output_file->WriteAtCurrentPos(events_str->data().c_str(),
                                 events_str->data().length());
  if (has_more_events)
    output_file->WriteAtCurrentPos(",", 1);
}

void StartTracing() {
  base::trace_event::CategoryFilter category_filter(kCategoryName);
  base::trace_event::TraceLog::GetInstance()->SetEnabled(
      category_filter, base::trace_event::TraceLog::RECORDING_MODE,
      base::trace_event::TraceOptions(base::trace_event::RECORD_UNTIL_FULL));
}

void StopTracingAndFlushToDisk() {
  base::trace_event::TraceLog::GetInstance()->SetDisabled();
  base::File output(base::FilePath::FromUTF8Unsafe(kTracingJsonPath),
                    base::File::FLAG_CREATE_ALWAYS | base::File::FLAG_WRITE);
  CHECK(output.IsValid());
  static const char kStart[] = "{\"traceEvents\":[";
  static const char kEnd[] = "]}";
  output.WriteAtCurrentPos(kStart, strlen(kStart));
  base::trace_event::TraceLog::GetInstance()->SetDisabled();
  base::trace_event::TraceLog::GetInstance()->Flush(
      base::Bind(&WriteTraceDataCollected, &output));
  output.WriteAtCurrentPos(kEnd, strlen(kEnd));
  output.Close();
}

float SomeHardcoreTask(int max_num) {
  TRACE_EVENT1(kCategoryName, "SomeHardcoreTask", "max_num", max_num);
  float x = 1.5f;
  for (int i = 0; i < max_num; ++i)
    x *= sin(x) / atan(x) * tanh(x) * sqrt(x);

  return x;
}

void SomeHardcoreAsyncTask(
    base::WaitableEvent* event,
    const base::Callback<void(float)>& out_cb) {
  TRACE_EVENT0(kCategoryName, "SomeHardcoreAsyncTask");
  for (int i : {20000000, 5000000, 80000000})
    out_cb.Run(SomeHardcoreTask(i));

  event->Signal();
}

void AsyncTaskCb(float x) {
}

void DoWork() {
  TRACE_EVENT0(kCategoryName, "DoWork");
  base::Thread thread("HardcoreTaskThread");
  thread.Start();
  base::WaitableEvent event(false, false);
  thread.message_loop_proxy()->PostDelayedTask(
      FROM_HERE,
      base::Bind(&SomeHardcoreAsyncTask,
                  &event,
                  base::Bind(&AsyncTaskCb)),
      base::TimeDelta::FromSeconds(2));

  for (int i : {10000000, 20000000, 50000000})
    std::cout << SomeHardcoreTask(i);

  event.Wait();
}

}  // namespace

int main() {
  StartTracing();
  DoWork();
  StopTracingAndFlushToDisk();
  return 0;
}




Результат


В результате получаем файл trace.json, который можно открыть на browser://tracing и увидеть следующее:


Заключение


Как можно заметить, получилось очень несложно позаимствовать достаточно полезный функционал из хромиума и применить его. Хотелось бы подчеркнуть, что кроме этого в исходниках хромиума очень много интересных подходов и просто-напросто готовых решений, которые так или иначе можно применить у себя в проекте.
Если у кого-то есть еще подобные примеры — расскажите о них в комментариях. От себя могу добавить, что, например, в фреймворке распределенных вычислений Яндекса YT используются хромиумовские коллбеки, которые были слегка доработаны напильником. Еще я однажды слышал байку про индусов, которые на базе хромиума сделали клиент для облачного диска, но не могу найти пруфов сейчас.

Полезные ссылки


https://www.chromium.org/developers/design-documents
https://code.google.com/p/chromium/codesearch#chromium/src/base/
https://www.chromium.org/developers/how-tos/trace-event-profiling-tool
Теги:
Хабы:
+14
Комментарии 7
Комментарии Комментарии 7

Публикации

Истории

Работа

QT разработчик
13 вакансий
Программист C++
122 вакансии

Ближайшие события

Московский туристический хакатон
Дата 23 марта – 7 апреля
Место
Москва Онлайн
Геймтон «DatsEdenSpace» от DatsTeam
Дата 5 – 6 апреля
Время 17:00 – 20:00
Место
Онлайн