Tantor, Postgres, 1С

Почему при включении plansql в ТЖ запросы в PostgreSQL выполняются дольше?

Материал эксперта «Тантор Лабс» из базы знаний ИНФОСТАРТ
Проверено на платформе 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С не собирает план запроса и поэтому выполняет запрос только один раз.
А что со вставкой во временную таблицу?

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

Выполним следующий запрос:
ВЫБРАТЬ
    КОЛИЧЕСТВО(РАЗЛИЧНЫЕ ОбъектыРасчетов.Ссылка) КАК Ссылка
ПОМЕСТИТЬ ВТ
ИЗ
    Справочник.ОбъектыРасчетов КАК ОбъектыРасчетов
ГДЕ
    ОбъектыРасчетов.Партнер = &Партнер
;
 
////////////////////////////////////////////////////////////////////////////////
ВЫБРАТЬ
    ВТ.Ссылка КАК Ссылка
ИЗ
    ВТ КАК ВТ
В логе ТЖ будет следующее:
42:13.439000-729996,DBPOSTGRS,6,process=rphost,p:processName=xxx,OSThread=20315,t:clientID=2258,t:applicationName=1CV8C,t:computerName=xxx,t:connectID=1437,SessionID=1,Usr=Администратор,AppID=1CV8C,DBMS=DBPOSTGRS,DataBase=xxx,Trans=0,dbpid=1164401,Sql="INSERT INTO pg_temp.tt1 (_Q_000_F_000) SELECT
COUNT(DISTINCT T1._IDRRef)
FROM _Reference75722 T1
WHERE ((T1._Fld2488 = CAST(0 AS NUMERIC))) AND ((T1._Fld76608RRef = '\\202\\223\\014\\304z5,\\031\\021\\351|\\200\\270\\2515\\236'::bytea))",planSQLText='Insert on pg_temp.tt1  (cost=69822.69..69822.70 rows=1 width=16) (actual time=726.609..726.614 rows=1 loops=1)
  Output: 0
  Buffers: shared hit=3 read=62240, local dirtied=1 written=1
  I/O Timings: shared read=439.492, local write=0.068
  ->  Subquery Scan on "*SELECT*"  (cost=69822.69..69822.70 rows=1 width=16) (actual time=725.904..725.907 rows=1 loops=1)
        Output: "*SELECT*".count
        Buffers: shared hit=3 read=62240
        I/O Timings: shared read=439.492
        ->  Aggregate  (cost=69822.69..69822.70 rows=1 width=8) (actual time=725.901..725.902 rows=1 loops=1)
              Output: count(DISTINCT t1._idrref)
              Buffers: shared hit=3 read=62240
              I/O Timings: shared read=439.492
              ->  Sort  (cost=69822.51..69822.60 rows=92 width=17) (actual time=725.894..725.895 rows=0 loops=1)
                    Output: t1._idrref
                    Sort Key: t1._idrref
                    Sort Method: quicksort  Memory: 25kB
                    Buffers: shared hit=3 read=62240
                    I/O Timings: shared read=439.492
                    ->  Seq Scan on public._reference75722 t1  (cost=0.00..69820.30 rows=92 width=17) (actual time=725.879..725.880 rows=0 loops=1)
                          Output: t1._idrref
                          Filter: ((t1._fld2488 = ''0''::numeric) AND (t1._fld76608rref = ''\\x82930cc47a352c1911e97c80b8a9359e''::bytea))
                          Rows Removed by Filter: 631743
                          Buffers: shared read=62240
                          I/O Timings: shared read=439.492
Query Identifier: 3165922059677811385
Planning:
  Buffers: shared hit=364 read=29
  I/O Timings: shared read=0.332
Planning Time: 1.064 ms
Execution Time: 726.939 ms
',RowsAffected=1,Result=PGRES_COMMAND_OK,Context='Форма.Вызов : ВнешняяОбработка.КонсольЗапросовСОбработкойРезультата.Форма.Форма.Модуль.ВыполнитьЗапросСервер
ВнешняяОбработка.КонсольЗапросовСОбработкойРезультата.Форма.Форма.Форма : 1835 : Результат = ОбъектОбработки.ВыполнитьЗапрос(Текст, МассивПараметров, ДокументРезультат, ПараметрыВыводаЗапроса, ОтчетПоВыполнениюЗапроса, МеткаЗапроса);
    ВнешняяОбработка.КонсольЗапросовСОбработкойРезультата.МодульОбъекта : 1312 : МассивЗапросов = Запрос.ВыполнитьПакет();
А вот лог СУБД:
2024-11-29 17:42:13.438 MSK [1164401:22/17849] [xxx] 10.200.41.85(34754) [unknown] LOG:  duration: 726.616 ms  plan:
    Query Text: explain (analyse, verbose, buffers) INSERT INTO pg_temp.tt1 (_Q_000_F_000) SELECT
    COUNT(DISTINCT T1._IDRRef)
    FROM _Reference75722 T1
    WHERE ((T1._Fld2488 = CAST(0 AS NUMERIC))) AND ((T1._Fld76608RRef = '\\202\\223\\014\\304z5,\\031\\021\\351|\\200\\270\\2515\\236'::bytea)) returning 0
    Insert on pg_temp.tt1  (cost=69822.69..69822.70 rows=1 width=16) (actual time=726.609..726.614 rows=1 loops=1) explain
      Output: 0
      Buffers: shared hit=3 read=62240, local dirtied=1 written=1
      I/O Timings: shared read=439.492, local write=0.068
      ->  Subquery Scan on "*SELECT*"  (cost=69822.69..69822.70 rows=1 width=16) (actual time=725.904..725.907 rows=1 loops=1)
            Output: "*SELECT*".count
            Buffers: shared hit=3 read=62240
            I/O Timings: shared read=439.492
            ->  Aggregate  (cost=69822.69..69822.70 rows=1 width=8) (actual time=725.901..725.902 rows=1 loops=1)
                  Output: count(DISTINCT t1._idrref)
                  Buffers: shared hit=3 read=62240
                  I/O Timings: shared read=439.492
                  ->  Sort  (cost=69822.51..69822.60 rows=92 width=17) (actual time=725.894..725.895 rows=0 loops=1)
                        Output: t1._idrref
                        Sort Key: t1._idrref
                        Sort Method: quicksort  Memory: 25kB
                        Buffers: shared hit=3 read=62240
                        I/O Timings: shared read=439.492
                        ->  Seq Scan on public._reference75722 t1  (cost=0.00..69820.30 rows=92 width=17) (actual time=725.879..725.880 rows=0 loops=1)
                              Output: t1._idrref
                              Filter: ((t1._fld2488 = '0'::numeric) AND (t1._fld76608rref = '\\x82930cc47a352c1911e97c80b8a9359e'::bytea))
                              Rows Removed by Filter: 631743
                              Buffers: shared read=62240
                              I/O Timings: shared read=439.492
    Query Identifier: 3165922059677811385
Видим конструкцию "explain (analyse, verbose, buffers)" - как мы выше знаем это сбор плана запроса платформой 1С, и запрос в отличии от просто выборки данных выполняется 1 раз.

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

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