Переносим все логи в журнал регистрации – реально ли и зачем?

Меня зовут Сергей Сковпин. Я представляю компанию «Самокат» – она появилась недавно, но к текущему моменту уже прошла большой путь и стала лидером российского онлайн-ритейла с быстрой доставкой.

Сегодня мы будем ковыряться в журнале регистрации, смотреть, что он может, и какие у него подводные камни.

Что логировать?

Логирование – запись действий программы в какие-либо журналы.

Для нашей компании в первую очередь важно иметь хорошее подробное логирование по обменам. Мы, как ритейл, имеем очень большой набор обменов:

• между внутренними базами 1С;

• с ИТ-системами;

• с внешними подрядчиками;

• с контролирующими органами.

Нам важно иметь четкую картину того, что мы отправили и что мы получили.

Помимо обменов, нам нужно логировать работу информационной системы:

• следить за ошибками;

• отлавливать предупреждения о том, что система пошла не по тому сценарию, который мы ожидали;

• мониторить информацию о работе системы – как у нас что-то запустилось, поработало и отработало;

• в дополнение к этому, нам важно иметь возможность включения режима отладки на логировании – это когда код обкладывается большим количеством логов, которые могут отмечаться каким-нибудь флагом; так мы можем отлаживать приложение в режиме реального времени на продуктовой системе, не включая отладку 1С, без всяких тормозов.

Проблемы

Компания «Самокат» развивалась очень бурно. Мы начали с небольшого стартапа, с одного магазинчика, а потом очень большими прыжками пришли к тому, что есть сейчас. Большое влияние на наше развитие оказала история про пандемию.

По мере своего роста мы стали замечать, что некоторые вещи, написанные на 1С, оказались не готовы к таким скачкам и к такой нагрузке – как по оптимальности кода, так и по архитектурным моментам.

• В частности, мы заметили, что база начала расти и пухнуть быстрыми темпами. Когда начали разбираться, в чем причина такого большого роста, нашли регистры сведений, которые хранили в себе логи. Таких регистров с логами у нас насобиралось примерно на 1 ТБ, а сама база на тот момент занимала 4 ТБ. Т.е. четверть базы хранила в себе логи – данные о том, что мы куда-то отправили, и как что-то работает.

• Поскольку все это сильно росло – по 100 ГБ в месяц – нас это, конечно, не устраивало. Мы начали смотреть, действительно ли это все нужно хранить.

• Учитывая, что это логи, хранить весь объем не имеет никакого смысла. Т.е. нам нужно иметь в горячем доступе какой-то хвост за последний период, а все остальное можно либо удалять, либо выносить куда-то в другое место.

• Но оказалось, что когда таблица разрастается до больших объемов, удалить запись из нее не так-то просто. Попробовав реализовать такое удаление средствами самой 1С, разработчики пришли к выводу, что на очистку самого большого регистра потребуется неделя-две работы – этого времени ни у кого нет.

• Помимо того, что вычищать регистр сложно, он занимает большой объем. А это приводит к тому, что он деградирует по производительности. 2/3 этого объема – это индексы, когда они сильно разрастаются, работа с ними затрудняется. В итоге запись и чтение занимают намного больше времени, чем раньше. Наша система постепенно деградирует на простых операциях логирования, которые не должны тормозить систему ни в коем случае.

• И последний проблемный момент при логировании на регистрах сведений – это транзакционность. В принципе хранение логов в традиционной базе – не лучшая идея. Когда разработчику нужно иметь возможность записать лог, причем не просто информацию об ошибке или о том, что что-то упало, а какие-то дополнительные данные, собранные во время работы программы (что привело к проблеме, какой набор данных обрабатывался), ему приходится каким-то образом выбрасывать эти данные наверх и потом записывать уже в отдельную транзакцию. Т.е. есть проблема записи логов в транзакции, и с ней приходится жить.

Требования к логированию

