Экспертный кейс. Расследование фатального замедления времени расчета себестоимости в 1С:ERP 2

Инфраструктура исследуемой системы

Технологическая платформа 1С:Предприятие 8, версия 8.3.19.1264
Конфигурация: 1С:ERP Управление предприятием 2, версия 2.5.6.234
СУБД: PostgresPro Enterprise 13
Операционная система: Astra Linux Орел 2.12

Проблема

При выполнении нагрузочного тестирования информационной системы на базе 1С:ERP для одного из клиентов с целью оценки возможности миграции системы на PostgreSQL и Astra Linux мы столкнулись с неприемлемым увеличением времени выполнения расчета себестоимости.

Строго говоря, сценарий тестирования закрытия месяца не был выполнен вообще – он не укладывался в таймаут выполнения теста, 24 часа. По прошествии 18 часов всё ещё шло выполнение операции «Распределение затрат и расчет себестоимости». Более 16 часов выполнялся подэтап “Расчет партий и себестоимости. Этап. Расчет себестоимости: РассчитатьСтоимость”. Всё это время выполнялся запрос, который в текущей инфраструктуре клиента (СУБД MS SQL Server) выполняется чуть более 3 минут на аналогичных данных.

Задача

Выявить причины неприемлемого поведения СУБД при расчете себестоимости в новой инфраструктуре заказчика (Linux/PostgreSQL) и привести показатели к сопоставимым показателями текущей инфраструктуры (MS Windows/MS SQL Server).

Решение

Для удобства повествования разобьем описание процесса расследования на этапы.

Этап 1. Поиск причины длительного выполнения расчета себестоимости

На этом этапе необходимо найти зацепки, которые позволят определиться, куда двигаться в расследовании дальше. Для начала анализируем технологический журнал 1С (ТЖ). Номер сеанса задания расчета интересует в первую очередь – берем его, например, в журнале регистрации 1С. Там же видим, что последнее событие этого сеанса зарегистрировано за ~18 часов до окончания теста. В ТЖ по сеансу аналогичная картина – никаких записей в течение 18 часов до момента отмены. И здесь находим интересное:

Один запрос выполнялся в течение ~17 часов (58 479 секунд в листинге выше).

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

Этап 2. Получение плана запроса

Следующим шагом нужно определиться, что не так с запросом, выполняющимся почти 17 часов. Оптимизировать запрос наугад – соблазнительный, но неверный путь. При этом можно потратить много времени и сил, а получить устойчивый результат – увы, вряд ли. Нужен анализ плана запроса.

Если этого не было сделано ранее, включаем логирование планов запросов в postgresql.conf:
shared_preload_libraries = 'auto_explain'
auto_explain.log_analyze = true
auto_explain.log_min_duration = '0s'

Обратите внимание, что применение параметра shared_preload_libraries требует перезапуска сервера. Можно использовать альтернативу: session preload libraries

Теперь требуемый план запроса найдем в логе СУБД и приступаем к его анализу.

Этап 3. Анализ полученного плана запроса

Для анализа плана запроса воспользуемся бесплатным онлайн-инструментом https://explain.depesz.com/, который представляет его в удобном виде. В качестве альтернативы можно воспользоваться https://explain.tensor.ru/ – тоже бесплатный и полезный онлайн-инструмент.

Обработав этим сервисом полученный на предыдущем этапе план запроса, в первую очередь ищем блоки, которые выполняются медленнее всего, либо которые повторяются чаще всего – т.к. именно это в результате приводит к фатальному замедлению. Такие блоки специально выделяются анализатором отдельным цветом.

Видим, что наша беда – запрос с объединением результатов 9 подзапросов, общее время выполнения данного запроса составляет 28 034 секунд (см. строки 1-5).

Из 28 034 секунд общего выполнения запроса 27 805 секунд заняло выполнение первого подзапроса объединения (строка 6).

Рассмотрим план выполнения этого подзапроса более внимательно:

