Заметки: Bash

Выложил скрипт на Python для поиска длительных запросов в ТЖ 1С. Накатал его в приступе отчаяния: никак не мог понять, почему мой верный баш для одного из запросов выдаёт среднее время выполнения больше максимального.

Как выяснилось, проблема была в gawk. Для некоторых событий ТЖ эта утилита не могла определить длительность: пыталась преобразовать строку в число, фейлилась и… Нет, что вы! Конечно, не кидалась исключением! Просто невозмутимо считала эти строки за ноль и ехала дальше.

Патч, кстати, вышел ещё глупее проблемы: я просто сделал явное преобразование строки в число, и всё заработало как надо. Чем, блин, явное преобразование в мире gawk'а отличается от неявного? И, главное, почему?

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

Это вполне рабочая тактика, пока входящий поток не переваливает за сотни тысяч элементов: где-то тут мы начинаем терять гигабайты ОЗУ на хранении коллекций и прорву времени процессора на поиске в них. Новый скрипт попрямее: коллекция одна, но хранит всe данные по каждому запросу.

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

Чтобы не быть голословным, давайте пример из практики. Есть, скажем, порядка семидесяти гигабайт логов ТЖ 1С, по которым нужно построить топ пояснений к исключениям — от самых частотных к менее частотным.

Плёвое дело, верно? Выгребаем EXCP, извлекаем Descr, считаем повторения. Даже нужный скрипт я как-то уже писал. Запускаю, терпеливо жду…

Знаете, сколько понадобилось времени? Я тоже нет: после того, как скрипт проработал сутки, я его вырубил и полез разбираться, в чём проблема. Затык возник где-то в скрипте gawk'а: именно она активно нагружала процессор (если не считать cat'а, которая время от времени читала очередную порцию данных).

Беда, беда, огорчение! В общем, я подумал и переписал этот скрипт на Питоне. Новая версия отработала за 15 минут и дала мне:

1. Топ пояснений по событиям исключений;
2. Скрипт, который можно прочитать через полгода без помощи гугла;
3. Уверенность, что я могу добавить в скрипт два-три условия и не вызвать Сатану случайным сочетанием операторов и ключей.

Конечно, я мог оптимизировать версию на баше. Вероятно, тормозит поиск в массиве — время, необходимое для поиска пояснения в массиве уже зафиксированных пояснений, линейно растет с увеличением размера массива. Можно, например, попробовать изменить подход к сбору данных — gawk'ом только извлекать сами пояснения, а результат сбора передать в тандем sort & uniq.

Однако это уже отчётливо отдаёт мемасом про буханку хлеба: из неё, конечно, можно сделать троллейбус, просто не очень понятно — зачем? Камон, мне бы проблему решить. А Питон с ней уже справился на твердую пятёрку, чем сэкономил мне кучу времени и нервов.

Собственно, к этому я вел. Родовые травмы баша понятны и нередко приемлемы, плюсы — приятны и очевидны, но при работе с ним вопрос иногда встает так: cтоит ли только ради того, чтобы получить решение именно на баше, потратить часа два на возню с утилитами, параметрами, мануалами и постами на Stack Overflow?

Вот поэтому не баш, да.

UPD: Хорошая заметка Ивана Гришаева на ту же тему.

Периодически вижу вопросы коллег: а что, 1С всё ещё носится с башем, да? А чё не пайтон-то? Или павершелл, на худой конец? Вот чудаки!

Да, баш не родной для Windows (которая, напротив, родная для 1С) и притащить его туда — отдельная история; да, при усложнении задачи читаемость скрипта падает по экспоненте; да, с некоторыми задачами баш просто не справляется.

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

Пример? Допустим, нужно выгрести из ТЖ исключения; простоты ради договоримся, что достаточно первой строки каждого события. Получим примерно такой скрипт на пайтоне.

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

Согласен! Но давайте сначала решим ту же задачу на баше:

grep -r --include "*.log" ',EXCP,' > result.txt

Вот почему баш.

Обновил скрипт поиска долгих запросов в технологическом журнале платформы. Ранняя версия содержала серьёзный косяк: она старательно группировала DBMSSQL по Sql и Content, но игнорировала случаи, в которых поле Sql отсутствовало (для DBMSSQL это не то чтобы норма, но встречается).