Мы пришли к тому, что логирование на регистрах сведений нам точно не подходит, нужно от этого уходить. Начали искать варианты решения и выдвигать определенные требования к той системе логирования, которую мы хотим у себя видеть.

Мы хотели получить:

1. Универсальность. Под универсальностью я подразумеваю, что у нас должна быть единая точка входа для всех логов – чтобы все лежало в одном месте, в одной системе. Чтобы было удобно выстраивать события в хронологическом порядке – как система жила до падения либо до ошибки.

2. Хранение логов вне основной базы. Все очевидно: логи занимают много места, и хранить их в базе ни к чему. База и так большая, еще больше ее раздувать на ровном месте совершенно не хочется.

3. Высокая скорость записи логов. Логирование не должно тормозить нашу систему. Не должно быть такого, что чем больше логов мы добавляем в систему, тем драматичнее у нас история с производительностью. Логирование должно быть быстрым, легким и без всяких проблем.

4. Простота обслуживания, ротация логов. Проблема с регистрами сведений была в том, что мы не могли удалять из них записи в какие-то приемлемые сроки. А нам нужно было такую возможность иметь – логи постоянно отживают свой срок, их нужно постоянно удалять, подчищать. Эта операция должна быть тривиальной, она не должна приводить к проблеме.

5. Компактность хранения. Сейчас прирост логов журнала регистрации у нас занимает порядка 250 гигабайт в месяц, а бизнес требует хранить логи в течение полугода. Это значительные объемы, и их увеличивать совершенно не хочется.

6. Не последняя по важности вещь – надежность. Мы хотим, чтобы наша система была надежной, чтобы логи не потерялись, никуда не отвалились. Чтобы мы в любой момент времени знали, что происходило в системе.

Варианты

Какие варианты мы рассматривали?

1. Оставить все как есть: регистры сведений и справочники. Проблематику этого варианта я уже описал – для справочников ситуация аналогичная. Мы от этого варианта отказались, но если кто-то хочет все-таки остаться на регистрах сведений и справочниках, единственный способ масштабироваться – использовать секционирование таблиц.

2. Сторонняя система логирования. Можно выкидывать логи в тот же Elastic либо в Sentry – в какую-то другую систему, которая хорошо работает с логами и умеет хорошо по ним искать. Но тут появляется зависимость от внешней системы, и мы получаем дополнительную точку отказа в нашей инфраструктуре. Если у нас что-то произойдет – либо канал упадет, либо сама сторонняя система откажет – нам нужно это предусмотреть. Либо нам нужна запасная площадка для логов. Либо нам нужно это в коде обыгрывать. Либо ничего не делать и остаться без логов на какое-то время, пока все не починят.

3. Еще один вариант, который также имеет на право на жизнь, – это прокси-сервер. Если для нас важно иметь логирование именно обменов – что к нам в базу приходит, и что от нас из базы выходит – можно поставить проксирующий сервер и прогонять данные через него, чтобы они одновременно логировались. И мы сможем посмотреть, что к нам пришло, что от нас уехало. Но в итоге мы получим несколько систем хранения логов: у нас есть журнал регистрации, и есть журнал проксирующего сервера. И в случае какой-то проблемы нам придется несколько журналов между собой сравнивать, выстраивать их данные в хронологическом порядке. Это проблематично. Особенно если у нас виртуалки, например, на разных машинах лежат, и там рассинхрон во времени – достаточно 1 секунды рассинхрона, и нам уже придется думать, как сопоставить между собой два списка событий с разными временными метками.

4. Последний вариант – это, конечно, журнал регистрации. Из названия доклада понятно, что мы пошли по последнему варианту и начали рассматривать ЖР как единую точку для хранения всего-всего.

Логирование в ЖР: плюсы и минусы

Какие плюсы журнала регистрации мы выбрали для себя:

• Первый плюс в том, что журнал регистрации – это платформенный механизм.

  • Он универсален – у нас всегда есть единая точка, куда мы все пишем.

  • И он надежен – работает ровно до тех пор, пока работает сам сервер 1С. Это здорово.

