Когда-нибудь трассировали рантайм вашего приложения? Знаете сколько запросов делает вон тот серый ендпоинт, который? А как долго вычитываются те кросс-референсы на схожий тип ресурсов с каждой странички сущностей, которую нужно вернуть в запрос? Пытались ли вы замерить как долго приходится ждать пользователю из-за опциональных полей запроса, которые он время от времени добавляет? Задумывались ли вы что будет если запараллелизировать эти шесть запросов к тем двум базам данных?

Если что-нибудь выше звучит интересно, или как минимум знакомо — добро пожаловать под кат.

chrome://tracing

Если ввести chrome://tracing в адресную строку Chrome, то вы попадёте на вот такую страничку:

Сам инструмент очень близко дружит с трассировочными данными самого V8 (и хрома). А с недавних пор node тоже позволяет нативно трассировать рантайм с поддержкой chrome://tracing в качестве фронтенда. Для трассировки достаточно просто нажать заветную “Record” и сделать несколько пассов над соседней вкладкой, после чего можно пронаблюдать в деталях чем именно занимался браузер, когда вы старательно болтали курсор внутри окна, хаотично крутя мышкиным колесом. Для нашего удобства, добрые люди даже написали очень подробную статью о том как интерпретировать результаты.

Формат данных, потребляемых этим визуализатором хорошо задокументирован, и отлично подходит даже для трассировки вещей отдаленных от рендеринга, вычисления разметки и отлова мусорной отрисовки. Благодаря открытости и способности загружать внешние файлы, этот трассировщик достаточно легко интегрируется с любой средой, способной на любой I/O. Кроме того, помимо самой визуализации есть и некоторые встроенные возможности для анализа групп событий. В общем, полезный и гибкий инструмент, который может пригодится и здорово помочь там, где в традиционном случае нужно было бы парсить тонны логов в поисках определенности.

Весь фронтенд трассировщика, кстати, написан на ванильном JS и лежит на GitHub. Сама chrome://tracing — обычная веб-страничка и её можно инспектировать через DevTools как и любую другую. То есть, если инструмент не сможет удовлетворить вас… полностью, то его можно спокойно помять под необходимый сценарий.

В опыте автора, необходимость в таком инструменте появилась во время работы над бессерверной системой для интерента вещей. В определенных сценариях, количество запусков лямбда функций достигало десятков и сотен для выполнения одной единственной операции. Анализировать все внутренности этих запусков по одним только логам было отнюдь не весело. Хотелось чего-то, что помогло бы окинуть картину одним взглядом целиком. Помог самописный трассировщик, который умел инструментировать внутренности наших функций и все запросы, которые они делали. О горе, автор тогда и не подозревал о существовании chrome://tracing, поэтому для трассировщика был написан с нуля фронтенд на d3, которому можно посвятить отдельный пост (tldr; не рендерьте ничего сложного через DOM, только canvas и WebGL). Давайте теперь посмотрим на несколько примеров, где трассировка помогла с оптимизацией:

Прогревание кеша

Дано: асинхронный мемоизирующий сервис и несколько суб-сервисов, которые его вызывают.

Проблема: при нескольких вызовах кеширующего сервиса подряд, результат не успевает попадать в кеш, соответственно вместо одного запроса, сервис делает n.

Решение: прогревание кеша (префетч, работает если серия вызовов нуждается в одной и той же зависимости), либо ленивая блокирующая мемоизация (название импровизированное)

class CachingService {
    constructor() {
        this.cache = null;
    }

    doAction() {
        if (this.cache) {
            return this.process();
        } else {
            return anotherService()
                .then(result => this.cache = result)
                .then(this.process);
        }
    }
}

Promise.all([
    cachingService.doAction(),
    cachingService.doAction(),
    cachingService.doAction()
]);

// Prefetch:
anotherService()
    .then(result => cachingService.cache = result)
    .then(
        () => Promise.all([
            cachingService.doAction(),
            cachingService.doAction(),
            cachingService.doAction()
        ])
    )

// Lazy blocking memoization:    
class FixedService {
    constructor() {
        this.pendingRequest = null;
    }

    doAction() {
        const pendingRequest = this.pendingRequest 
            ? this.pendingRequest 
            : this.pendingRequest = anotherService();

        return pendingRequest
            .then(this.process);
    }
}

Незадокументированные запросы

Дано: один из SDK при каждой инициализации делал дополнительные блокирующие запросы (и пусть весь мир подождёт) о которых мы не подозревали, они никак не логировались и не были задокументированы.