При детальном анализе видно (внимание на скриншот с подписями – можно открыть в отдельном окне): 3 проблемных левых соединения (строки 15-17) с одной и той же временной таблицей tt786. Строки 9-11 показывают, что три этих левых соединения выполняются при помощи nested loops (вложенными циклами). Первое левое соединение – строка 11, Второе – строка 10, Третье – строка 9. Время выполнения каждого такого объединения занимает по 9 265 секунд.

При этом для каждого соединения было обработано 19 838 704 480 строк, но ни одна строка не подошла под условия соединения. Видно, что временная таблица tt786 имеет индекс, но в него попало только одно условие:

Index Cond: (_q_001_f_003rref = t2._q_001_f_036rref)

Остальные условия по таблице tt786 выполнялись со сканированием:

Filter: (('\\x08'::bytea = _q_001_f_007_type) AND ('\\x000000f8'::bytea = _q_001_f_007_rtref) AND ('\\x08'::bytea = _q_001_f_010_type) AND (t2._q_001_f_037rref = _q_001_f_004rref) AND (t2._q_001_f_038rref = _q_001_f_005rref) AND (t2._q_001_f_006rref = _q_001_f_002rref) AND (t2._q_001_f_056_type = _q_001_f_006_type) AND (t2._q_001_f_056_rtref = _q_001_f_006_rtref) AND (t2._q_001_f_056_rrref = _q_001_f_006_rrref) AND (t2._q_001_f_057rref = _q_001_f_007_rrref) AND (t2._q_001_f_058_type = _q_001_f_009_type) AND (t2._q_001_f_058_rtref = _q_001_f_009_rtref) AND (t2._q_001_f_058_rrref = _q_001_f_009_rrref) AND (t2._q_001_f_059rref = _q_001_f_010_rrref))

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

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

	|		ЛЕВОЕ СОЕДИНЕНИЕ
	|			ВтУзлыКорректировки КАК УзлыКорректировкиПриемник
	|		ПО
	|			УчетСебестоимости.КорАналитикаУчетаНоменклатуры  = УзлыКорректировкиПриемник.АналитикаУчетаНоменклатуры
	|			И УчетСебестоимости.КорРазделУчета 				 = УзлыКорректировкиПриемник.РазделУчета
	|			И УчетСебестоимости.КорВидЗапасов 				 = УзлыКорректировкиПриемник.ВидЗапасов
	|			И УчетСебестоимости.Организация 				 = УзлыКорректировкиПриемник.Организация
	|			И УчетСебестоимости.КорОрганизация 				 = ЗНАЧЕНИЕ(Справочник.Организации.ПустаяСсылка)
	|			И УчетСебестоимости.КорПартия              	     = УзлыКорректировкиПриемник.Партия
	|			И УчетСебестоимости.КорАналитикаУчетаПартий      = УзлыКорректировкиПриемник.АналитикаУчетаПартий
	|			И (УчетСебестоимости.КорАналитикаФинансовогоУчета = УзлыКорректировкиПриемник.АналитикаФинансовогоУчета
	|				ИЛИ НЕ &ПартионныйУчетВерсии22)
	|			И (УчетСебестоимости.КорВидДеятельностиНДС        = УзлыКорректировкиПриемник.ВидДеятельностиНДС
	|				ИЛИ НЕ &ПартионныйУчетВерсии22)
	|
	|		ЛЕВОЕ СОЕДИНЕНИЕ
	|			ВтУзлыКорректировки КАК УзлыКорректировкиПриемникПередачи	
	|		ПО
	|			УчетСебестоимости.КорАналитикаУчетаНоменклатуры  = УзлыКорректировкиПриемникПередачи.АналитикаУчетаНоменклатуры
	|			И УчетСебестоимости.КорРазделУчета 				 = УзлыКорректировкиПриемникПередачи.РазделУчета
	|			И УчетСебестоимости.КорВидЗапасов 				 = УзлыКорректировкиПриемникПередачи.ВидЗапасов
	|			И УчетСебестоимости.КорОрганизация 				 = УзлыКорректировкиПриемникПередачи.Организация
	|			И УчетСебестоимости.КорОрганизация 				 <> ЗНАЧЕНИЕ(Справочник.Организации.ПустаяСсылка)
	|			И УчетСебестоимости.РазделУчета 				 <> ЗНАЧЕНИЕ(Перечисление.РазделыУчетаСебестоимостиТоваров.ТоварыПринятыеНаКомиссию)
	|			И УчетСебестоимости.КорПартия              	     = УзлыКорректировкиПриемникПередачи.Партия
	|			И УчетСебестоимости.КорАналитикаУчетаПартий      = УзлыКорректировкиПриемникПередачи.АналитикаУчетаПартий
	|			И (УчетСебестоимости.КорАналитикаФинансовогоУчета = УзлыКорректировкиПриемникПередачи.АналитикаФинансовогоУчета
	|				ИЛИ НЕ &ПартионныйУчетВерсии22)
	|			И (УчетСебестоимости.КорВидДеятельностиНДС        = УзлыКорректировкиПриемникПередачи.ВидДеятельностиНДС
	|				ИЛИ НЕ &ПартионныйУчетВерсии22)
	|
	|		ЛЕВОЕ СОЕДИНЕНИЕ
	|			ВтУзлыКорректировки КАК УзлыКорректировкиПриемникРеглУчет
	|		ПО
	|			УчетСебестоимости.КорАналитикаУчетаНоменклатуры  = УзлыКорректировкиПриемникРеглУчет.АналитикаУчетаНоменклатуры
	|			И УчетСебестоимости.РазделУчета 				 = УзлыКорректировкиПриемникРеглУчет.РазделУчета
	|			И УчетСебестоимости.КорВидЗапасов 				 = УзлыКорректировкиПриемникРеглУчет.ВидЗапасов
	|			И УчетСебестоимости.КорОрганизация				 = УзлыКорректировкиПриемникРеглУчет.Организация
	|			И УчетСебестоимости.КорПартия 					 = УзлыКорректировкиПриемникРеглУчет.Партия
	|			И УчетСебестоимости.КорАналитикаУчетаПартий 	 = УзлыКорректировкиПриемникРеглУчет.АналитикаУчетаПартий
	|			И (УчетСебестоимости.КорАналитикаФинансовогоУчета = УзлыКорректировкиПриемникРеглУчет.АналитикаФинансовогоУчета
	|				ИЛИ НЕ &ПартионныйУчетВерсии22)
	|			И (УчетСебестоимости.КорВидДеятельностиНДС 		 = УзлыКорректировкиПриемникРеглУчет.ВидДеятельностиНДС
	|				ИЛИ НЕ &ПартионныйУчетВерсии22)