• Второй плюс – это запись в текстовый файл.

  • Это решает проблему транзакционности, поскольку мы выносим лог из транзакций. Разработчик не заморачивается – запишется или не запишется, и как с этим быть. Он просто пишет все в коде, и это сразу же попадает в лог.

  • В то же время появляется история с легкой автоматизацией ротации: в зависимости от настроек файлики бьются на кусочки – у нас каждый час новый файл. И мы можем спокойно брать эти кусочки, архивировать, перекладывать на другие диски. А потом, если вдруг потребуется что-то с этим делать, можем перекинуть на какой-нибудь тестовый сервер и там разворачивать.

  • И благодаря тому, что каждый час создается новый файл, появляется стабильность записи при масштабировании. Мы не имеем какого-то гигантского файла, который операционная система не могла бы прочитать либо дописать в него. У нас каждый час пишется новый файл, и мы имеем стабильную запись, стабильную скорость.

Если говорить про недостатки журнала регистрации, то это:

• Всем известная медленная скорость его работы. Все знают, как тяжело работать со штатным сервисом журнала регистрации, какие мучения доставляет поиск и разбор каких-то проблемных ситуаций. К сожалению, это так.

• Вторая проблема – это неизвестность. Неизвестность заключается в том, что, вроде бы, журнал регистраций у всех на слуху, и все о нем знают. Но что он на самом деле умеет? Какая у него скорость записи? Какие у него пределы по скорости записи? Как он параллельно пишет? Появляются вопросы, ответы на которые хочется узнать до того, как начинать им пользоваться для повсеместного логирования.

Именно эти вопросы мы решили как следует разобрать и осветить в этом докладе.

Скорость записи ЖР на разных носителях, исследуем пределы

Мы подготовили тестовый стенд: насобирали ядер на процессор, подготовили оперативки.

И подготовили 4 диска, так как было предположение, что в зависимости от скорости диска будут сильно отличаться пределы скорости записи в журнал регистрации:

• Первый диск – SSD на интерфейсе SATA.

• Второй диск – тоже SSD на интерфейсе NVMe.

• Третий диск – это особый диск на Optane, безумный по мелкоблочным операциям.

• В конце мы решили добавить еще и RAM Disk, чтобы использовать почти все имеющееся.

Единственное, что мы сюда не добавили, – это HDD диски. Ими уже не нужно пользоваться на таких вещах. Единственное место в инфраструктуре, где мы пользуемся HDD дисками, – это холодное хранение бэкапов.

Все это мы крутили на платформе 8.3.18.

Вот такое текстовое сообщение в формате JSON мы писали в журнал регистрации, а потом прогоняли тесты: в 1 поток, потом в 2, потом в 4 и т.д. И смотрели, сколько таких сообщений в секунду мы можем записать.

Итог такого тестирования перед вами:

• по оси Х – количество потоков;

• по оси У – количество записей этого JSON в секунду.

Первое, что бросается в глаза – что какой-то разительной разницы между тем, на какой диск писать, нет.

• На последнем месте ожидаемо оказался SDD, но он очень слабо отстает от победителей, и до 8 потоков вообще никакой разницы нет.

• Второе, что мы можем увидеть, – что NVMe и Optane вообще идут одинаково.

• На удивление RAM Disk не показал таких же результатов, как NVMe и Optane. Он был чуть-чуть медленнее и ограничивается здесь 64 потоками из-за того, что в бесплатной версии у нас место на нем закончилось. Больше потоков мы туда нагрузить не могли – не помещался у нас журнал регистрации.

Так выглядит результат записи на поток. Здесь опять можно увидеть, что разительной разницы между тем, на какой диск писать, нет.

После этого мы начали анализировать, как себя ведет сервер 1С во время такой тяжелой записи в журнал регистрации.

Из интересного:

