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

    Всем привет!
    Меня зовут Костя, я занимаюсь разработкой Яндекс.Браузера. Недавно у нас в Новосибирском офисе в Академгородке проходила небольшая 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

    Similar posts

    Ads
    AdBlock has stolen the banner, but banners are not teeth — they will be back

    More

    Comments 7

      0
      Я как-то для небольшого проектика использовал реализацию IPC. Получилось на удивление просто и быстро.
        +1
        Зачем писать имя функции для макроса? Пусть он сам берет через __FUNCTION__.
          0
          Совсем не обязательно трейсить только функцию целиком. Можно, например, вставлять трейсы в отдельные блоки. Тогда могут быть какие-то другие имена, а не просто имя функции
            0
            Тогда пусть будет отдельный макрос на функцию и отдельный макрос на блок с доп.параметром — именем блока. Причем второй макрос тоже будет брать имя функции, чтобы однозначно можно было понять, где находится блок.
          0
          Спасибо, интересный способ, а можно ли это решение прикрутить вживую — чтоб сбор данных и визуализация были одновременными?
          Плюс с нескольких машин одновременно?
            0
            Нет, одновременно сбор и визуализация сейчас работать не будут. Я думаю, что можно подхачить немного, чтобы все заработало, но нужно тогда как минимум гарантировать, что вывод и визуализация не создадут еще TraceEvent.
            Сбор с нескольких машин сделать можно — по сути это просто json, который можно как-то склеивать и потом как-то отображать.
            0
            atom.io весь же чистый хромиум.

            Only users with full accounts can post comments. Log in, please.