Временные расхождения между журналом postgresql и pg_stat_statements - PullRequest
Новая
       52

Временные расхождения между журналом postgresql и pg_stat_statements

0 голосов
/ 25 октября 2018

Кажется, есть несоответствие между временами, зарегистрированными log_min_duration_statement и pg_stat_statements.

Следующее выводится из журнала pg: 

[root@kvrh7os202 pg_log]# less postgresql-Thu-11.log
2018-10-25 10:59:59 +08 [12556]: [9195-1] user=sri,db=sri,app=PostgreSQL JDBC Driver,client=10.176.8.80 LOG:  duration: 6754.569 ms  bind <unnamed>: select resource0_.RESOURCE_FACING_SERVICE_ID as RESOURCE3_20_1_, $1 as RFS4_20_1_, $2 as QB20_1_, $3 as QR20_1_, OBJECT_ID as RESOURCE1_1_, REVISION_ID as RESOURCE2_1_, resourceen1_.OBJECT_ID as OBJECT1_20_0_, resourceen1_.REVISION_ID as REVISION7_20_0_, $4 as QB20_0_, $5 as QR20_0_, resourceen1_.OPTLOCK as OPTLOCK20_0_, resourceen1_.NAME as NAME20_0_, resourceen1_.BRANCH_ID as BRANCH8_20_0

Следующее из pg_stat_statements: 

postgres=# select pd.datname, substr(pss.query,0,100) AS SQLQuery, pss.rows AS rows, pss.min_time, pss.max_time, pss.stddev_time, pss.total_time, pss.calls, (pss.total_time / 1000) AS total_elapsed_in_sec, round(((pss.total_time / 1000)/calls)::numeric,6) as avg_elapsed_in_sec
postgres-# FROM pg_stat_statements AS pss
postgres-# INNER JOIN pg_database AS pd ON pss.dbid=pd.oid
postgres-# where query like 'select resource0_.RESOURCE_FACING_SERVICE_ID%';
 datname |                                              sqlquery                                               | rows | min_time | max_time  |   stddev_time    |    total_time    | calls  | total_elapsed_in_sec | avg_elapsed_in_sec
---------+-----------------------------------------------------------------------------------------------------+------+----------+-----------+------------------+------------------+--------+----------------------+--------------------
 sri     | select resource0_.RESOURCE_FACING_SERVICE_ID as RESOURCE3_20_1_, $1 as RFS4_20_1_, $2 as QB20_1_, $ |    0 | 0.047669 | 97.293171 | 2.21278920834544 | 27451.0374100001 | 106724 |     27.4510374100001 |           0.000257
 sri     | select resource0_.RESOURCE_FACING_SERVICE_ID as RESOURCE3_20_1_, $1 as RFS4_20_1_, $2 as QB20_1_, $ |    0 | 0.038346 | 133.10015 | 1.73874479902066 |     17600.230552 | 106510 |         17.600230552 |           0.000165
(2 rows)

параметр log_min_duration_statement: 

postgres=# show log_min_duration_statement;
log_min_duration_statement
----------------------------
 5s
(1 row)

postgres=#

Журнал Postgres показывает, что длительность запроса составляет 6754,569 мс, тогда как pg_stat_statements показывает, что максимальная длительность запроса составляет 97 мс и 133 мс.Так что мне интересно, куда ушла остальная часть продолжительности.Есть ли способ отследить неучтенное время истечения?

ОС: CentOS Linux выпуск 7.4.1708 (Core) Postgres: PostgreSQL 10.5

...