• Сколько бы потоков мы не нагрузили, мы не смогли вывести в сервис журналов регистрации rmngr значение больше 43%. И не важно, сколько rphost в него пишется: в левой части картинки 1 rphost его нагружает, в правой – 8 rphost.

• И общая нагрузка на систему тоже сохраняется примерно на одном и том же уровне.

• Еще мы увидели, что нагрузка между rmngr и rphost делится примерно пополам.

Если внимательно посмотреть на графики, видно, что пик производительности в районе 16 потоков. 16 х 2 = 32, а ядер у нас 24. Поэтому появилось предположение, что, возможно, мы просто упираемся в количество ядер, и пределы записей ЖР еще выше. Поэтому мы запустили эти же тесты на 64-х ядерном процессоре. И получили вот такой результат:

Т.е. на 64 ядрах максимальная производительность оказалась действительно немного больше.

При этом мы расширили тестирование между 8 и 16 потоками и увидели, что:

• при 24 ядрах рост скорости записи заканчивается в районе 12-14 потоков;

• а при 64 ядрах рост как раз доходит до 16 потоков.

Поскольку 24 ядра у нас более герцовые, этот вариант до определенного момента показывает лучший результат.

Из этого мы сделали вывод о том, что журнал регистрации упирается в параллельность в 16 потоков.

Если кому-то когда-то потребуется нагружать журнал регистрации до предела – не знаю, зачем – знайте, что больше 16 потоков он не потянет.

Дальше мы уже начали развлекаться. Раз уж мы все подготовили, у нас есть хорошие циферки, решили смотреть и другие форматы.

Здесь мы видим график сравнения производительности журнала регистрации последовательного формата и формата SQLite.

Ожидаемо, что SQLite сильно хуже, особенно в вопросах параллельной записи. Он уже на 4 потоках доходит до своего предела, а потом еще немного даже может деградировать.

И по заветам прошлой конференции мы проверили, как работает с отладкой и без отладки.

Ожидаемо оказалось, что с включенной отладкой на сервере журнал регистрации работает медленнее. Но удивительно, что в районе 16 потоков происходит небольшой скачок. Три раза запускали и перепроверяли, он есть.

После пройденных тестов мы сделали для себя следующие выводы:

1. запись в журнал регистрации идет быстро – до 500 тысяч событий в секунду, что для нас очень большой запас;

2. скорость записи не сильно привязана к качеству диска, мы можем на обычном SSD спокойно жить, нам не нужно покупать более дорогие диски, чтобы писать в журнал регистрации;

3. экспериментально было выяснено, что максимальная производительность параллельной записи в журнал регистрации достигается при записи в 16 потоков, сильнее параллелить запись смысла не имеет.

Как с этим работать дальше: 1C-ELK-Grafana

После тестирования мы вернулись к первой проблеме – медленное чтение журнала регистрации.

Но на самом деле это давно уже не проблема – все везде пишут, что удобнее и быстрее всего работать с данными журнала регистрации, если выгружать его в какую-то стороннюю систему. У нас это ELK стек и Clickhouse.

ELK стек хорош тем, что у него:

• большое сообщество;

• куча плагинов;

• отличная визуализация в kibana, можно делать красивые дашборды – там копаться в логах достаточно приятно;

• но у него есть существенный недостаток: он имеет достаточно большой объем хранимой информации. Наши тесты показывают, что на одну ноду расходуется 125% от объема 1С-ного журнала регистрации, а в проде нод, конечно, несколько, поэтому объем получается весьма значительный.

Поэтому на Elastic мы храним только хвост за последние 2 недели, а чтобы хранить информацию о логах за последние полгода, у нас есть Clickhouse, у которого:

• безумная скорость работы;

• он отлично все жмет – по результатам наших тестов получается порядка 15% от исходного объема логирования;

• и у него бесплатный ODBC интерфейс – это здорово.

Тут пара скриншотов kibana, как ELK стек выглядит вживую.