Ну и код слегка причесал, чтобы два раза не вставать: добавил разметку и комментарии, а часть логики gawk'а вынес из основного тела в функции. Да, скрипт стал смотреться длиннее, чем он есть на самом деле, зато читать его стало куда проще.

Мне вообще, по-чеснаку, непонятна причина, по которой ветераны баша трамбуют всю логику в две-три строки: язык и так-то не блещет читаемостью (в телеграм-канале Никиты Прокопова есть отличный текст на эту тему), а при виде страницы конвейеров без единого перевода строки вообще хочется молча выйти в окно.

Выложил на GitHub ещё несколько скриптов для разбора технологического журнала платформы, которые написал за последнее время:

• Частотные события. Группирует события по наименованию, считает количество воспроизведений для каждого и выводит в порядке убывания — от наиболее частотного к наименее частотному. Практического применения у этого скрипта, скорее, нет; просто фиксировал для себя, какой процесс кластера какие события пишет.
• Описания исключений. Группирует EXCP по полю Name; для каждого наименования выводит варианты значений поля Description, которые были у исключений с таким наименованием. С помощью этого скрипта можно составить примерную картину: какие исключения действительно проблема, а какие — просто белый шум, который можно игнорировать и, например, закинуть в фильтры Кибаны.
• Блокировки по ID соединения и области. Удобен для поиска виновника таймаута на управляемых блокировках: скрипт выгребает из ТЖ все TLOCK'и по конкретной области от конкретного соединения, а потом выстраивает их в хронологическом порядке.

Время назад я примеривался к поискам уязвимостей в коде скриптами на bash (звучит грозно, но это просто рекурсивный поиск текста с помощью регулярных выражений). Скрипты-то я тогда написал, но, как сегодня понял — несколько… Ректально, кхм. Для решения хватает одного egrep! То есть из связки find, xargs и egrep можно выкинуть два компонента из трех.

Например, сегодня у нас возникла проблема: конфигурация перестала собираться в последнем релизе EDT. Подозрение пало на битые GUID — ссылки на объекты метаданных, удаленные из конфигурации. Платформа не всегда справляется с их вычисткой после того, как удалит сами объекты; я уже пару раз писал про это (например, здесь или вот тут).

В общем, мы решили порыться в выгрузке конфигурации — найти GUID'ы и оценить, все ли они находятся там, где положено. Общее решение — одна-единственная команда:

egrep -rn '.{8}-.{4}-.{4}-.{4}-.{12}' dump

Ключ r включает рекурсивный поиск, ключ n — заставляет утилиту пристегнуть к найденной строке не только имя файла, в котором найдена строка, но и номер самой строки. Последний параметр, dump — имя директории, где нужно искать.

Регулярку можно сделать точнее, но и такой за глаза хватает. Что до ложных срабатываний (то есть GUID, которые не являются битыми ссылками) — их легко отсеять через пайп. Например, скрипт ниже не будет выводить строки с GUID, в которых есть подстрока «uuid»:

egrep -rn '.{8}-.{4}-.{4}-.{4}-.{12}' dump | grep -v 'uuid'

Как понять, что надо сделать перерыв в работе? Скажем так: если ваш скрипт внезапно начал вам подмигивать — точно пора проветриться.

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

По ходу дела столкнулся в двумя любопытными проблемами, которые меня порядком сбили с толку. Во-первых, я почему-то был уверен, что uniq -c группирует строки вне зависимости от того, где в потоке данных они встречаются. Рассмотрим пример:

банан
банан
груша
банан

Я думал, что если отдать эти данные uniq -c, то она сгруппирует одинаковые строки, посчитает количество повторений и выдаст примерно такое:

3 банан
1 груша

Но на деле получилось так:

2 банан
1 груша
1 банан

Вывод: утилита uniq ожидает, что повторяющиеся строки идут одна за другой. Если строка отличается от предыдущей — она начинает считать счетчик совпадений для неё с нуля. То есть, чтобы получить тот результат, на который я рассчитывал — нужно сначала отсортировать данные, и только потом передавать их в uniq.

Второй проблемой стала утилита sed. С помощью неё я пытался удалить из потока данных всё, кроме часов и минут (текст попытки на 12-й строке скрипта). Однако часть событий упорно не попадали под регулярку несмотря на то, что визуально никак не отличались. Я промаялся кучу времени и здорово разозлился, но потом вспомнил про существование BOM. Вычистил их и дальше все пошло как по маслу.