Решение: инструментирование SDK для отключения этого “вредного” запроса.

Аномально долгое выполнение пользовательских скриптов

Дано: трассировка показала, что пользовательские скрипты на несколько строк выполняются на два порядка дольше ожидаемого. Дебаг показал что проблема в чрезмерном использовании переменных из глобального скоупа.

Решение: симуляция глобального скоупа для пользовательского кода через аргументы функции

const vm = require('vm');

const scope = {
    property: 'value',
    // ...
    propertyN: 'valueN'
};

const script = `
    property = '0.6911';
    propertyN = '42';
`;

// Overusing global scope
vm.runInNewContext(
    script,
    scope
);

// Argument based scoping
vm.runInNewContext(
    `
        (
            // Turn scope keys into arguments of wrapper function
            ({ ${Object.keys(scope).join(',') } }) => { ${script} }
        )(this.scope);
    `,
    { scope }
);

Код выше симулирует глобальные переменные для скрипта через аргументы виртуальной функции (привет, CommonJS).

Преждевременная нормализация данных

Дано: Некоторые сущности достаточно велики (2.5-3Мб)
Проблема: подозрение на то, что такие сущности долго и дорого загружать по сети.

Решение: трассировка показала, что загрузка таких сущностей — одна из самых дешевых операций и есть куда более глубинные проблемы требующие решения. Данные помогли сконцентрировать рефакторинг на частях системы, которые дали многократный прирост в производительности после улучшения.

Помимо этих примеров, была масса случаев, когда трассировщик помогал быстро и точно оценить последствия изменений, давал возможность смотреть на всю картину целиком, избегая “построчного” поглощения информации, в целом проявив себя как инструмент упрощающий жизнь.

Устройство простейшего трассировщика

Переходя к практической реализации простейшего трассировщика, их можно условно разделить на две большие группы, по способу инструментации кода:

Централизованный — все точки захвата устанавливаются из единственной точки в коде. Трассировщик вызывает необходимые модули приложения и перегружает точки входа в них.
Распределенный — все точки захвата определяются по месту необходимости, напрямую вызывая код трассировщика. Непосредственно определяют начало события и его конец.

Централизованный подход хорош тем, что инструментируемый код остается чистым и практически независимым от трассировщика. Но, в то же время, появляются неявные зависимости, которые нужно явно поддерживать. Помочь в таком случае могут, например, специальные аннотации, или отдельный интеграционный тест для трассировщика, удостоверяющий что все необходимые модули на их местах вместе с точками захвата.

Распределенный подход хорош тем, что можно очень ситуативно определять длительность и содержание событий, включая в них целые блоки полезного кода. Также, он проще для начальной реализации, потому что трассировщик избавлен от необходимости абстрактно отлавливать потенциальные ошибки и обеспечивать неизменный поток исполнения.

Самый банальный пример трассировщика второго типа может выглядеть так:

class Tracer {
    constructor() {
        this.events = {};
    }

    start(meta) {
        const id = Math.random().toString(16).substr(2);
        const start = Date.now();

        this.events[id] = { start, id, meta };

        return id;
    }

    stop(id) {
        this.events[id].stop = Date.now();
    }
}

Все достаточно банально и трассировщик не должен беспокоиться ни о каких сторонних эффектах инструментируемого кода. Также, никогда не используйте ничего наподобие `Math.random().toString(16).substr(2);`, этот пример сугубо для иллюстрации, есть куда более правильные способы.

Как только мы захотим перейти к централизованному подходу, нам нужен будет абстрактный интерфейс для установки точек захвата:

addHook(path, method) {
        const module = require(path);
        const originalMethod = module[method];

        module[method] = function() {
            const event = this.start();
            const result = originalMethod.apply(module, arguments);
            this.end(event);

            return result;
     }
}

Такой метод можно будет вызывать в том единственном месте, которое будет сердцем конфигурации. Обычный monkey-patching, даже нечего добавить. Легко заметить что метод имеет несколько недостатков:

Расположение модуля относительно трассировщика
Никаких проверок ввода
Никакая поддержка асинхронных функций

Первый недостаток вызван плохой продуманностью интерфейса этой функции. Заставлять трассировщик разрешать пути к файлам для инструментации — сомнительная затея, т.к. Для конечного пользователя это добавляет дополнительный слой неявной обработки, который приводит к сомнениям, относительно интерфейса трассировщика. “А тот ли путь я передал?”, “Путь должен быть относительно моего файла или файла трассировщика?”, “Должен ли я писать стандартную портянку с __dirname и path.resolve?” — всего этого можно избежать, просто передавая сам модуль, который нужно инструментировать:

