Я уже рассказывал про сервис мониторинга запросов к PostgreSQL, для которого мы реализовали онлайн-коллектор серверных логов, чья основная задача — одновременно принимать потоки логов сразу с большого количества хостов, быстро их разбирать на строки, группировать в пакеты по определенным правилам, обрабатывать и записывать результат в PostgreSQL-хранилище.



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

Мы погрузились в недра профайлера и обнаружили некоторые особенности работы с Buffer в Node.js, знание которых может сильно сэкономить ваше время и серверные ресурсы.

Процессорная нагрузка

Большая часть процессорного времени тратилась на обработку входящего лог-потока, что вполне понятно. Но что было непонятно — ресурсоемкость примитивной «нарезки» входящего потока бинарных блоков на строки по \r\n:



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

Пробуем readline

Беглый обзор имеющихся решений вывел нас на штатный модуль readline ровно с необходимым нам функционалом нарезки на строки:



После его внедрения «нарезка» из топа профайлера ушла в глубину:



Но, как выяснилось, внутри себя readline принудительно приводит строку в UTF-8, чего нельзя делать, если у записи лога (запроса, плана, текста ошибки) другая исходная кодировка.

Ведь даже на одном PostgreSQL-сервере может быть одновременно активно несколько баз, каждая из которых формирует вывод в общий серверный лог именно в своей оригинальной кодировке. В результате, обладатели баз на win-1251 (иногда удобно применять ради экономии дискового пространства, если «честный» многобайтовый UNICODE не нужен) смогли наблюдать у себя планы с примерно такими «русскими» названиями таблиц и индексов:

Дорабатываем велосипед

Беда-беда… Придется все таки делать нарезку самостоятельно, но уже с оптимизациями типа Buffer.indexOf() вместо «побайтного» сканирования:



Вроде все хорошо, в тестовом контуре нагрузка не выросла, win1251-названия починились, выкатываем на бой… Та-дам! CPU usage периодически пробивает потолок в 100%:



Как же так?.. Оказывается, во всем виноват Buffer.concat, которым мы «подклеиваем хвост», оставшийся от предыдущего блока:



Но ведь у нас склейка идет только при переходе строки через блок, а их не должно быть много — правда-правда?.. Ну, почти. Только вот иногда приходят «строки» из нескольких сотен 16KB-сегментов:



Спасибо коллегам-разработчикам, которые позаботились такое сгенерировать. Случается оно «редко, но метко», поэтому увидеть заранее в тестовом контуре не удалось.

Понятно, что подклейка несколько сотен раз к буферу на несколько мегабайт мелких кусочков — прямой путь в бездну переаллокаций памяти с выеданием ресурсов CPU, что мы и пронаблюдали. Так а давайте просто не будем клеить, пока строка не кончилась совсем. Просто будем складывать «кусочки» в массив, пока не настанет пора отдать всю строку «наружу»:



Теперь нагрузка снова вернулась к показателям, которые давал readline.

Потребление памяти

Многие, кто писал на языках с динамическим выделением памяти, в курсе, что одна из наиболее неприятных «убийц производительности» — это фоновая активность «сборщика мусора» (Garbage Collector, GC), который сканирует созданные в памяти объекты и удаляет те, которые больше никому не требуются. Настигла эта неприятность и нас — в какой-то момент мы начали замечать, что активности GC как-то слишком уж много, и не к месту.



Традиционные «крутилки» не особо помогали… «Если ничего не помогает — сделай дамп!» И народная мудрость не подвела — мы увидели тучу Buffer по 8360 байт общим размером на 520MB…



Причем порождены они внутри CopyBinaryStream — ситуация начала проясняться…

COPY… FROM STDIN WITH BINARY

Чтобы уменьшить объем передаваемого на БД трафика, мы используем бинарный формат COPY. Фактически, для каждой записи нужно в поток отправить буфер, состоящий из «кусочков» — количества полей в записи (2 байта) и дальше бинарного представления значения каждого из столбцов (4 байта на ID типа + данные).

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

memo

Ну а раз у нас многие кусочки повторяются снова и снова (например, количество полей в записях одной и той же таблицы) — давайте будем просто их запоминать, а потом брать уже готовые, сгенерированные однократно при первом обращении. Исходя из COPY-формата вариантов достаточно немного — типовые кусочки бывают по 1, 2 или 4 байта:



И… бам, прилетели грабли!



То есть да, каждый раз при создании Buffer по-умолчанию выделяется кусок памяти 8KB, чтобы создаваемые подряд небольшие буферы можно было складывать «рядом» в уже выделенной памяти. А наше выделение срабатывало «по требованию», и оказывалось совсем не «рядом» — поэтому каждый наш буфер на 1-2-4 байта физически занимал 8KB + заголовок — вот они, наши 520MB!

smart memo

Хм… А зачем нам вообще ждать, пока потребуется тот или иной 1/2-байтовый буфер? С 4-байтовыми тема отдельная, но этих-то разных возможных вариантов всего 256 + 65536. Так давайте нагенерим их подряд все сразу! Заодно и условие существования из каждой проверки спилим — еще и работать станет быстрее, поскольку инициализация проводится только при старте процесса.



То есть кроме 1/2-байтовых буферов сразу инициализируем и самые ходовые значения (нижние 2 байта и -1) для 4-байтовых. И — это помогло, всего 10MB вместо 520MB!