1С и СУБД Tantor: история одного внедрения

• Постановка задачи
• Заполнение документа "Резервы по оплате труда" в базе ЗУП
  • Описание проблемы
  • Как планировщик делает оценку по таблицам без статистики
  • Как работает платформа с временными таблицами, создаваемыми из таблицы значений
    • Создание временной таблицы без индексов
    • Создание временной таблицы с индексом
  • Решаем проблему с помощью плагина online_analyze
• Расчет себестоимости за период в базе УХ
  • Описание проблемы
  • Сравниваем данные логов СУБД и "1С"
  • Анализируем окружение и готовим скрипты
  • Неожиданный результат
  • Причины долгой вставки
• Перепроведение документов в базе УХ
  • Описание проблемы
  • Оптимизация запроса
  • Predicate pushdown в Postgres
• Заключение

Меня зовут Александр Симонов, я руководитель направления развития и поддержки 1С в компании "Тантор Лабс".

В рамках клиентских пилотов по миграции на СУБД Tantor Special Edition 1C мы сопровождаем процесс приемо-сдаточных работ и оказываем поддержку в ходе тестирования.

В данной статье рассмотрим пример доработки СУБД Tantor под потребности 1С, а также расследуем причины медленного выполнения запросов у одного из наших клиентов. 

Постановка задачи

Тестовый стенд

Оба сервера СУБД виртуализированы. Они сильно различаются по характеристикам, но организовать равноценные стенды у заказчика не было возможности.

Тестируемые операции:

1. Заполнение документа "Резервы по оплате труда" в базе ЗУП.
2. Расчет себестоимости за период в базе УХ.
3. Перепроведение документов в базе УХ.

Каждая из них сначала выполняется на MS SQL, а затем – на Tantor.

Заполнение документа "Резервы по оплате труда" в базе ЗУП

Описание проблемы

Были получены следующие результаты:

MS SQL – 478, Tantor – 855 сек.

Созвонившись с заказчиком, выясняем, что настройки Tantor у него дефолтные. Настраиваем систему в соответствии с нашими рекомендациями и получаем результат 697 сек.

Разница более 200 секунд, это плохой результат, поэтому начинаем разбираться в причинах. Заказчик собрал технологический журнал и логи СУБД. Проанализировав его, видим, что у нас есть топ запросов, которые долго выполняются.

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

Находим проблемный запрос в логе СУБД, получаем план и видим причину: дело в том, что планировщик неправильно оценил количество строк во временной таблице:

Но почему планировщик может так ошибаться? Ведь для таблицы должна рассчитываться статистика, т.к. при ее создании платформа 1С сама вызывает команду ANALYZE. Ситуация выглядит странно.

После этого мы развернули пустую конфигурацию ЗУП и нашли запросы по проблемному контексту:

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

Полученную базу мы развернули на своем стенде:

Проблемные запросы у нас выполнялись так же долго, и мы cобрали лог технологического журнала (ТЖ) по событию DBPOSTGRS без фильтра по длительности, и из такого лога причина стала понятна: по временной таблице не была рассчитана статистика. Поговорим немного о ней.

Как планировщик делает оценку по таблицам без статистики

Каким образом планировщик получил оценку в 5 строк (метка 1 на рисунке ниже), если по таблице нет статистики?

В подобных случаях планировщик оценивает количество строк, исходя из размера файла с таблицей и ширины строки (метка 2 на рисунке).

Оценка в 5 строк учитывает наложенные отборы из поля Filter (метка 3 на рисунке). Для колонок, по которым нет статистики, планировщик использует фиксированную оценку – 0.5% от количества строк. У нас отбор накладывается на 2 колонки, и эту оценку планировщик дает для каждой из них. В итоге мы можем получить формулу:

Количество строк в таблице * 0.005 * 0.005 = 5.

Давайте вспомним базовые уроки алгебры и вычислим, сколько, по мнению планировщика, в данной таблице строк (до наложения отборов): 5/(0.005*0.005) = 200 000

Получается, исходя из ширины одной строки и размера файла, планировщик подумал, что в таблице tt268 примерно 200 тысяч строк. После наложения фильтра по указанной выше формуле получается оценка – 5 строк. 

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

Давайте вернемся к нашей проблеме и посмотрим какие команды выполняются при создании временной таблицы из таблицы значений.

Такая временная таблица создается конструкцией "COPY pg_temp.tt FROM STDIN BINARY" вместо привычной конструкции "INSERT INTO pg_temp.tt (список колонок) SELECT ... FROM ...", которая используется при создании временной таблицы выборкой из результата запроса.

