Почему на Postgres запросы выполняются дольше при включении plansql в технологическом журнале?

27.11.24

Рассмотрим логику выполнения запросов платформой 1С к СУБД при включенной настройке ТЖ.

Проверено на платформе 8.3.25. Добавим в файл logcfg.xml тег <plansql/> перед закрывающим тегом </config>:

<?xml version="1.0" encoding="UTF-8"?>
<config xmlns="http://v8.1c.ru/v8/tech-log">
    <log location="ПутьККаталогуСбораЛогов" history="24">
                <event>
                        <eq property="name" value="DBPOSTGRS"/>
                        <eq property="p:processName" value="ИмяБазы"/>
                        <ge property="Durationus" value="100000"/>
                     
                </event>
                        <property name="all"/>
    </log>     
<plansql/>
</config>

Выполним запрос в консоли запросов:

Запрос выполнился за 932 мс.

В логе ТЖ будет следующее:

59:22.810000-874999,DBPOSTGRS,6,process=rphost,p:processName=xxx,OSThread=4968,t:clientID=18,t:applicationName=1CV8C,t:computerName=xxx,t:connectID=1,SessionID=5329,Usr=Администратор,AppID=1CV8C,DBMS=DBPOSTGRS,DataBase='xxx port=5434\xxx',Trans=0,dbpid=1563675,Sql="SELECT
COUNT(DISTINCT T1._IDRRef)
FROM _Reference75722 T1
WHERE ((T1._Fld2488 = CAST(0 AS NUMERIC))) AND ((T1._Fld76608RRef = '\\207\\013 \\004\\017\\353\\301\\200\\021\\355;?\\037\\350\\321\\212'::bytea))",planSQLText="Aggregate  (cost=69909.79..69909.80 rows=1 width=8) (actual time=510.180..510.182 rows=1 loops=1)
  Output: count(DISTINCT _idrref)
  Buffers: shared hit=62322
  ->  Sort  (cost=69909.60..69909.69 rows=97 width=17) (actual time=510.174..510.175 rows=0 loops=1)
        Output: _idrref
        Sort Key: t1._idrref
        Sort Method: quicksort  Memory: 25kB
        Buffers: shared hit=62322
        ->  Seq Scan on public._reference75722 t1  (cost=0.00..69907.26 rows=97 width=17) (actual time=510.155..510.155 rows=0 loops=1)
              Output: _idrref
              Filter: ((t1._fld2488 = '0'::numeric) AND (t1._fld76608rref = '\\x870b20040febc18011ed3b3f1fe8d18a'::bytea))
              Rows Removed by Filter: 631743
              Buffers: shared hit=62319
Query Identifier: 5507907324175298056
Planning:
  Buffers: shared hit=207
Planning Time: 0.640 ms
Execution Time: 510.368 ms
",RowsAffected=1,Result=PGRES_TUPLES_OK,Context='Форма.Вызов : ВнешняяОбработка.КонсольЗапросовСОбработкойРезультата.Форма.Форма.Модуль.ВыполнитьЗапросСервер
ВнешняяОбработка.КонсольЗапросовСОбработкойРезультата.Форма.Форма.Форма : 1835 : Результат = ОбъектОбработки.ВыполнитьЗапрос(Текст, МассивПараметров, ДокументРезультат, ПараметрыВыводаЗапроса, ОтчетПоВыполнениюЗапроса, МеткаЗапроса);
    ВнешняяОбработка.КонсольЗапросовСОбработкойРезультата.МодульОбъекта : 1312 : МассивЗапросов = Запрос.ВыполнитьПакет();'

Событие DBPOSTGRS выполнялось 875 мс, из которых сам запрос выполнялся 510 мс (исходя из данных плана запроса). Куда делись еще 365 мс?

Смотрим лог СУБД:

2024-10-20 20:59:22.447 MSK [1563675:20/59] [xxx] 10.177.143.210(59180) [unknown] LOG:  duration: 510.185 ms  plan:
    Query Text: explain (analyse, verbose, buffers) SELECT
    COUNT(DISTINCT T1._IDRRef)
    FROM _Reference75722 T1
    WHERE ((T1._Fld2488 = CAST(0 AS NUMERIC))) AND ((T1._Fld76608RRef = '\\207\\013 \\004\\017\\353\\301\\200\\021\\355;?\\037\\350\\321\\212'::bytea))
    Aggregate  (cost=69909.79..69909.80 rows=1 width=8) (actual time=510.180..510.182 rows=1 loops=1)
      Output: count(DISTINCT _idrref)
      Buffers: shared hit=62322
      ->  Sort  (cost=69909.60..69909.69 rows=97 width=17) (actual time=510.174..510.175 rows=0 loops=1)
            Output: _idrref
            Sort Key: t1._idrref
            Sort Method: quicksort  Memory: 25kB
            Buffers: shared hit=62322
            ->  Seq Scan on public._reference75722 t1  (cost=0.00..69907.26 rows=97 width=17) (actual time=510.155..510.155 rows=0 loops=1)
                  Output: _idrref
                  Filter: ((t1._fld2488 = '0'::numeric) AND (t1._fld76608rref = '\\x870b20040febc18011ed3b3f1fe8d18a'::bytea))
                  Rows Removed by Filter: 631743
                  Buffers: shared hit=62319
    Query Identifier: 5507907324175298056
2024-10-20 20:59:22.809 MSK [1563675:20/60] [xxx] 10.177.143.210(59180) [unknown] LOG:  duration: 360.635 ms  plan:
    Query Text: SELECT
    COUNT(DISTINCT T1._IDRRef)
    FROM _Reference75722 T1
    WHERE ((T1._Fld2488 = CAST(0 AS NUMERIC))) AND ((T1._Fld76608RRef = '\\207\\013 \\004\\017\\353\\301\\200\\021\\355;?\\037\\350\\321\\212'::bytea))
    Aggregate  (cost=69909.79..69909.80 rows=1 width=8) (actual time=360.623..360.625 rows=1 loops=1)
      Output: count(DISTINCT _idrref)
      Buffers: shared hit=62319
      ->  Sort  (cost=69909.60..69909.69 rows=97 width=17) (actual time=360.617..360.618 rows=0 loops=1)
            Output: _idrref
            Sort Key: t1._idrref
            Sort Method: quicksort  Memory: 25kB
            Buffers: shared hit=62319
            ->  Seq Scan on public._reference75722 t1  (cost=0.00..69907.26 rows=97 width=17) (actual time=360.610..360.610 rows=0 loops=1)
                  Output: _idrref
                  Filter: ((t1._fld2488 = '0'::numeric) AND (t1._fld76608rref = '\\x870b20040febc18011ed3b3f1fe8d18a'::bytea))
                  Rows Removed by Filter: 631743
                  Buffers: shared hit=62319
    Query Identifier: 5507907324175298056

В логе СУБД мы видим, что данный запрос выполнялся дважды:

Первый раз его выполнила платформа для того, чтобы собрать план для логов ТЖ - он выполнялся 510 мс и его отличает, что Query text начинается с "explain (analyse, verbose, buffers)"
Второй раз он выполнился за 360 мс - это уже выполнение платформой для того, чтобы выдать мне результат в консоли запросов.

Вот и мы нашли, куда были потрачены 365 мс.

А что с запросами на изменение данных?

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

Выполним код:

НовыйЭлемент = Справочники.Валюты.СоздатьЭлемент();
НовыйЭлемент.Наименование = "BRICS";
НовыйЭлемент.Записать();

В логе ТЖ будет следующее:

41:56.920000-1996,DBPOSTGRS,6,process=rphost,p:processName=erp_v_15_6,OSThread=29051,t:clientID=76,t:applicationName=1CV8C,t:computerName=test-1c-win-wks,t:connectID=45,SessionID=1,Usr=Администратор,AppID=1CV8C,DBMS=DBPOSTGRS,DataBase=database-test-1c-db-px-002.tantorlabs.ru\erp_v_full,Trans=1,dbpid=63290,Func=quickInsert,tableName=_Reference66,Sql='INSERT INTO _Reference66 (_IDRRef,_Version,_Marked,_PredefinedID,_Code,_Description,_Fld52488,_Fld52489,_Fld52490,_Fld52491RRef,_Fld52492,_Fld52493,_Fld52494RRef,_Fld2488) VALUES($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)',Prm="
p_1: '\\235O\\216\\350\\335+S\\000\\021\\357\\222\\015\\274\\250\\305\\200'::bytea
p_2: NULL
p_3: FALSE
p_4: '\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000'::bytea
p_5: ''::mvarchar
p_6: 'BRICS'::mvarchar
p_7: FALSE
p_8: ''::mvarchar
p_9: 0
p_10: '\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000'::bytea
p_11: ''::mvarchar
p_12: ''::mvarchar
p_13: '\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000\\000'::bytea
p_14: 0",RowsAffected=1,Context='Форма.Вызов : ВнешняяОбработка.КонсольЗапросовСОбработкойРезультата.Форма.Форма.Модуль.ВыполнитьАлгоритмНаСервере
ВнешняяОбработка.КонсольЗапросовСОбработкойРезультата.Форма.Форма.Форма : 2698 : ОбъектОбработки.ИнициализироватьАлгоритм(ИДНастройки, РезультатТаблица, РезультатДерево);
    ВнешняяОбработка.КонсольЗапросовСОбработкойРезультата.МодульОбъекта : 67 : ВыполнитьАлгоритм(Запрос, РезультатТаблица, РезультатДерево);
        ВнешняяОбработка.КонсольЗапросовСОбработкойРезультата.МодульОбъекта : 87 : Выполнить(мТекстПрограммногоКодаДляВыполнения);
             : 3 : НовыйЭлемент.Записать();'

