Comments 16
извините, я не понял, какой алгоритм в результате получился?
Алгоритм работы получается следующим: перегруженный логгер сообщения ниже порогового уровня не пишет в лог сразу, а сохраняет в очередь. Потом middleware принимает решение - показывать эти сообщения, или игнорировать.
Логика такая: если нет признаков потенциального инцидента, то и все сообщения уровня Debug, или Info в рамках текущего запроса можно игнорировать. А если признаки есть, то не просто ошибку показываем, а выливаем в логи всё сохранённое, чтобы было проще разбираться.
а как понять с какого момента нужно писать в лог дебажные сообщения? а если все началось полчаса назад, когда кто-то передал куда-то неправильный аргумент?
Нет, если надо сохранить данные нескольких отдельных запросов, то этот подход не подходит. Он работает в рамках отдельно взятого запроса. Я уже писал ниже, что применял его для API без хранения каких-либо промежуточных состояний.
В вашем случае боюсь, что поможет только тщательная валидация данных при записи изменений и собственно ведение журнала этих изменений с сохранением в отдельное хранилище «кто», «когда» и «что» поменял.
Т.е. это кэш для записей логов класса INFO в ожидании успешности транзакции? Есть ряд вопросов - достаточно ли нам одного шага для понимания причин ошибки или хранить стоит бОльший интервал, не пишут ли в один лог разные потоки, из-за чего нарушится хронология при пакетной записи, если ошибка критическая и грохнется процесс то и следов от этой записи в лог не останется?
По сути, да, это кэш.
Про один шаг немного не понял. В очередь пишутся все записи с момента старта работы над запросом и до момента его окончания. Иначе никак - мы не знаем, в какой момент может произойти событие-триггер.
При этом все ошибки уровня выше Info логируются незамедлительно, как и положено, специально, чтобы избежать проблемы с "всё упало, а логи не записались". И дополнительно пишутся в кэш, чтобы можно было их потом разобрать вместе с остальными.
Основные операции, типа добавления в очередь и поднятия уровня логов, сделаны потокобезопасными. При этом, да, если вызвать ToString в неправильном месте, можно словить эффекты с синхронизацией, но ими я сознательно пренебрёг в угоду скорости.
"одношаговая" я имел в виду в рамках одной транзакции (то что вы называете запросом) - т.е. подразумевается что ошибки имеет смысл ловить только в рамках запроса, более старые редко могут оказать влияние, и там уже логирования уровня INFO не увидим.
Но запись идёт в файл на диске, или в какую-то более сложную структуру? Если мы в реальном времени пишем ошибки, а по окончанию транзакции вываливаем info, то оно будет записано позже, плюс если пишут разные потоки то они ещё успеют накидать "своих" логов в середину, и в файле будет нарушена хронология?
Не совсем. Там Warn и выше пишутся И сразу в лог И в трассировку, которая потом будет показана единой простынёй. Иными словами, мы видим сообщения уровня Warn+:
В моменте и в том месте, где они произошли, Это позволяет отследить событие относительно других запросов/логов уровня warn+
В единой "простыне" сообщений запроса. Там сообщение показывается на своём месте относительно других сообщений этого же запроса без чехарды с записями других запросов. Это сообщение записывается в конце выполнения запроса и, да, проследить info относительно info в других запросах (особенно те, которые не запишутся), нельзя
У нас очень похожая система, TimeMachine называется. Только мы помимо предшествующих логов низкого уровня храним еще историю навигации (последние 10 записей), и при возникновении критической ошибки её тоже скидываем - очень полезно.
Плюс, есть ещё серверный конфиг, который позволяет форсировать отправку логов любого уровня для определённого логгера или юзера. Конфигурируется через админку, можно быстро включить/выключить. Порой очень помогает решить конкретную проблему.
Спасибо за мысли! У нас эти советы не все применимы из-за специфики (stateless, api), но похожую идею, только, наоборот, с выключением логов для конкретного пользователя тоже реализовывали. Были случаи, когда клиенты начинали упорно долбить запросами при закончившемся ключе, организовывая мини-DDOS с "белых" IP, и надо было их либо вручную под протоколы обработки DDOS подводить, хотя всё стабильно работало, либо минимизировать число записей в логах.
Это ж какой адский оверхед на обработку и хранение в памяти выходит. Не эффективнее ли метить записи к контексту относящимися метками типа "userId=xxxxxxxxx", тщательнее продумать структуру и выстроить логику ротации и удаления ненужного?
Судя по графикам потребления памяти, затраты по факту не подскочили вообще. В смысле, они, очевидно, выросли, но оказались меньше погрешности измерения. Вот прямо полный ответ из базы в логи, естественно, за исключением каких-то критических случаев, не пишем, максимум, информацию о количестве найденных объектов. То есть в моменте "простыня" логов занимает значительно меньше места в памяти, чем типичный средний ответ, который уходит клиенту.
Для понимания: все записи метками помечаются в обязательном порядке, логи живут на диске две недели. Но при нагрузке в 1000+ rps размер суточного файла в 50+ Gb на одной реплике был ежедневной реальностью, а при пиковой нагрузке до 140 Gb доходило. Сейчас снизилось до 20 Gb без полной переборки всех мест, где пишутся логи и определения степени их критичности (что тоже отдельная задача с далеко не нулевой трудоёмкостью). При этом за прошедшие 2 месяца не было ни одной ситуации, когда понадобились бы логи, которые сейчас, по факту, идут в сброс после окончания запроса, а вот "простынёй" пользоваться приходилось. Субъективно поудобнее стало.
Ну и, да, я ни разу не утверждаю, что описанный выше способ подходит для всех возможных случаев. Конкретно в нашем - явно помогло.
Идея прикольная но это не работает для всей распределенной трассировки. Ещё бывает надо копать сценарий когда нет Error'ов/Warn'ов.
В плане перфа вижу проблему что мы в ToString потенциально создаем большие строки которые могут засерать LOH
Конечно, это не универсальное решение. Самый лучший вариант - это когда хватает ресурсов для того, чтобы писать все логи на любое телодвижение. Но увы, это не всегда возможно, и приходится применять ту, или иную оптимизацию в ущерб чему-то. В нашем случае был проведён предварительный анализ того, подходит нам такой сценарий, или нет, и только потом сделано внедрение. Ну и уже за почти 4 месяца эксплуатации ни разу пока не было ситуаций, когда мы бы сказали что-то типа "эх, а вот если бы так не сделали, то сейчас бы проблему было легче разбирать".
Про перформанс риск понятен, и мы его тоже и оценивали и мониторили после релиза. За счёт того, что мы в логи полный ответ от базы всё равно не пишем за исключением крайне редких сценариев было понятно, что при сериализации/десериализации данных тратится гораздо больше ресурсов, чем при хранении логов этого запроса. Про фактические результаты я в статье писал - конкретно в нашем случае заметного изменения в потреблении памяти/ресурсов процессора после релиза не было.
Но да, сам посыл абсолютно правильный и если кто-то решит у себя внедрять такой подход, то риски оценивать однозначно надо "до", а не постфактум.
Про перф наверное стрельнуть может какой нибудь цикл с логированием внутри. Например где-то в конце итерации всплыл Warn.
Либо просто запрос с длинным временем выполнения.
Но на практике такие вещи могут быть нужны при отладке, тут да, а потом выпиливаться либо самим разработчиком, либо на ревью.
Ну, либо если такой сценарий реально зачем-то нужен на проде и есть описанные риски, то флаг IsTraceEnabled ставим в false и для этого запроса работает старая логика логирования.
Как сократить размеры логов без потери функциональности