Создание временной таблицы без индексов

Запрос 1С:

В этом случае на СУБД будут выполнены две команды, согласно данным ТЖ событий DBPOSTGRS:

В поле RowsAffected содержится количество строк, помещенных в созданную временную таблицу.

Создание временной таблицы с индексом

Если при создании временной таблицы сразу создать в ней индекс, получится следующее:

Запрос 1С:

 В этом случае, по данным ТЖ событий DBPOSTGRS, на СУБД будут выполнены следующие команды:

Получается, что платформа не выполняет команду ANALYZE по временной таблице (создаваемой в результате передачи таблицы значений в запрос), если при этом в ней сразу не создать индекс. 

Возникшую проблему отсутствия статистики на временной таблице можно было бы решить двумя способами:

1. При создании ВТ создать индекс.
2. Из созданной ВТ переложить данные в новую ВТ, которую далее и использовать.

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

Решаем проблему с помощью плагина online_analyze

Пробуем включить и настроить плагин online_analyze, который как раз и предназначен для того, чтобы выполнять команду ANALYZE, например, для временных таблиц.

Включаем плагин:

Запускаем снова наш тест – результат такой же. Передаем кейс в команду разработки СУБД и в ходе их анализа узнаем, что в плагине не учтена операция создания таблицы методом COPY FROM, поэтому ANALYZE не вызывается.

Команда СУБД доработала плагин online_analyze, чтобы он учитывал этот метод создания таблицы. Пересобрали сборку Tantor, установили ее на свой тестовый контур и после выполнения теста получили следующий план проблемного запроса, в котором оценка строк во временной таблице максимально близка к реальной:

Результат до оптимизации – 97150 мс, после – 346 мс, т.е. стало быстрее в 280 раз благодаря тому, что планировщик правильно посчитал строки во временной таблице и выбрал более подходящий оператор соединения двух таблиц: Hash Join вместо Nested Loops.

На стенде заказчика с новой сборкой Tantor мы получили результат 545 сек., т.е. на 140 сек. быстрее, чем было, но все равно на минуту медленнее, чем на MS SQL.

На своем стенде у нас оказался совсем другой результат – 398 сек., при этом мы еще раз синхронизировались с заказчиком, чтобы убедиться, что время выполнения операции фиксируем одинаковым способом и данные при тестировании у нас и у них совпадают. Стоит также отметить, что для параметра default_statistics_target в наших тестах было установлено значение по умолчанию – 100. Если поставить 1000, все ускорение выполнения запросов нивелировалось временем, уходившим на выполнение команды ANALYZE для временных таблиц: они создавалось в большом количестве и содержали по 100К-400К строк.

Итого получились следующие результаты:

• MS SQL – 478 секунд;
• Tantor после настройки параметров – 697 секунд;
• Tantor c доработкой online_analyze – 545 секунд;
• Tantor на нашем стенде c доработкой online_analyze – 398 секунд.

Длительность на наших стендах сильно различалась, поэтому мы решили собрать ТЖ событий DBPOSTGRS без фильтрации по длительности и сравнить со своими показателями. Получилось, что у нас суммарное время выполнения всех запросов 137 сек., а у заказчика – 208, что наводит на мысль, что на его стенде, возможно, есть инфраструктурная проблема, которая негативно влияет на результаты. С ней мы подробно разбирались при тестировании следующей операции. 

Также мы передали информацию по данному кейсу в фирму "1С". Коллеги оперативно сделали доработки, и исправление выйдет в ближайших июльских релизах. 

Расчет себестоимости за период в базе УХ

Описание проблемы

Для данной операции были получены следующие результаты: MS SQL – 80 мин, Tantor – 300 мин.

В кейсе с УХ Tantor тоже не была настроена. Следовало сначала все-таки ее настроить и запустить повторно: это уберет часть проблем, и мы получим результат, с которым дальше можно работать. Также мы рекомендовали заказчику установить наш последний релиз 15.6 с оптимизациями для "1С".

После этого длительность уменьшилась до 241 мин.

Далее нужно было убедиться, что проблема именно в СУБД, и в этом нам помог собранный ТЖ событий DBPOSTGRS.

Проанализировали его следующим скриптом:

Данный скрипт сначала считает общую длительность всех событий DBPOSTGRS, а затем расшифровывает ее до поля t:clientID. Получился вот такой результат в микросекундах:

Общая длительность составила 245 минут, она возросла из-за того, что был проанализирован лог за 5 часов, куда попали и другие события до и после запуска теста. 

В разрезе t:clientID видно, что 99.9% времени ушло на одно соединение, т.е. операция не выполнялась многопоточно, и мы можем сделать вывод, что проблема на стороне СУБД.

Группируем логи ТЖ по запросу и контексту и видим: явного лидера по времени, который бы занимал львиную долю всех 245 минут, нет, но обращает на себя внимание то, что в топе элементарные запросы, например, вставка одной записи в таблицу:

Может показаться, что вставка идет долго из-за большого размера версии объекта, но в других примерах, по логике, блобов нет, а также в логе ТЖ есть и другие элементарные запросы типа выборки по ссылке, выполняющиеся по 15 мс, которые, по опыту, должны занимать менее 1 мс:

Сравниваем данные логов СУБД и 1С

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

1. Собрать планы запроса, чтобы если время выполнения там будет такое же, увидеть, на что оно тратится. Устанавливаем auto_explain.log_min_duration в 5 мс.
2. Не обязательно перезапускать весь тест. Достаточно провести один документ, который создает версию объекта.

Попросили заказчика это сделать и прислать логи ТЖ и СУБД.

Проанализировав эти логи на примере проведения одного документа, получили следующий результат:

Вставка в регистр накопления (версия объекта не создалась, поэтому для анализа мы взяли другой запрос), по данным ТЖ, занимает 844 мс, а в данных плана запроса из лога СУБД – 15 мс. На предыдущем месте работы я сталкивался с кейсом, когда сетевое взаимодействие между СП и СУБД было организовано не по выделенному для этого каналу, а по общей сети и приводило к такой же ситуации. Поэтому подозрение упало на сеть, но мы решили проверить и другое окружение.

Анализируем окружение и готовим скрипты

Антивирус на тестовой СУБД не стоял, но выяснилось, что Astra Linux установлена в самом защищенном варианте —"Смоленск":

На своем стенде мы развернули еще одну ВМ под СУБД с Astra Linux с уровнем защищенности "Смоленск", чтобы сравнить ее с Astra Linux в базовом режиме работы СЗИ ("Орел"). Провели внутренние нагрузочные тесты на базах 1С и выяснили, что выбор варианта "Смоленск" на производительности СУБД никак не сказывается.

Клиент для тестирования также переразвернул ВМ с СУБД, но уже под Astra Linux в режиме "Орел" и провел тест еще раз — результат не изменился.

Мы вернулись к гипотезе с сетью и разработали план диагностики.

Для СП на Windows Server использовали скрипт для диагностики времени отклика и потери пакетов к серверу СУБД:

Идея и сам скрипт взяты из кейса Виктора Богачева. 

Скрипт каждую секунду выполняет команду ping до хоста localhost с размером пакета 65500 байт и сохраняет лог по пути D:\Bases\Ping_localhost.txt. В самом скрипте перед запуском нужно только поменять localhost на IP сервера СУБД и путь сохранения файла.

Для сервера СУБД на Astra Linux составили вот такие скрипт и план действий:

Также мы хотели проверить с помощью утилиты atop утилизацию диска во время теста:

Неожиданный результат

Договорились с клиентом еще об одном тесте, подключились, вместе настроили сбор данных по диску и сети, запустили процесс.

И получили результат 19.8 минут вместо 241, а при повторном тестировании на MS SQL – 20 минут вместо 80!

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

Кстати, мы собрали данные по сети, и в них время отклика оказалось отличное, а потерь не было. Вот примеры:

СП→ СУБД:

СУБД→СП:

Причины долгой вставки

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

Событие DBPOSTGRS из лога ТЖ 1С – длительность 779 мс:

Запрос по логу СУБД (логируется с помощью настройки log_min_duration_statement) – длительность 779 мс:

План запроса (логируется с помощью плагина auto_explain) – длительность 0.135 мс:

На "Инфостарте" эту проблему уже рассматривали в статье "Сказ о том, как online_analyze INSERT "удлинял", и в нашем случае причина была в том, что в параметр shared_preload_libraries был добавлен online_analyze, по умолчанию включенный для всех типов таблиц: online_analyze.table_type = 'all'. Чтобы его выключить, необходимо явно указать параметр online_analyze.enable = 'off' либо поменять тип анализируемых таблиц только на временные: online_analyze.table_type = 'temporary'.

