Заметки 1С:Эксперта 30.08.2021

Пропажа индексов дескрипторов в 1С:Документообороте

Пользователи копии продуктивной базы начали жаловаться на полное падение производительности в 1C:Документообороте на PostgresPro Enterprise + Linux.

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

При анализе происходящего из консоли администрирования 1С в момент запуска системы видим, что зависание начинается в момент обращения к СУБД.

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

Мы ставим фильтр — запросы длительностью более 10 секунд. И анализируем полученный результат с помощью регулярных выражений.

1. Находим 3 запроса PostgresPro с максимальной длительностью.
2. Посмотрим текст самого длительного запроса PostgresPro.
3. Анализируем план длительного запроса PostgresPro.

Находим 3 запроса PostgresPro с максимальной длительностью.

Для этого:

«вырезаем» sed-ом часть тех.журнала с начала стоки: дата, время, номер микросекунды, до длительности события;
сортируем результат;
получаем 3 верхние строки;
«подкрашиваем» событие DBPOSTGRS для наглядности

1	sed 's/[0-9][0-9]:[0-9][0-9]\.[0-9]\{6\}\-//g' /C/logs1c/*.log\| sort -rnb \| head -n 3\|grep -P 'DBPOSTGRS' --color

Результат:

В результате видим, что топ-3 занимают запросы примерно одного порядка длительности. Вполне вероятно, что сами запросы в этой группе повторяются.

Дело в том, что в регулярном выражении не сгруппированы запросы по его тексту/контексту.

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

Итак,

Посмотрим текст самого длительного запроса PostgresPro.

Для этого:

grep-ом «найдем» запрос по его длительности и «подкрасим»;
покажем 55 строк после найденой строки.

1	grep -P '326804007' --color -A 55 /C/logs1c/*.log

Контекст:

'Система.ПолучитьФорму : Обработка.ТекущиеДелаДокументооборот.Форма.ФормаТекущиеДела

Обработка.ТекущиеДелаДокументооборот.Форма.ФормаТекущиеДела.Форма : 11 : ЗаполнитьВиджеты(ПрочитатьНастройкиВиджетов);

Обработка.ТекущиеДелаДокументооборот.Форма.ФормаТекущиеДела.Форма : 127 : ТекущиеДелаДокументооборотСервер.ЗаполнитьВиджетыТекущихДел(ЭтаФорма, Виджеты);

ОбщийМодуль.ТекущиеДелаДокументооборотСервер.Модуль : 59 : ЗаполнитьВиджетМоиДокументы(Параметры);

ОбщийМодуль.ТекущиеДелаДокументооборотСервер.Модуль : 1437 : Результаты = Запрос.ВыполнитьПакет();'

Это событие загрузки текущих дел при запуске 1С:Документооборот.

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

SELECT

(COUNT(DISTINCT CASE WHEN T1._Fld2806_TYPE = '\\001'::bytea THEN '\\001'::bytea END) + COUNT(DISTINCT CASE WHEN T1._Fld2806_TYPE = '\\010'::bytea THEN T1._Fld2806_RTRef || T1._Fld2806_RRRef END))

FROM _InfoRg2804 T1

LEFT OUTER JOIN (SELECT

T3._IDRRef AS IDRRef,

T3._Marked AS Marked_

FROM _Reference66 T3

WHERE (EXISTS(SELECT

FROM (SELECT 1 AS SDBL_DUMMY) SDBL_DUAL

INNER JOIN _InfoRg2219 T4

ON ('\\010'::bytea = T4._Fld2220_TYPE AND '\\000\\000\\000B'::bytea = T4._Fld2220_RTRef AND T3._IDRRef = T4._Fld2220_RRRef)

INNER JOIN _InfoRg3486 T5

ON (T4._Fld2221RRef = T5._Fld3487RRef)

WHERE (T5._Fld3488RRef = '\\270\\030\\000PV\\245\\252f\\021\\353\\023f)=\\026{'::bytea) AND (T4._Fld2224 = FALSE)))) T2

ON T1._Fld2806_TYPE = '\\010'::bytea AND T1._Fld2806_RTRef = '\\000\\000\\000B'::bytea AND T1._Fld2806_RRRef = T2.IDRRef

WHERE (((T1._Fld2805RRef = '\\270\\030\\000PV\\245\\252f\\021\\353\\023f)=\\026{'::bytea))) AND ((NOT ((CASE WHEN T1._Fld2806_TYPE = '\\010'::bytea AND T1._Fld2806_RTRef = '\\000\\000\\000B'::bytea THEN T2.Marked_ ELSE CAST(NULL AS BOOLEAN) END) = TRUE)) AND (T1._Fld2805RRef = '\\270\\030\\000PV\\245\\252f\\021\\353\\023f)=\\026{'::bytea))

В тексте видим характерную для РЛС особенность – добавление условия в конце запроса:

В нашем случае – добавление условия по таблице _InfoRg2219.

Используя метод ПолучитьСтруктуруХраненияБазыДанных() выясняем, что _InfoRg2219 – это РегистрСведений.ДескрипторыДляОбъектов.

Таким образом, если кто-то не знал, делаем вывод, что все настройки прав через дескрипторы реализованы на уровне СУБД также как и РЛС – добавлением условия в запрос.

Анализируем план длительного запроса PostgresPro.

План запроса:

Aggregate (cost=11080899.33..11080899.34 rows=1 width=8) (actual time=162996.933..162996.933 rows=1 loops=1)

Output: (count(DISTINCT CASE WHEN (t1._fld2806_type = '\\x01'::bytea) THEN '\\x01'::bytea ELSE NULL::bytea END) + count(DISTINCT CASE WHEN (t1._fld2806_type = '\\x08'::bytea) THEN (t1._fld2806_rtref || t1._fld2806_rrref) ELSE NULL::bytea END))

Buffers: shared hit=6936869

-> Nested Loop Left Join (cost=0.33..11080898.31 rows=204 width=24) (actual time=153.145..162993.540 rows=385 loops=1)

Output: t1._fld2806_type, t1._fld2806_rtref, t1._fld2806_rrref

Inner Unique: true

Join Filter: ((t1._fld2806_type = '\\x08'::bytea) AND (t1._fld2806_rtref = '\\x00000042'::bytea))

Filter: (NOT CASE WHEN ((t1._fld2806_type = '\\x08'::bytea) AND (t1._fld2806_rtref = '\\x00000042'::bytea)) THEN t3._marked ELSE NULL::boolean END)

Buffers: shared hit=6936869

-> Index Only Scan using _inforg2804_1 on public._inforg2804 t1 (cost=0.17..393.88 rows=407 width=24) (actual time=0.030..2.081 rows=385 loops=1)

Output: t1._fld2805rref, t1._fld2806_type, t1._fld2806_rtref, t1._fld2806_rrref, t1._fld2807rref

Index Cond: (t1._fld2805rref = '\\xb818005056a5aa6611eb1366293d167b'::bytea)

Heap Fetches: 385

Buffers: shared hit=216

-> Index Scan using _reference66ng_pkey on public._reference66 t3 (cost=0.17..27224.81 rows=1 width=18) (actual time=423.345..423.345 rows=1 loops=385)

Output: t3._idrref, t3._version, t3._marked, t3._predefinedid, t3._code, t3._description, t3._fld5155rref, t3._fld5156, t3._fld5157rref, t3._fld5158rref, t3._fld5159rref, t3._fld5160rref, t3._fld5161, t3._fld5162, t3._fld5163, t3._fld5164, t3._fld5165, t3._fld5166, t3._fld5167rref, t3._fld5168, t3._fld5169, t3._fld5170rref, t3._fld5171rref, t3._fld5172, t3._fld5173, t3._fld5174, t3._fld5175, t3._fld5176, t3._fld5177rref, t3._fld5178rref, t3._fld5179, t3._fld5180, t3._fld5181rref, t3._fld5182rref, t3._fld5183rref, t3._fld5184rref, t3._fld5185rref, t3._fld5186rref, t3._fld5187, t3._fld5188, t3._fld5189rref, t3._fld5190, t3._fld5191rref, t3._fld5192rref, t3._fld5193rref, t3._fld5194rref, t3._fld5195, t3._fld5196, t3._fld5197rref, t3._fld5198, t3._fld5199, t3._fld5200, t3._fld5201, t3._fld5202, t3._fld5203, t3._fld5204rref, t3._fld5205rref, t3._fld5206, t3._fld5207rref, t3._fld5208, t3._fld5209rref, t3._fld9500rref, t3._fld9515, t3._fld9516rref, t3._fld9550rref, t3._fld9568, t3._fld9569rref, t3._fld9617, t3._fld9618, t3._fld9619, t3._fld9729, t3._fld9731, t3._fld9732, t3._fld9736, t3._fld9737rref, t3._fld9755, t3._fld9767rref, t3._fld9796, t3._fld9797rref, t3._fld9814, t3._fld9815rref, t3._fld9816, t3._fld9817rref, t3._fld9829rref, t3._fld9830rref, t3._fld9831rref, t3._fld9833, t3._fld9837rref, t3._fld9839, t3._fld9845rref, t3._fld9846rref, t3._fld9853rref, t3._fld9854rref, t3._fld9855, t3._fld9857, t3._fld9858, t3._fld9866, t3._fld9882, t3._fld9886rref, t3._fld9887rref, t3._fld9895, t3._fld9906_type, t3._fld9906_rtref, t3._fld9906_rrref, t3._fld9907, t3._fld9908rref, t3._fld9919, t3._fld9930, t3._fld9948rref, t3._fld9953, t3._fld9954, t3._fld9957, t3._fld9958rref, t3._fld9959, t3._fld9960, t3._fld9965, t3._fld9966, t3._fld9967, t3._fld9968, t3._fld9969, t3._fld9970, t3._fld9971, t3._fld9972, t3._fld9973, t3._fld9987rref, t3._fld9988rref, t3._fld9989rref, t3._fld9990, t3._fld9991, t3._fld9992, t3._fld10010, t3._fld10022, t3._fld10023, t3._fld10024, t3._fld10025rref, t3._fld10026, t3._fld10027, t3._fld10041, t3._fld10044, t3._fld10077, t3._fld10078rref, t3._fld10079, t3._fld10138rref, t3._fld10139, t3._fld10140rref, t3._fld10208rref, t3._fld10209, t3._fld10210, t3._fld10285, t3._fld10286, t3._fld10298, t3._fld10306rref, t3._fld10317rref, t3._fld10330, t3._fld10336, t3._fld10337, t3._fld10346

Index Cond: (t1._fld2806_rrref = t3._idrref)

Filter: (SubPlan 1)

Buffers: shared hit=6936653

SubPlan 1

-> Nested Loop (cost=0.17..54445.27 rows=2 width=0) (actual time=423.319..423.319 rows=1 loops=385)

Buffers: shared hit=6935113

-> Seq Scan on public._inforg2219 t4 (cost=0.00..54418.92 rows=11 width=17) (actual time=423.213..423.217 rows=7 loops=385)

Output: t4._fld2220_type, t4._fld2220_rtref, t4._fld2220_rrref, t4._fld2221rref, t4._fld2222rref, t4._fld2223, t4._fld2224, t4._fld2225_type, t4._fld2225_rtref, t4._fld2225_rrref

Filter: ((NOT t4._fld2224) AND ('\\x08'::bytea = t4._fld2220_type) AND ('\\x00000042'::bytea = t4._fld2220_rtref) AND (t3._idrref = t4._fld2220_rrref))

Rows Removed by Filter: 1254364

Buffers: shared hit=6926246

-> Index Only Scan using _inforg3486_2 on public._inforg3486 t5 (cost=0.17..2.39 rows=1 width=17) (actual time=0.009..0.009 rows=0 loops=2825)

Output: t5._fld3488rref, t5._fld3487rref, t5._fld3489_type, t5._fld3489_rtref, t5._fld3489_rrref

Index Cond: ((t5._fld3488rref = '\\xb818005056a5aa6611eb1366293d167b'::bytea) AND (t5._fld3487rref = t4._fld2221rref))

Heap Fetches: 385

Buffers: shared hit=8867

Planning Time: 1.290 ms

Execution Time: 162997.255 ms

Видим, что реальное время выполнения всего запроса 162 секунды.

При этом производилось сканирование уже знакомого нам _InfoRg2219 РегистрСведений.ДескрипторыДляОбъектов.

На сканирование ушло 423 мс., операция повторялась 385 раз. Что в сумме даёт 162 секунды.

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

А что же индексы? Где индексы?

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

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

О том, что к этому привело – читайте в наших следующих статьях…

#1С #1С Эксперт #1С:ДО #postgresql #psql #парсинг #регулярные выражения 1С #Технологический журнал #ТЖ

Еще можно посмотреть

Анализ технологического журнала 1С регулярными выражениями. От простого к сложному.

Что делать, если у пользователя возникают ошибки, «все тормозит» или возникают другие неясные проблемы, а разработчик не знает где искать проблему в коде? С этой статьи мы начинаем нашу рубрику по расследованию проблем производительности и стабильности работы систем на базе 1С:Предприятия. Речь пойдет о реальных примерах анализа технологического журнала 1С экспертами с помощью регулярных выражений. […]

Ошибка 1С:Предприятие «Потеряно соединение»

Потеряно соединение Во время выполнения действия была потеряна связь с сервером. Проверьте сетевой соединение и нажмите "Повторить" для повторной попытки выполнения действия. Если ошибка повторится, возможно, сервер временно недоступен.

Технологический журнал 1С и бесконечный цикл в коде 1С

Несмотря на то, что проблема в статье История одного конфликта блокировок 1С , казалось, была решена, ее повторное появление не заставило себя долго ждать. Пользователь Лапкина вновь приступила к работе и ее сеанс снова парализовал работу пользователей системы с блокируемым справочником. Описание ошибки: Пользователь создает элемент справочника и при записи система 1С:Предприятия «повисает». Сеанс закрывается пользователем, […]

Настройка и сбор логов для анализа проблем производительности систем 1С на Linux

Для осуществления мониторинга за качеством работы систем на базе 1С, а также для анализа проблем с производительностью, необходимо уметь настраивать сбор логов, дампов. Настройка сбора логов 1С под Linux имеет ряд особенностей. О них мы и поговорим в данной статье. Описание приводится для ОС Linux дистрибутивов RHEL/CentOS 7. 1. Как настроить и включить технологический журнал […]

История одного конфликта блокировок 1С

В определенный момент времени, пользователи информационной базы, которые ранее работали без проблем — начали жаловаться на возникновение ошибок при записи элемента справочника. В нашем распоряжении оказались скрины и тексты ошибок, переданные пользователями. Без возможности самостоятельного воспроизведения проблемы в этой или каких-либо других тестовых базах данных. 1. Знакомимся с текстами ошибок. 2. Парсим технологический журнал 1С […]

1C тормозит и возникают ошибки. С чего начать расследование?

Когда мы читаем о том, как настраивать и анализировать технологический журнал 1С на предмет «узких» мест, мы не всегда представляем себе, что это отнюдь не первое, что нужно сделать, когда сталкиваемся с падением производительности и стабильности работы системы. Прежде чем «бросаться» собирать технологический журнал и его парсить, изначально рекомендуется провести первичный сбор информации о проблеме: […]

Что такое PG_TEMP в PostgreSQL для 1С

pg_temp — это пространство СУБД PostgreSQL для временных таблиц, то есть таблиц, существующих в пределах жизни одного соединения (в терминах СУБД) или сеанса (в терминах кластера 1С). Такие таблицы мы можем увидеть в тексте запроса СУБД, если в запросе на языке запросов 1С присутствует конструкция ПОМЕСТИТЬ, которая и помещает выборку во временную таблицу. Таким образом […]