Хабр Курсы для бэкендеров
РЕКЛАМА
Практикум, Хекслет, SkyPro, авторские курсы — собрали всех и попросили скидки. Осталось выбрать!
Поток Бэкенд доступен 24/7 благодаря поддержке друзей Хабра
Комментарии 10
Есть сообщения, которые важны по факту своего появления, но не несут новой информации при повторении. Типичный пример — ошибка записи на диск: пока операция ретраится, лог может заполниться одинаковыми строками. С точки зрения диагностики достаточно знать, что проблема есть; всё остальное только мешает.
Просто какое-то "безумие и отвага". Когда возникают ошибки записи на диск лучше бы током кого-то било при каждой ошибке, а не все кроме первой под ковер заметались...
я говорю ведь не о заметании под ковер, а мусоре. ок, если не нравится этот пример, можно ведь придумать и другие. речь о том, что зачастую не хочется видеть миллион одинаковых сообщений которыми забит весь лог. и это задача именно программиста решить уместно ли печатать это один раз или миллион. я говорю о возможностях, а не о том как следует их использовать
Вопрос влияния на производительность при генерации сообщений ниже требуемого уровня логирования оставляем в стороне?
конечно же никто не отменял традиционные методы фильтрации логируемых сообщений. это и уровень. да собственно и возможность полной блокировки вывода в лог. если интересно, посмотрите другую мою статью - https://habr.com/ru/articles/1012874/
Речь про другое: если сообщение не нужно на текущем уровне логирования, то вообще не надо его формировать, включая форматирование и прочее.
так и происходит в библиотеках, которые я рассматривал
обратите внимание что в предлагаемой к вниманию статье benchmark библиотек логирования C++ в разделе Overhead логирования как раз рассматривает то о чем выв говорите и приводятся конкретные результаты тестирования. к условиям тестирования могут быть претензии (например, в стиле "Quill показал не лучшие результаты потому что его тестировали не в тех условиях для которых он предназначен"). но ведь там как раз суть тестов в измерении затрат на логирование в ситуации когда форматировать не нужно
Все верно в общем и целом. Пришли примерно к тому же (плюс-минус, учитывая нашу специфику - у нас вся работа с БД, соответственно, логи тоже пишутся в таблицы БД + есть настроечные таблицы для каждой системы логирования)
Мы пришли к такой структуре. В настройках:
Узел логирования (близко к тому, что у вас называется "подсистема")
Текущий уровень логирования (остановились на трех уровнях - E - вывод только ошибок; B - вывод ошибок и бизнес сообщений и T - ошибки, бизнес сообщения и трейсы)
Статус активности узла
Глубина хранения лога для каждого уровня логирования (например, D007 для E; D005 для B и D002 для T) - поскольку все в таблицах БД, сопровождение в начале каждого дня запускает скрипт прочистки лога где удаляется все, выходящее за глубину хранения.
В самом логе:
Дата
Таймштамп
Узел логирования
Полное имя задания (у нас все работает в изолированных заданиях - job, потоки внутри задания используются мало)
Уровень логирования
Ключ сообщения (используется для дополнительной фильтрации, может использоваться, например, для связки сообщения об ошибки с конкретной записью в БД при обработке которой эта ошибка произошла)
Данные сообщения
Точка вызова (позволяет привязать сообщение к конкретной точке кода где оно случилось)
Кроме собственно функций записи в лог есть функция AllowLog где указывается узел логирования и уровень логирования. Сделана она для того, чтобы не тратить время на формирование сообщения лога в тех случаях, когда оно до лога не дойдет (узел логирования не активен или для него установлен уровень E, а сообщение имеет уровень B или T). Это уже было добавлено позднее по результатам нагрузочных тестов.
Поскольку логи в БД, то работа с ними потом обычным скулем - просто, быстро и никаких проблем с фильтрацией по любому параметру (сочетанию параметров).
Да, очень похоже на то, к чему в итоге приходят в реальных системах
Особенно показательно, что у вас:
есть разбиение на узлы
уровень управляется отдельно
и отдельно появился AllowLog после нагрузочных тестов
Это как раз иллюстрирует основной тезис статьи — логирование начинает жить своей жизнью, как отдельная подсистема, а не просто “вызовы printf”.
Про AllowLog — это вообще классический момент. Почти везде к этому приходят, когда становится понятно, что стоимость формирования сообщения иногда выше, чем его запись.
С БД как хранилищем тоже понятный выбор, особенно если потом активно анализируете логи SQL-запросами. Тут уже больше вопрос компромисса между удобством анализа и нагрузкой на саму систему хранения.
В целом хороший пример того, что в проде важнее управляемость и структура.
С БД как хранилищем тоже понятный выбор, особенно если потом активно анализируете логи SQL-запросами. Тут уже больше вопрос компромисса между удобством анализа и нагрузкой на саму систему хранения.
Тут влияет специфика платформы - мы работаем на IBM i (AS/400), тут БД (DB2) является частью ОС, интегрирована в нее на низком уровне (включая SQL движок) и посему очень быстрая. Особенности файловой системы, что тут нет файлов как таковых. Все есть объект. Есть объект типа PF - физический файл. Это таблица. Есть LF - логический файл, индекс (несколько шире на само деле, но ближе всего индекс), есть DSPF - дисплейный файл, описание экранной формы, есть PRTF - принтерный файл, описание формы для вывода на печать (в спул печати). А вот просто текстового файла тут нет (как хранятся исходники лучше не спрашивать - начну рассказывать во всех подробностях :-)
Параллельно нативной ФС есть еще "интегрированная файловая система (IFS). Это уже UNIX-like ФС.
Т.е. варианты вывода - в таблицу БД, на IFS или в спул печати. Так вот в БД не только самый удобный для последующей работы - интерактивный скуль тут есть как в терминале, так и отдельным приложением, не требующим терминала (оно еще и умеет планы запросов показывать и диагностику всякую), но и самый быстрый и экономичный по ресурсам.
Все остальное - да, выросло в процессе работы. Система очень большая, команд много. У каждой команды в принципе своя подходы. Принципы общие, но в деталях могут быть различия. Одно время (где-то 18-19-й годы) обсуждалась централизованная система логирования, но потом пришли к тому, что будет слишком громоздко и сложно учесть во всех деталях требования всех команд. А поскольку каждая команда отвечает за свой участок (скажем, мы, комплаенс, никогда не полезем в зону ответственности той же системы расчетов или тарифного модуля), то у каждой команды свои логи. Иногда (по необходимости), их может быть несколько - у нас есть общий и еще пара под конкретные линейки, там, где требуется какая-то специфическая информация помимо той что описал выше).
В целом хороший пример того, что в проде важнее управляемость и структура.
На самом деле, производительность нам тоже важна т.к. система высоконагруженная. И каждая поставка, помимо компонентного, бизнес и интеграционного тестирования обязательно проходит этап тестирования нагрузочного.
Но без логирования нельзя - это не только расследование инцидентов, но и выявление не консистентности данных, выявление ситуаций когда автоматическая обработка не проходит и требуется ручной разбор (например в каких-то ситуациях когда идет массовая обработка, та же ежегодная актуализация где в выборку попадает 25+ млн записей и какие-то из них выдают ошибку и потом уходят на ручной разбор)... Там много чего может быть.
Но здесь идет речь исключительно о продуктовых логах. Т.е. тех ошибках, которые перехватываются и обрабатываются. К сожалению, бывают и падения - необработанные исключения. Это уже отражается в системных логах - у каждого задания всегда есть свой joblog, который ведется системой (мы, конечно, можем туда сообщения кидать, но стараемся этого не делать - они и так достаточно объемные). Пока задание активно, его можно смотреть в терминале системной командой или скулем с использованием системной UDTF. По завершению задания joblog преобразуется в спульник (spool file) и уходит в спул печати профайла из под которого это задание было запущено. Дальше его уже можно с сервера на комп вытащить в виде txt или pdf. Там все достаточно подробно, примерно вот так:
MCH6802 Escape 40 28.03.26 19:56:13.901238 QLEAWI QSYS *STMT QLEAWI QSYS *STMT
From module . . . . . . . . : QLEDTAWI
From procedure . . . . . . : CEEUTCO
Statement . . . . . . . . . : 2
To module . . . . . . . . . : QLEDTAWI
To procedure . . . . . . . : CEEUTCO
Statement . . . . . . . . . : 2
Message . . . . : Literal values cannot be changed.
Cause . . . . . : An attempt was made to write over a literal (constant)
value. A common cause of this exception condition is supplying the address
of a literal as an argument when the called code is expecting to return
information at that address. Note that all program calls pass arguments by
address. The object that contains the literal value is QRNXUTIL.И сопровождение говорит "там у вас упало", то сразу "давайте джоблоги и если есть дампы".
Т.е. тут есть разделение на логи продуктовые и системные. Продуктовые делаем сами, системные, к счастью, ведет система без нашего вмешательства.
Зарегистрируйтесь на Хабре, чтобы оставить комментарий
Логгер — это не про скорость: что действительно важно в дизайне