BOM используется во всех файлах ТЖ (в этом можно убедиться, например, с помощью скрипта). То есть каждый лог начинается с особых символов, которых невооруженным глазом не увидеть и которые могут помешать обработать первую строку файла (так как эти самые символы не будут попадать под условие регулярного выражения).

Вывод: проще всего удалять BOM по умолчанию, не оценивая рисков для каждой конкретной задачи. Да, иногда это будет лишним (например, решению задачи по тексту выше через grep BOM никак не мешает). Но я не люблю сюрпризы. Кроме того, несколько тактов процессора на простую замену — явно выгоднее, чем эквивалент в сгоревших нервных клетках и потерянном времени.

Набросал ещё два скрипта для анализа ТЖ: первый строит топ тяжелых запросов к MS SQL, второй — топ длительных ожиданий на блокировках.

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

Ожидания на блокировках тоже считаются по продолжительности. При этом скрипт проверяет, что у события TLOCK заполнено свойство WaitConnections — то есть платформа действительно ждала возможности установить блокировку, а не просто потратила какое-то время на её установку.

Переписал скрипт на баше, строящий топ исключений по собранному ТЖ: хотел решить эту задачу как-то попроще.

В итоге выкинул из кода возню с заменой начала события на маркер gawk для разделения записей (его можно сразу задать регулярным выражением) и перенес больше логики в скрипт для gawk (так нагляднее, особенно если потом захочется её расширить).

Получилось явно лучше, чем было — во всяком случае, логика выглядит понятнее. Изначально, правда, я хотел скорее сократить скрипт в размере и получить что-то вроде:

grep -hoP ",EXCP,.*\KDescr=.*" */*.log | uniq -c | sort -rn

То есть фильтруем только строки с событием EXCP, отрезаем всё до описания ошибки и группируем с помощью uniq. По-моему, очень изящно.

Однако описание у EXCP может быть многострочным. То есть мы будем время от времени терять часть данных, нужных для расследования (всё описание после первого же перевода строки). Как решить эту проблему так, чтобы скрипт не разбарабанило втрое — я пока не придумал :-)

В прошлом месяце был на митапе «Инфостарта» по безопасности решений на платформе 1С. Узнал кучу интересного! Среди прочего, Олег Тымко обзорно рассказывал про подходы в разработке, которые можно считать потенциальными уязвимостями продуктов. Например, зашитых прямо в код IP-адресов, ссылок, e-mail'ов, паролей и так далее.

Накидал вчера простой скрипт на баше, который роется в выгрузке конфигурации в поисках таких косяков. По сути, эта штука просто пропускает конфигурацию через регулярки — я особо не заморачивался и чисто из спортивного интереса реализовал два-три варианта.

Вывод: для серьёзной итеративной разработки лучше сразу думать в сторону чего-то вроде SonarQube, а не колхозить вот это всё — подходы «в лоб» дают слишком много ложных срабатываний, нужно думать над фильтрами, исключениями, историей и другой обвязкой.

А вот для быстрой оценки такого подхода вполне достаточно — никакой инфраструктуры, никакой возни с настройкой и железом. Выгрузил конфигурацию, пнул баш и, собственно, всё — готовый результат за несколько секунд.

Выложил на GitHub скрипт на баше, который по собранному технологическому журналу 1С определяет наиболее частотные исключения.

Скрипт анализирует события EXCP. Это основной источник информации об ошибках, хотя, конечно, не единственный: например, есть EXCPCNTX (событие, которое началось, но не закончилось в тот момент, когда произошла ошибка). Кроме того, если исключение происходит во время серверного вызова, то в поле RetExcp у события CALL будет текст ошибки, которая вернется на клиент.

Впрочем, в большинстве случаев EXCP и, иногда, EXCPCNTX вполне достаточно. Часто их собирают просто по умолчанию — нагрузки это не создает, зато позволяет прогонять собранные логи через какой-нибудь инструмент аналитики (скрипт выше, например) и держать, так сказать, руку на пульсе.

Задача: нужно найти в общих модулях конфигурации методы с определенным параметром (в этом примере — с параметром DecimalPlacesFor).

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

Первая часть скрипта (до пайпа) выполняет сам поиск, вторая — отрезает лишнее, чтобы на вывод уходили только названия модулей и найденных в них методов. Получится, например, так:

Профит? Профит!