Этап 4. Решение выявленной проблемы

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

Для начала сопоставим имена проблемной временной таблицы из плана запроса “tt786” и из текста запроса 1С – это “ВтУзлыКорректировки”.

Поля соединения временной таблицы “ВтУзлыКорректировки” во всех трех случаях идентичны, но проиндексировано только одно: “АналитикаУчетаНоменклатуры”:


	ПараметрыНумерации = РасчетСебестоимостиПрикладныеАлгоритмы.СформироватьПараметрыНумерацииСтрокВременнойТаблицы(
		"АналитикаУчетаНоменклатуры", // разделитель
		, // без группировки
		"АналитикаУчетаНоменклатуры,
			//++ НЕ УТ
			|РазделУчета,
			//-- НЕ УТ
			|ВидЗапасов, Организация, Партия, АналитикаУчетаПартий, АналитикаФинансовогоУчета, ВидДеятельностиНДС", // порядок
		"НомерУзла", // поле номера
    	"АналитикаУчетаНоменклатуры"); // индекс

Очевидно нарушен стандарт разработки, присутствующий на ИТС в разделе “Несоответствие индексов и условий запроса”. Подробнее можно прочитать: https://its.1c.ru/db/v8std#content:652:hdoc

Чтобы избавиться от сканирования по остальным полям при выполнении соединения, необходимо добавить эти поля в индекс:


	ПараметрыНумерации = РасчетСебестоимостиПрикладныеАлгоритмы.СформироватьПараметрыНумерацииСтрокВременнойТаблицы(
		"АналитикаУчетаНоменклатуры", // разделитель
		, // без группировки
		"АналитикаУчетаНоменклатуры,
			//++ НЕ УТ
			|РазделУчета,
			//-- НЕ УТ
			|ВидЗапасов, Организация, Партия, АналитикаУчетаПартий, АналитикаФинансовогоУчета, ВидДеятельностиНДС", // порядок
		"НомерУзла", // поле номера
    	"АналитикаУчетаНоменклатуры, РазделУчета, ВидЗапасов, Организация, Партия, АналитикаУчетаПартий, АналитикаФинансовогоУчета, ВидДеятельностиНДС"); // индекс

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

