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

Добавим в файл 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>

XML

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

Запрос выполнился за 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 : МассивЗапросов = Запрос.ВыполнитьПакет();'

CODE

Событие 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

CODE

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

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

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

Вывод:

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