• Слева вверху – как можно поискать информацию, как она выглядит, в каком формате.

• Справа снизу – дашборд на kibana, где мы можем посмотреть какие-то ошибочки.

А здесь скриншоты Tabix – это наиболее распространенная и наиболее удобная оболочка для Clickhouse.

Здесь тоже ничего сложного нет – простой SQL язык, с которым справится любой разработчик 1С. И можно очень быстро получить какую-то информацию по запросам из журнала регистрации.

Выводы

Сейчас мы пишем все в журнал регистрации – нам это нравится. Все системы, которые у нас есть, мы переводим на него, с разработчиками тоже договорились.

• Пользуйтесь журналом регистрации! Он универсальный и быстрый.

• Учитесь выгружать журнал регистрации в сторонние системы.

• И любите свои логи.

P.S. от Антона Дорошкевича

В платформе 8.3.20 фирма «1С» тоже озаботилась медленным чтением журнала регистрации и сделала индексы у текстового формата журнала регистрации.

Это, конечно, не ClickHouse и не Elastic, но стало намного быстрее.

Журнал регистрации меганадежный, и очень важно, что это – асинхронная штука, он работает вне транзакций, пока работает сервер 1С. Когда у вас сдох сервер 1С, вам без разницы, что там не логируется, потому что мертвые не потеют, там нечего логировать.

Вопросы

В начале вы сказали, что вы используете логи, чтобы не включать отладку. Что у вас есть какой-то тумблер, который позволяет вам получать расширенную информацию о поступлении и отдаче запросов. Как вы это сделали?

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

Это все включается параметром. Грубо говоря, есть триггер, и когда мы его включаем, система начинает генерировать большой объем логов. Постоянно это делать не нужно, потому что это чрезмерный объем логирования.

Но в те моменты, когда нужно провести расследование, разобраться, почему тут – так, а здесь – так, включается тумблер, идем в логи и рассматриваем все там.

Даже у фирмы «1С» это – неофициальная рекомендация. Они тоже рекомендуют ориентировать запись журнала на какую-то константу. Включил – пишем, выключил – не пишем. Отличная штука. У всех, у кого болит, что нельзя делать отладку на проде – только так и узнаешь.

Сталкивались ли вы с проблемой, что в журнале регистрации слишком свободный формат записи? Например, туда можно записывать события с идентификатором – из-за этого получается огромное количество событий, и все с разными индексами. С этим невозможно работать, это не стандартизируется. У нас нет ограниченного количества справочников событий, мы можем писать все что угодно.

Там слишком свободное только одно поле – это «Комментарий». Если разработчик много пишет, с ним можно договориться, и он будет писать то, что нужно. Проблемы, что туда много положат, нет.

Если этот индекс действительно нужен, записывайте, все будет нормально. Clickhouse переварит.

Логи, которые делают программисты для отладки, – это здорово, прикольно. А если технологические логи, техжурнал по такой же схеме сделать – выгружать в Elastic или в ClickHouse. Это ложится?

Ложится. У нас сейчас это не поднято, но мы собираемся в ближайшее время начать экспортировать свой техжурнал либо в Clickhouse, либо в Elastic. Куда – еще не решили до конца. Для этого есть инструменты у Юрия Пермитина и у Вадима Фоминых. Это можно сделать.

По опыту скажу, не нужно техжурнал складывать в Elastic, он занимает очень много места на каждой ноде. В нем много лишней информации, его нужно правильно парсить. С помощью какого программного обеспечения отправляются логи в тот же Elastic или Clickhouse?

Мы пользуемся разработкой https://github.com/akpaevj/OneSTools.EventLog. Ее хорошо описали на канале «Веселый 1С». Там вы найдете отличную инструкцию, как свой журнал регистрации выгружать в Elastic или Clickhouse, кому что удобно.

*************

Статья написана по итогам доклада (видео), прочитанного на конференции Infostart Event.