SET enable_nestloop = off;

Правда, проверка в консоли осложняется необходимостью добавления запросов вставки данных во временные таблицы. Но мы проверили – hash join выполнился за 50 секунд :)

После добавления нужных полей в индекс, запускаем расчет себестоимости заново, теперь наш запрос выполняется за 4 282 секунды. Уже лучше, но далеко ещё не хорошо…

Этап 5. И снова анализ и исправление

Получив первую оптимизацию, расслабляться рано. На этом этапе нужно дополнительно проанализировать актуальный план запроса (который обновился после нашей оптимизации) и устранить очередные узкие места, если они остались. В принципе, такой повтор “от итерации к итерации” может повторяться несколько раз – просто в этой конкретной ситуации нам хватило двух :)

Открываем свежий план запроса и видим, что теперь проблемным стал 6-й подзапрос (строка 54) из объединения. В нем используется соединение вложенными циклами, хотя до этого использовался hash join и весь подзапрос выполнялся за 38 сек.

Анализируем план аналогично описанному выше процессу:

внешний цикл состоит из 3 316 651 итераций (строка 58)
вложенный цикл представляет из себя поиск по индексу и частичное сканирование временной таблицы tt904 (строка 63)
на каждой итерации было отброшено в среднем 244 строки, за все итерации 809 262 844 строк не подошло под условия соединения (строка 63)

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

Сопоставляем имена временной таблицы из плана запроса и текста запроса: “tt904 ” -> “ВтУзлыКорректировкиПостатейные”. Переходим к тексту запроса на языке 1С, проблемное соединение имеет вид:

Временная таблица “ВтУзлыКорректировкиПостатейные” имеет индекс по следующим полям:

|ИНДЕКСИРОВАТЬ ПО
| СтатьяРасходов, АналитикаФинансовогоУчета

Добавляем в индекс необходимые поля:

После этого запускаем расчет себестоимости заново.

Этап 6. Финал

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

План выполнения исправленного запроса имеет вид:

УРА! Запрос стал выполняться всего 225 секунд, из которых 92 секунды выполняется 6-й подзапрос: соединение вложенными циклами с временной таблицей “ВтУзлыКорректировкиПостатейные” так и осталось самой долгой частью.

Но теперь, как видно (строка 63 на скриншоте ниже), условие соединения полностью попадает в индекс лишние строки не обрабатываются и не отбрасываются:

Заметим, что в изначальной версии запроса, который выполнялся 28 тысяч секунд, проблемное соединение в 6-м подзапросе выполнялось при помощи хеширования, время выполнения составило всего 12 секунд.

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

Итак, время выполнения запроса на Postgres стало соизмеримым с временем выполнения на MS SQL Server, проблема решена, цель достигнута.

Строго говоря, после исправления этого запроса мы столкнулись с его братом-близнецом в следующем этапе: “Расчет партий и себестоимости. Этап. Расчет себестоимости: РассчитатьСтоимостьРегл”, для которого применили аналогичные изменения. Но это уже не совсем интересно – повторяться не будем.

Автор: Алексей Белый
Эксперт по технологическим вопросам
ИТ-Экспертиза

Впервые опубликовано на портале Инфостарт: https://infostart.ru/1c/articles/1628171/

Вернуться назад