addHook(module, method) {
        const originalMethod = module[method];

        module[method] = function() {
            const event = this.start();
            const result = originalMethod.apply(module, arguments);
            this.end(event);

            return result;
     }
}

Помимо более явного поведения для пользователя, это позволяет упростить валидацию на существование:

isInstrumentable(module, method) {
    return module && (typeof module[method] === 'function');
}

addHook(module, method) {
      if (this.isInstrumentable(module, method)) {
            const originalMethod = module[method];

            module[method] = function() {
                const event = this.start();
                const result = originalMethod.apply(module, arguments);
                this.end(event);
     
                return result;
          }
      }
}

Поведение при невалидной конфигурации может быть жёстким (выбросить ошибку) или мягким (игнорировать модуль, продолжить работу). Теоретически хороший трассировщик должен позволять следовать любому из путей при помощи конфигурации, так как оба варианта могут быть оправданы в разных случаях.

Обработка асинхронных функций — уже чуть более интересная задача. Во первых, нужно определить является ли инструментируемый метод асинхронным, и изменить поведение трассировщика для определения конца события. Для этого можно модифицировать наш перегруженный метод следующим образом:

addHook(module, method) {
    if (this.isInstumentable(module, method)) {
      const tracer = this;
      const originalMethod = service[method];

      service[method] = function () {
        let result;
        const eventId = tracer.start();

        try {
          result = originalMethod.apply(this, arguments);
        } catch (error) {
          tracer.stop(eventId, {
            success: false,
            error: errorToString(error)
          });

          // rethrow to keep the flow as it would
          // be without having tracker at all
          throw error;
        }

        if (result instanceof Promise) {
          // Handle services returning promises
          return result
            .then(
              tracer.handleResolved(eventId),
              tracer.handleRejected(eventId)
            );
        } else {
          // Handle synchronous services
          tracer.stop(eventId);
          return result;
        }
      };
   }
}

handleResolved(event) {
    return res => {
        this.stop(event);
        return res;
    };
}

handleRejected(event) {
    return err => {
        this.stop(event);
        return Promise.reject(err);
    }
}

Из интересного, трассировщик должен гарантировать отсутствие сторонних эффектов во время выполнения. Поэтому он должен пробрасывать любые словленные ошибки назад в поток приложения.

Вот и все, такой примитивный трассировщик уже можно использовать для чего-то полезного. Из дополнительных возможностей, которыми можно озадачится:

Поддержка before и after точек захвата для инструментируемого кода, с передачей аргументов и возвращаемого результата для любых других дополнительных действий
Поддержка событий различных типов по именам, это просто удобно
Поддержка сохранения метаданных об успешности каждого события
Поддержка сохранения результатов выполнения инструментированного метода
Библиотека стандартных точек захвата для публичных интерфейсов node.js и популярных библиотек
Поддержка экспорта в других форматах, например: Open Tracing
Возможность удалённого запуска трассировочных сессий с отправкой результата на клиент
Защита от непреднамеренно долгих сессий (на нашей памяти были случаи, когда включенный трассировщик генерировал несколько гигабайт данных и ронял родительское приложение).

После того как события записаны, останется лишь сохранить их в формате, подходящем для chrome://tracing. Для этого можно воспользоваться следующей функцией:

function toChromeTracingEvent(event) {
  const parsed = url.parse(event.meta.url);
  const base = {
    id: event.id,
    pid: process.pid,
    tid: 0,
    cat: event.type,
    name: event.meta.method,
    args: event.meta
  };

  return [
    Object.assign({}, base, {
      ph: 'b',
      ts: event.start * 1000
    }),
    Object.assign({}, base, {
      ph: 'e',
      ts: event.stop * 1000
    })
  ];
}

Суть в том, что каждое событие трассировщика раскрывается в два объекта представляющих начало и конец асинхронного события chrome://tracing. Помимо асинхронных событий, можно создавать и “законченные” (Completed) события. Но они перекрывают друг друга при рендере в chrome://tracing из-за чего их не так просто анализировать :3

После того как все события сконвертированы, останется просто аккуратно сложить их массивом в поле объекта `traceEvents` и сохранить его куда-нибудь, откуда его не будет мучительно долго искать через файловый проводник.

Заключительным шагом будет добавить инструментацию в части вашего приложения где происходит что-то неявное, запустить его и загрузить полученный файл в chrome://tracing.

Трассировщик, послуживший вдохновением для этой статьи.

Пусть работа будет интересной!

Трассировка и Javascript