Мы не видим в логе плана запроса.

Смотрим лог СУБД:

2024-10-24 16:42:42.750 MSK [63290:35/24657] [xxx] 10.177.143.210(51606) [unknown] LOG:  duration: 0.070 ms  plan:
    Query Text: INSERT INTO _Reference66 (_IDRRef,_Version,_Marked,_PredefinedID,_Code,_Description,_Fld52488,_Fld52489,_Fld52490,_Fld52491RRef,_Fld52492,_Fld52493,_Fld52494RRef,_Fld2488) VALUES($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14)
    Insert on public._reference66  (cost=0.00..0.01 rows=0 width=0) (actual time=0.069..0.070 rows=0 loops=1)
      Buffers: shared hit=6
      ->  Result  (cost=0.00..0.01 rows=1 width=324) (actual time=0.001..0.001 rows=1 loops=1)
            Output: '\\x9d4f8ee8dd2b530011ef920dd7fa3d64'::bytea, 0, false, '\\x00000000000000000000000000000000'::bytea, ''::mvarchar(3), 'BRICS'::mvarchar(10), false, ''::mvarchar(50), 0.00::numeric(10,2), '\\x00000000000000000000000000000000'::bytea, ''::mvarchar(200), ''::mvarchar(100), '\\x00000000000000000000000000000000'::bytea, '0'::numeric(7,0)

Видим только один план запроса, а не 2, как было в случае с запросом на выборку данных. И данный план запроса не содержит конструкции "explain (analyse, verbose, buffers)", исходя из чего можно сделать вывод - при выполнении запросов на модификацию данных (INSERT/UPDATE/DELETE) платформа 1С не собирает план запроса и поэтому выполняет запрос только один раз.

Итоги:

При включенном сборе планов запросов в настройках технологического журнала каждый запрос на выборку данных (SELECT) к базе данных на postgres будет выполняться два раза, что отрицательно сказывается на производительности 1С. Используйте данную возможность только в тестовой зоне для целей диагностики и отладки!

Postgres plansql ТЖ технологические журнал нюансы 1С

+2 –

См. также

Infostart Toolkit: Инструменты разработчика 1С 8.3 на управляемых формах

Инструментарий разработчика Роли и права Запросы СКД Программист Платформа 1С v8.3 Управляемые формы Запросы Система компоновки данных Конфигурации 1cv8 Платные (руб)

Набор инструментов программиста и специалиста 1С для всех конфигураций на управляемых формах. В состав входят инструменты: Консоль запросов, Консоль СКД, Консоль кода, Редактор объекта, Анализ прав доступа, Метаданные, Поиск ссылок, Сравнение объектов, Все функции, Подписки на события и др. Редактор запросов и кода с раскраской и контекстной подсказкой. Доработанный конструктор запросов тонкого клиента. Продукт хорошо оптимизирован и обладает самым широким функционалом среди всех инструментов, представленных на рынке.

10000 руб.

02.09.2020 160815 890 399

871

Примеры настроек технологического журнала

Технологический журнал Программист Платформа 1С v8.3 Бесплатно (free)

Шпаргалка по настройке технологического журнала.

27.04.2024 12053 kuzyara 5

116

Анализ SQL сервера

HighLoad оптимизация Инструменты администратора БД Системный администратор Программист Платформа 1С v8.3 Конфигурации 1cv8 Абонемент ($m)

Обработка для простого и удобного анализа настроек, нагрузки и проблем с SQL сервером с упором на использование оного для 1С. Анализ текущих запросов на sql, ожиданий, конвертация запроса в 1С и рекомендации, где может тормозить.

2 стартмани

15.02.2024 12545 245 ZAOSTG 82

115

Опыт оптимизации 1С на PostgreSQL

HighLoad оптимизация Системный администратор Программист Бесплатно (free)

