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

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

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

chrome://tracing

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

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

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

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

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

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

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

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

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

class CachingService 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.

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

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