![[personal profile]](https://www.dreamwidth.org/img/silk/identity/user.png){kind=small}
Логгер для CloudWall
Написал за ночь сегодня логгер для следующеего релиза CloudWall, сейчас потестил – оч шустро вышло. Написал заметочку в корпоративной Стене и решил сюда кросспостнуть.
Под катом инженерные соображения про логгер для браузерной системы.
Заимплементил логгер. Это довольно любопытный зверёк, поэтому подробнее опишу. Смотреть код можно тут (сорри, френды, вам пока нельзя), искать функцию _logstart.Требования к логгеру
- Логгер должен стартовать до всей остальной системы
- Должен писать всё, что пишется в системную консоль (именно она отображается на консоль браузера в debug-mode)
- Должен быть синхронным и быстрым
- Он не должен падать ни от какого набора аргументов, в тч от jQuery-объектов – и записывать все аргументы, которые возможно записать
- Должен контролировать длину сериализованных аргументов, чтобы не засорять лог длинными записями
- Не должен занимать много ключей в ls
- Должен дописываться append-ом (поэтому чистый JSON не подходит; с ним чтобы добавить запись, надо сначала распарсить все предыдущие записи, потом вставить элемент, а потом обратно сериализовать – это O(n^2) сложность, а нам надо O(1)) (UPD. Никак тут не обойтись без минимум O(n))
- Должен различать сообщения из разных табов одной системы
- Должен быть читаем человеком
Я над этим неделю думал и читал всякое, и вот что получилось.
Есть два ключа в localStorage – _cw_log_curr и _cw_log_prev. Первый рабочий, его длина ограничена 50Кб, второй – архивный, не больше 1Мб. Параметры задаются в конфиге.
Как только рабочий лог становится длинным, он приписывается к архивному целиком и очищается. Архивный, если стал длинным, подрезается с головы до 1Мб.
Структура
Сам по себе лог – длинная строка, набор JSON-строк, конкатенированных через \n. Разрывов строк в JSON-ах не бывает (это энфорсится), поэтому такой подход рационален вполне.
То-есть для добавления новой записи мы читаем текущий лог как длинную строку, это быстро. Ничего не парсим, а просто приписывем к этой строке \n и сериализованную в JSON новую запись лога. То, что получилось, пишем обратно в ls.
Каждый раз читать лог нужно потому, что в него может писать соседняя вкладка, например.
Если лог нужно разобрать по записям, мы читаем строку лога, делаем .split("\n") и получаем массив JSON-строк записей. Каждую запись нужно потом распарсить отдельно. Заодно такой подход защищает нас от кривых записей – они не повлияют на остальные, даже если не разберутся.
Для различения сессий я ввёл сессионный ключ, он генерится новый при каждой загрузке cw.js – то-есть записи из соседних вкладок будут иметь разные маркеры.
Сериализация записи
Тут тоже нужен трюк. cw.log(arg1, arg2, ...argN) может быть вызван с несколькими аргументами, причём некоторые после сериализации могут оказаться слишком длинными.
Поэтому сделан кастомный сериализатор, который обрезает слишком длинные строки, получившиеся после стрингифая каждого аргумента. Ещё он принимает на вход jQuery-объекты и сохраняет их как {jQuery:["SPAN#id.class1.class2","DIV.class3"]}.
Зацикленные объекты тоже не отклоняются вслепую – по ним пишется список ключей первого уровня.
Как посмотреть
Чтобы прочитать рабочий лог, можно в консоли выполнить cw.log(N) – вернёт массив из N последних неразобранных записей.
cw.log(N).map(JSON.parse) – вернёт массив из распарсенных.
Скорость – примерно 100-200мкс на сохранение килобайтной записи с обрезкой длинных узлов (~5Кб) посредине, это при отправке 1000 записей подряд. И можно ещё быстрее кратно сделать, если пооптимизировать на серализации и в плане подстройки по GC, чтобы он пореже мир останавливал.
Такие дела.
---
Пока копировал псто, подумал ещё, что надо сделать фичу распознавания повторяющихся событий. И, может, это выпилить отдельной стэндэлон-библиотекой и на гитхаб сложить.
Справочно: скорость записи в localStorage небольших фрагментов (десятки килобайт) колоссальна: на моём i7 – сотни мегабайт в секунду в любом браузере. Это многократно превосходит среднюю скорость сериализации в JSON, например.
Коллеги, что я забыл про важные фичи лога?
no subject
Но можем потерять запись (lost update)?
no subject
При этом в лог у нас помещается примерно 20К записей, так что вероятность потери от лог ротэйта выше.
В этой связи я посчитал нецелесообразным городить какие-то дополнительные механизмы, чтобы ещё эту вероятность уменьшить. Они все замедлят лог, а совсем надёжные сделают его вовсе асинхронным, что неприемлемо.
Одновременный старт в двух вкладках событие маловероятное само по себе. Другие близкие к одновременным события (репорт о новых приложениях, например, когда они в базу прилетают) терять не страшно, они для разных вкладок всё равно одинаковые, база то одна.
Обычно всё же пользователь работает в одной вкладке, это сильно смещает tradeoff надёжность-скорость в сторону скорости.
no subject
no subject
Вообще, главное соображение – в неактивных вкладках типичная плотность событий, которые страшно потерять, уменьшается на примерно два порядка. Скрипты подтормаживаются, приложения пользовательские событий не генерят и тп.
Если б это было не так и не надо было бы уложиться в мегабайт, я б делал по ключу в БД на каждую сессию, по ключу на heartbeat каждой сессии и асинхронный сборщик/архиватор логов умерших сессий на старте новой вкладки.
Но я не хочу вылезать из мегабайта никогда – потому что полная ls quota в браузерах 5-10Мб. Да и 1е-6 в наихудшем сценарии по мне ок.
no subject
no subject
переделыватьдоделывать, спасибо.Первой стартует активная вкладка. Она может писать в ls маркер, которые остальные будет проверять на старте, и если разница небольшая, просто подтормаживать старт. Заодно кста можно сделать так, чтобы PIN надо было вводить в таком мценарии однократно. Сейчас нужно во всех вкладках.
no subject
1. Как ты правильно заметил, линейное добавление к логу. У тебя не O(1), потому что склеивание строк это уже O(N). На практике, может быть две пары строк (<50kb и <1mb) будут good enough, но в теории, чтобы получить хотя бы амортизированный O(1) на склеивании строк, тебе нужно иметь не пару буферов, а O(log N).
2. Нужна дифференциация по verbosity levels. Твой п.5 слабоват: на практике тебе, как правило, либо нужно целиком всё сериализованное значение, либо никакого вовсе. Нужно иметь возможность включить нужный уровень logging'а при необходимости, пусть во вред performance'у, но который сохранит всё, что нужно.
3. Нужна дифференциация по severity of errors, хотя бы для того, чтобы для high severity делать flush (не накапливать в памяти и дожидаться, пока storage запишет). Если у тебя и так всегда flush, то disregard this :)
4. Нужна возможность каких-то связывающих идентификаторов, чтобы можно было реализовать "сквозной" просмотр логов из разных компонент, касающихся одного workflow. Например, когда ты дебагаешь веб-приложение, тебе хорошо бы видеть в хронологическом порядке логи сервера в перемешку с логами клиента. Чтобы это было возможным, нужны всякие там request ids. Ну и часы правильно синхронизовать и в одной часовой зоне (а лучше в GMT) логать время. Я бы для этого функционала добавил бы фичу закачивать логи на сервер, которую можно включить опционально и "на лету".
5. Logging engine должен быть максимально прост, потому что ты не можешь использовать его же, чтобы логать ошибки внутри logging engine :) Сделай хорошее покрытие тестами.
no subject
no subject
no subject
no subject
1. Если память копируется, то да, O(N). Но у меня есть стойкое ощущение, что непосредственно при конкатенации строк память не копируется – результирующая строка получается как набор указателей и не копируется до тех пор, пока части остаются неизменными. Хотя я не уверен на 100% и в код V8 тыкнуть не могу.
Но при записи в ls копируется, конечно.
2-3. Я ещё не придумал, как это по-хорошему сделать, но точно сделаю.
no subject
no subject
Оно работает так. При старте вкладки весь localStorage кэшируется в оперативной памяти и хранится как конструкция, стандартная для рантайма.
Она только как-то по-другому попадает под GC и неё на входе, видимо, ограничение, она принимает объекты не всяких типов под ключи.
Я предположил, что это явно означает, что строки не копируются и дальше копаться в коде Хромиума не стал, а провёл такой эксперимент:
var x = "x".repeat(1000000), t;
localStorage.setItem("x",x); t=Date.now();
var i=1, a=[];a[0] = localStorage.getItem("x");
for(i=1;i<100;i++) a[i]=a[i-1]+localStorage.getItem("x");
Date.now() - t;
>160
Эта штука выполнилась за 160мс. Снэпшот всего, что было выделено по пути, выглядит так:
8Мб на всю вкладку.
Если бы память копировалась, оно бы выделило минимум гигабайт, а максимум – 5 Гб. За 1/6 секунды такой объём можно закопировать в одном потоке, если иметь производительность связки память-процессор 30Гб/с+, это не про айМак )
Так что тут напрашивается два вывода:
1. Хороший: как минимум при чтении из ls и последующей конкатенации строки не копируются, а создаётся вектор указателей на буфера.
2. Плохой: оно персистится на диск только по закрытию вкладки.
Ну и 3 – видимо, и при записи в ls строки не копируются.
Кажется, в этом случае моё чутьё получше твоего сработало, что вселяет в меня просто нереальный оптимизм )
no subject
Попробуй вместо:
a[i]=a[i-1]+localStorage.getItem("x");
Написать вот такое:
localStorage.setItem("x", x + localStorage.getItem("x"))
Тогда мы действительно будем append'ить строки к localStorage.
В твоём примере append'ятся строки, уже живущие в JavaScript-списке, а не помещённые в localStorage. localStorage вполне может иметь layer кэша и не ходить на диск за каждым повторным вызовом getItem() если setItem() между ними не было.
no subject
1.
var x = "x".repeat(10000), t;
localStorage.setItem("x",x); t=Date.now();
var i=1, a=[];a[0] = localStorage.getItem("x");
for(i=1;i<100;i++) a[i]=a[i-1]+localStorage.getItem("x");
Date.now() - t;
стабильно 3ms.
2.
var x = "x".repeat(10000), t;
localStorage.setItem("x",x); t=Date.now();
var i=1, a=[];a[0] = localStorage.getItem("x");
for(i=1;i<50;i++) localStorage.setItem("x", x + localStorage.getItem("x"));
Date.now() - t;
200-250 ms, среднее около 225ms.
3.
var x = "x".repeat(10000), t;
localStorage.setItem("x",x); t=Date.now();
var i=1, a=[];a[0] = localStorage.getItem("x");
for(i=1;i<100;i++) localStorage.setItem("x", x + localStorage.getItem("x"));
Date.now() - t;
980-1080ms, но среднее тяготеет к нижней границе, около 1000ms.
Вот тебе пришла квадратичность. Объём конечной строки вдвое выше, а времени потребовалось в 4 раза больше.
4.
var x = "x".repeat(10000), t;
localStorage.setItem("x",x); t=Date.now();
var i=1, a=[];a[0] = localStorage.getItem("x");
for(i=1;i<150;i++) localStorage.setItem("x", x + localStorage.getItem("x"));
Date.now() - t;
2470-2880ms, среднее около 2600ms.
Размер конечной строки увеличили ещё в 1.5 раза, время увеличилось в более, чем 2.25 раз, т.е. оно чуть хуже, чем квадратично.
no subject
Получается, что без json-a O(n^2). С json-ом просто ещё минимум втрое (это если бы каждая запись строкой была) медленней.
Вот же говно.
Ну, всё равно переделывать – там Тонски ниже хороший поинт написал. Стало быть, если я ввожу ключ, который фиксирует, какая последняя сессия писала в ls, я могу не читать весь working cache, если писала в предыдущий раз та же самая вкладка.
В этом случае я храню то, что было записано в прошлый раз, локально, аппендю к нему и пишу что получилось. Тогда тоже O(n^2), но всё же быстрее.
Ну и два набора – длинный и короткий – тоже позволяют этому O(n^2) быть не так заметным.
no subject
Насчёт O(n^2) - давай я чуток разовью идею, как получить ... хотел сказать O(n), но, на самом деле, похоже, будет O(n log n).
Во-первых, сразу идея - по поводу двух наборов - длинного и короткого - ограничивай короткий не длиной в байтах/символах, а количеством append'ов.
Теперь продолжение: представь себе, что у тебя наборов не два, а много, но каждый строго ограничен количеством append'ов, скажем, не больше 10. Как только в одном наборе набирается 10, он тут же приклеивается к набору старшего разряда (увеличивая его количество append'ов на 1, нужно track'ать отдельно), а свой буфер сбрасывает в пустую строку и 0 append'ов. В этом случае расклад по количеству append'ов будет десятичное число :) где каждой цифре соответствует свой буфер.
Append одного сообщения - эквивалент прибавления 1 к этому числу (с переносами). Нетрудно увидеть, что амортизированная стоимость этого процесса это фиксированное количество сложений, O(1). Даже не логарифм, а константа, т.к. ты будешь делать append в младшем разряде с вероятностью 100%, в следующем с вероятностью 10%, в следующем с вероятностью 1%, и т.п., 1 + 1/10 + 1/100 + .. это очень убывающий ряд.
Квадратичные оверхеды будут только в рамках последнего разряда, они константны. Но с каждым разрядом тебе придётся пусть в 10 раз реже, но копировать в 10 раз более длинную строку, так что стоимость именно копирования будет N + N + N + ... это N log N.
Конечно, десятичная система просто для наглядности. Можно в двоичной. Чтобы держать миллион записей, тебе нужно будет 20 буферов. Можно потестить и выбрать такое основание, которое оптимально по перформансу. Не факт, что это будет 2, и не факт, что 10. Хотя, интуиция мне подсказывает, что правильный ответ ближе к 2, чем к 10.
no subject
С количеством аппендов – я тоже так собирался делать. Но тогда нам надо прочитанный лог разобрать на отдельные записи – а это лишняя движуха.
Сейчас я эту лишнюю движуху делаю только в случае, если мне надо отрезать записи с головы (выход за 1Мб).
Писать в отдельный ключ счётчик(и) к-ва записей (чтобы не разбирать) я не хочу – это лишний рид-райт в ls, а транзакций у нас нет. То-есть так я просто повышу себе вероятность потери записей, если одноврменно начнут писать две вкладки.
Насчёт цепочки буферов кратного размера – да, я это понимаю. Просто для размера в 1Мб я посчитал, что двух достаточно.
no subject
Кроме того, парсить её совершенно не обязательно, на практике вполне годится ограничение по длине (которая будет как прокси для количества записей). Счётчики были только для рассуждения о сложности.
Кстати, carryover это potential failure point. Лучше сначала добавить наверх, потом обнулить. (В случае fail in the middle, получишь дупликат записей, который можно разрезолвить как-нибудь потом, а не data loss.)
no subject
Да, я так и делаю. Там выше где-то тоже есть в комментах про это.
> по сути, нужна API-level функциональность для синхронизации параллельных потоков
Точнее, как минимум для откладывания старта соседних, но неактивных вкладок. Это я сделаю, оно несложно. Кстати первый подход к снарядку показал, что активная вкладка стартует побыстрее даже на глаз если подтормаживать старт остальных (в общем-то, ожидаемый результат).
Совсем синхронизировать потоки мне незачем. Pouch это делает для БД, куда-то выше я пока не готов лезть.
Про затирание сообщений – да, я готов с этим примириться, выше объяснял почему.
Плюс надо понимать, что вкладка с Клаудволлом – это уже кооперативная многозадачность, в ней много приложений может быть запущено одновременно. Открывать даже вторую незачем обычно.
no subject
no subject
no subject
Если вкладки будут стартовать одновременно, тебе, по сути, нужна API-level функциональность для атомарного append'а или для синхронизации параллельных потоков (я правильно понимаю, что JS в разных табах исполняется параллельно?). Иначе могут быть неприятные race conditions.
localStorage.setItem("x", x + localStorage.getItem("x")); это, на самом деле, много операций: getItem, взять значение x, сложить, setItem. Interleave между тредами может быть совершенно произвольный. Например, легко представить себе, что ты будешь терять сообщения, потому что между getItem и setItem первого треда выполнится пара из второго (сообщение второго треда будет затёрто тормознутым setItem'мом первого).
no subject
no subject
no subject
no subject
Потому что сам CloudWall так работает, ему ничего не нужно кроме открытой вкладки. Он даже картинки не из сети берёт. Это noBackend и offline-first.
no subject
no subject
а) не во всех браузерах он есть (в IE и Сафари 5- вообще никак, в мобильных плохо работает),
б) в нём будет не поймать момент закрытия других вкладок
в) самое главное – он не видит localStorage.
no subject
no subject
1. Нередко нужно каким-то образом форматировать сообщение лога. API должен быть такой, чтобы отложить форматирование и избежать работы на случай, если данный уровень логгинга выключен. Напр., питоновское: лучше делать log("Price = %0.2f", price), чем log("Price = %0.2f" % price). Во втором случае подстановка и форматирование делаются всегда, а в первом они делаются движком логгера и только при необходимости.
2. Полезные фичи - throttling. Например, логать в этой строке не чаще, чем раз в секунду, или по 1 разу на каждые 100 проходов, или по условию.
no subject
Резало слух, наконец, смог сформулировать, что именно.
Разделяй задачи logging'а и задачи introspection. Если ты будешь думать об этом как о разных задачах и писать для этого разные компоненты, тебе будет легче.
Задача "посмотреть накопившийся лог" входит в круг задач introspection (узнать состояние системы в данный момент), но это лишь одна из задач. В контексте интроспекции нативных предложений может быть полезно посмотреть stack dumps, посмотреть active RPC calls и т.п. Что-то аналогичное может быть полезно и для веба. Будет легче, если во время дизайна и имплементации таких штук не смешивать всё это с логгингом (логгинг это последовательная запись строк в файл).