Российская СУБД Tantor: отечественные базы данных на PostgreSQL, профессиональная коммерческая система управления БД многопользовательская, разработка на русском языке
Связаться Купить
Этот сайт использует файлы cookie для улучшения пользовательского опыта. Подробнее...
ОК
Блог Tantor

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

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С не собирает план запроса и поэтому выполняет запрос только один раз.
А что со вставкой во временную таблицу?

У нас еще один случай, который по сути объединяет 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