При переводе типовой конфигурации 1C ERP/УТ/КА на PostgreSQL придется вложить ресурсы в доработку и оптимизацию запросов. Расскажем, на что обратить внимание при потерях производительности и какие инструменты/подходы помогут расследовать проблемы после перехода.

20.11.2023 13720 ivanov660 6

Начните уже использовать хранилище запросов

HighLoad оптимизация Запросы

Очень немногие из тех, кто занимается поддержкой MS SQL, работают с хранилищем запросов. А ведь хранилище запросов – это очень удобный, мощный и, главное, бесплатный инструмент, позволяющий быстро найти и локализовать проблему производительности и потребления ресурсов запросами. В статье расскажем о том, как использовать хранилище запросов в MS SQL и какие плюсы и минусы у него есть.

11.10.2023 19452 skovpin_sa 15

105

«Монитор» – простой анализ производительности

Администрирование СУБД Технологический журнал Системный администратор Бесплатно (free)

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

21.09.2023 7340 Andreynikus 14

MS SQL Server: изучаем планы запросов

Запросы HighLoad оптимизация Программист Запросы Бесплатно (free)

Многие знают, что для ускорения работы запроса нужно «изучить план». При этом сам план обычно обескураживает: куча разноцветных иконок и стрелочек; ничего не понятно, но очень интересно! Аналитик производительности Александр Денисов на конференции Infostart Event 2021 Moscow Premiere рассказал, как выполняется план запроса и что нужно сделать, чтобы с его помощью находить проблемы производительности.

20.06.2023 28630 Филин 37

118

Все консоли запросов для 1С

Запросы Инструментарий разработчика Программист Бесплатно (free)

Список всех популярных обработок.

17.03.2023 61301 kuzyara 89

191

Комментарии

Подписаться на ответы Инфостарт бот

Свернуть все

1. ivanov660 4581 27.11.24 20:39 Сейчас в теме

Вроде это общеизвестная информация, то же самое будет и на MS SQL? Разве нет?

2. Tantor 90 27.11.24 22:20 Сейчас в теме

(1) MSSQL нет под рукой проверить. Но насколько помню, там один раз выполняется.

3. paulwist 28.11.24 08:49 Сейчас в теме

Вот и мы нашли, куда были потрачены 365 мс.

Ну, как бы в документации об этом "русским" по белому написано:

14.1.2. EXPLAIN ANALYZE

С этим параметром EXPLAIN на самом деле выполняет запрос, а затем выводит фактическое число строк и время выполнения, накопленное в каждом узле плана, вместе с теми же оценками, что выдаёт обычная команда EXPLAIN.

И данный план запроса не содержит конструкции "explain (analyse, verbose, buffers)", исходя из чего можно сделать вывод - при выполнении запросов на модификацию данных (INSERT/UPDATE/DELETE) платформа 1С не собирает план запроса и поэтому выполняет запрос только один раз.

Ммм, данный вывод несколько противоречит доке вендора:

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

PS Для "старых склеротиков" статья годная :)

4. Tantor 90 29.11.24 11:18 Сейчас в теме

(3)

данный вывод несколько противоречит доке вендора

В чем данный вывод противоречит документации вендора?

5. paulwist 29.11.24 12:50 Сейчас в теме

(4)

В чем данный вывод противоречит документации вендора?

А можете привести лог ТЖ при insert во временную табличку??

PS имею в виду использование online_analyze и его настройки.
online_analyze.enable" = ...; online_analyze.verbose" = ...; online_analyze.table_type" = ...;

6. Tantor 90 29.11.24 17:51 Сейчас в теме

(5) Да, нужно такой пример добавить в статью.

7. TMV 14 29.11.24 21:20 Сейчас в теме

Если выключить отладку, производительность вырастет

Оставьте свое сообщение

E-mail:

Автор:

(Tantor)

Рейтинг: 90

Для получения уведомлений о новых публикациях автора подключите телеграм бот: Инфостарт бот

Публикация:

№ 2230304

Создание 27.11.24 17:00

Обновление 27.11.24 17:00

Статистика:

Просмотры 256

Загрузки 0

Рейтинг 2

Комментарии 7

Характеристики:

Код открыт Да

Рубрики HighLoad оптимизация Запросы Технологический журнал

Кому Программист

Тип файла Нет файла

Платформа Платформа 1С v8.3

Конфигурация Не имеет значения

Операционная система Не имеет значения

Страна Не имеет значения

Отрасль Не имеет значения

Налоги Не имеет значения

Вид учета Не имеет значения

Доступ к файлу Бесплатно (free)