Но почему analyze вызывается при каждой вставке в таблицу регистра сведений, в котором 8 млн записей? Выглядит избыточно.

Читаем документацию к плагину, чтобы понять, в каких случаях это может происходить:

• lower_limit – минимальное число строк в таблице, при котором будет срабатывать online_analyze, по умолчанию 0;
• threshold – минимальное число изменений строк, после которого может начаться немедленный анализ, по умолчанию 50.
• scale_factor – процент от размера таблицы, при котором начинается немедленный анализ, по умолчанию 0.1.

У нас все значения были дефолтными, и подходил параметр lower_limit: по умолчанию он настроен так, что при любой вставке должен вызываться analyze.

Меняем его на 10 млн, перезапускаем тест со вставкой одной записи – без изменений, analyze все равно вызывается. По значениям параметров threshold + scale_factor analyze должен вызываться, если изменили 5 записей, но ради интереса мы поменяли значение threshold на 10 млн и опять получили вызов analyze при вставке одной записи.

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

А пока мы решили в следующем релизе "Tantor SE 1C" по умолчанию изменить значение параметра online_analyze.table_type с 'all' на 'temporary', чтобы уменьшить вероятность неправильной настройки плагина.

Перепроведение документов в базе УХ

 Описание проблемы

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

MS SQL – 230 минут, Tantor – 510 минут.

При повторном прогоне мы собрали 2 варианта данных технологического журнала:

1. Минилог, в котором фиксируются только событие и его длительность:

2. Событие DBPOSTGRS для анализа длительных запросов.

Анализируем полученный минилог скриптом, взятым, как и идея, из выступления Юрия Федорова на партнерском семинаре (часть материалов доступна по ссылке):

Получаем следующие результаты:

• CALL – 513 минут;
• DBPOSTGRS – 392 минуты.

76% времени занимают запросы к БД. Дальше анализируем их. 

Смотрим самые долгие – везде один и тот же запрос, который выполняется при проведении трех документов: "Требования-накладной", "Корректировки назначения" и "Перемещения товаров".

Находим запрос в коде 1С. В нем нарушен стандарт обращения к виртуальным таблицам: 

"При использовании виртуальных таблиц в запросах следует передавать в параметры таблиц все условия, относящиеся к данной виртуальной таблице. Не рекомендуется обращаться к виртуальным таблицам при помощи условий в секции "ГДЕ".

Проблемная часть запроса выглядела так:

Оптимизация запроса

В MS SQL этот запрос работает быстро, потому что там есть технология Predicate pushdown, которая, по сути, переписывает запрос перед выполнением и добавляет условия внутрь параметров виртуальной таблицы. Переписываем запрос:

После оптимизации время выполнения запроса уменьшилось с 4.45 до 0.046 сек. 

Внесли изменения в конфигурацию, перезапустили операцию перепроведения документов и получили результат – 240 минут. Можно было и дальше искать, в чем разница с MS SQL, но клиента данное время устроило.

Predicate pushdown в Postgres

В Postgres тоже есть технология Predicate pushdown, правда, она не такая продвинутая как в MS SQL. Давайте упростим наш запрос и посмотрим его план выполнения.

Текст запроса:

Текст запроса SQL:

Поле Fld68345RRef – это "Организация", а Fld68346RRef – "Номенклатура", и как видим по тексту запроса, накладываются они в отборах в секции "ГДЕ" на таблицу "T1". Она представляет собой вложенный запрос, в котором идут вычисления при выборке данных из таблицы _AccumRg68344 (таблица "РегистрНакопления.СкладскойУчет").

В плане запроса отбор по номенклатуре и организации будет наложен именно на таблицу _AccumRg68344, а не на результат вложенного запроса:

Отсюда и моментальное время выполнения, т.к. для поиска был выбран индекс _accumrg68344_3 по номенклатуре, из которого, согласно нашим условиям, выбраны 24 записи. Predicate pushdown работает.

Теперь перепишем запрос так, чтобы отборы накладывались через внутреннее соединение, а не через "ГДЕ":

 Текст запроса SQL:

 Отборы по полям "Номенклатура" и "Организация" у нас также накладываются на таблицу Т1 – результат вложенного запроса.

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

Predicate pushdown для такого условия отбора не работает. Но это временно: такая задача у нас есть в бэклоге разработки.

Заключение

После второго кейса мы перезапустили тест по первому кейсу и получили следующие итоговые результаты:

Клиента полученные результаты устроили.