Мониторинг производительности запросов PostgreSQL. Часть 2 - репортинг реализация
Начало тут - Мониторинг производительности запросов PostgreSQL. Часть 1 - репортинг подготовка
Собственно репортинг
Используя простые запросы, можно получить вполне себе полезные и интересные отчеты.
Агрегированные данные за заданный промежуток времени
Запрос
SELECT
database_id ,
SUM(calls) AS calls ,SUM(total_time) AS total_time ,
SUM(rows) AS rows , SUM(shared_blks_hit) AS shared_blks_hit,
SUM(shared_blks_read) AS shared_blks_read ,
SUM(shared_blks_dirtied) AS shared_blks_dirtied,
SUM(shared_blks_written) AS shared_blks_written ,
SUM(local_blks_hit) AS local_blks_hit ,
SUM(local_blks_read) AS local_blks_read ,
SUM(local_blks_dirtied) AS local_blks_dirtied ,
SUM(local_blks_written) AS local_blks_written,
SUM(temp_blks_read) AS temp_blks_read,
SUM(temp_blks_written) temp_blks_written ,
SUM(blk_read_time) AS blk_read_time ,
SUM(blk_write_time) AS blk_write_time
FROM
pg_stat_history
WHERE
queryid IS NULL AND
database_id = DATABASE_ID AND
snapshot_timestamp BETWEEN BEGIN_TIMEPOINT AND END_TIMEPOINT
GROUP BY database_id ;
DB Time
to_char(interval '1 millisecond' * pg_total_stat_history_rec.total_time, 'HH24:MI:SS.MS')
I/O Time
to_char(interval '1 millisecond' * ( pg_total_stat_history_rec.blk_read_time + pg_total_stat_history_rec.blk_write_time ), 'HH24:MI:SS.MS')
TOP10 SQL by total_time
Запрос
SELECT
queryid ,
SUM(calls) AS calls ,
SUM(total_time) AS total_time
FROM
pg_stat_history
WHERE
queryid IS NOT NULL AND
database_id = DATABASE_ID AND
snapshot_timestamp BETWEEN BEGIN_TIMEPOINT AND END_TIMEPOINT
GROUP BY queryid
ORDER BY 3 DESC
LIMIT 10
-------------------------------------------------------------------------------------
| TOP10 SQL BY TOTAL EXECUTION TIME
| #| queryid| calls| calls %| total_time (ms) | dbtime %
+----+-----------+-----------+-----------+--------------------------------+----------
| 1| 821760255| 2| .00001|00:03:23.141( 203141.681 ms.)| 5.42
| 2| 4152624390| 2| .00001|00:03:13.929( 193929.215 ms.)| 5.17
| 3| 1484454471| 4| .00001|00:02:09.129( 129129.057 ms.)| 3.44
| 4| 655729273| 1| .00000|00:02:01.869( 121869.981 ms.)| 3.25
| 5| 2460318461| 1| .00000|00:01:33.113( 93113.835 ms.)| 2.48
| 6| 2194493487| 4| .00001|00:00:17.377( 17377.868 ms.)| .46
| 7| 1053044345| 1| .00000|00:00:06.156( 6156.352 ms.)| .16
| 8| 3644780286| 1| .00000|00:00:01.063( 1063.830 ms.)| .03
TOP10 SQL by total I/O time
Запрос
SELECT
queryid ,
SUM(calls) AS calls ,
SUM(blk_read_time + blk_write_time) AS io_time
FROM
pg_stat_history
WHERE
queryid IS NOT NULL AND
database_id = DATABASE_ID AND
snapshot_timestamp BETWEEN BEGIN_TIMEPOINT AND END_TIMEPOINT
GROUP BY queryid
ORDER BY 3 DESC
LIMIT 10
----------------------------------------------------------------------------------------
| TOP10 SQL BY TOTAL I/O TIME
| #| queryid| calls| calls %| I/O time (ms)|db I/O time %
+----+-----------+-----------+-----------+--------------------------------+-------------
| 1| 4152624390| 2| .00001|00:08:31.616( 511616.592 ms.)| 31.06
| 2| 821760255| 2| .00001|00:08:27.099( 507099.036 ms.)| 30.78
| 3| 655729273| 1| .00000|00:05:02.209( 302209.137 ms.)| 18.35
| 4| 2460318461| 1| .00000|00:04:05.981( 245981.117 ms.)| 14.93
| 5| 1484454471| 4| .00001|00:00:39.144( 39144.221 ms.)| 2.38
| 6| 2194493487| 4| .00001|00:00:18.182( 18182.816 ms.)| 1.10
| 7| 1053044345| 1| .00000|00:00:16.611( 16611.722 ms.)| 1.01
| 8| 3644780286| 1| .00000|00:00:00.436( 436.205 ms.)| .03
TOP10 SQL by max time of execution
Запрос
SELECT
id AS snapshotid ,
queryid ,
snapshot_timestamp ,
max_time
FROM
pg_stat_history
WHERE
queryid IS NOT NULL AND
database_id = DATABASE_ID AND
snapshot_timestamp BETWEEN BEGIN_TIMEPOINT AND END_TIMEPOINT
ORDER BY 4 DESC
LIMIT 10
-----------------------------------------------------------------------------------------
| TOP10 SQL BY MAX EXECUTION TIME
| #| snapshot| snapshotID| queryid| max_time (ms)
+----+------------------+-----------+-----------+----------------------------------------
| 1| 05.04.2019 01:03| 4169| 655729273| 00:02:01.869( 121869.981 ms.)
| 2| 04.04.2019 17:00| 4153| 821760255| 00:01:41.570( 101570.841 ms.)
| 3| 04.04.2019 16:00| 4146| 821760255| 00:01:41.570( 101570.841 ms.)
| 4| 04.04.2019 16:00| 4144| 4152624390| 00:01:36.964( 96964.607 ms.)
| 5| 04.04.2019 17:00| 4151| 4152624390| 00:01:36.964( 96964.607 ms.)
| 6| 05.04.2019 10:00| 4188| 1484454471| 00:01:33.452( 93452.150 ms.)
| 7| 04.04.2019 17:00| 4150| 2460318461| 00:01:33.113( 93113.835 ms.)
| 8| 04.04.2019 15:00| 4140| 1484454471| 00:00:11.892( 11892.302 ms.)
| 9| 04.04.2019 16:00| 4145| 1484454471| 00:00:11.892( 11892.302 ms.)
| 10| 04.04.2019 17:00| 4152| 1484454471| 00:00:11.892( 11892.302 ms.)
TOP10 SQL by SHARED buffer read/write
Запрос
SELECT
id AS snapshotid ,
queryid ,
snapshot_timestamp ,
shared_blks_read ,
shared_blks_written
FROM
pg_stat_history
WHERE
queryid IS NOT NULL AND
database_id = DATABASE_ID AND
snapshot_timestamp BETWEEN BEGIN_TIMEPOINT AND END_TIMEPOINT AND
( shared_blks_read > 0 OR shared_blks_written > 0 )
ORDER BY 4 DESC , 5 DESC
LIMIT 10
--------------------------------------------------------------------------------------------
| TOP10 SQL BY SHARED BUFFER READ/WRITE
| #| snapshot| snapshotID| queryid| shared blocks read| shared blocks write
+----+------------------+-----------+-----------+---------------------+---------------------
| 1| 04.04.2019 17:00| 4153| 821760255| 797308| 0
| 2| 04.04.2019 16:00| 4146| 821760255| 797308| 0
| 3| 05.04.2019 01:03| 4169| 655729273| 797158| 0
| 4| 04.04.2019 16:00| 4144| 4152624390| 756514| 0
| 5| 04.04.2019 17:00| 4151| 4152624390| 756514| 0
| 6| 04.04.2019 17:00| 4150| 2460318461| 734117| 0
| 7| 04.04.2019 17:00| 4155| 3644780286| 52973| 0
| 8| 05.04.2019 01:03| 4168| 1053044345| 52818| 0
| 9| 04.04.2019 15:00| 4141| 2194493487| 52813| 0
| 10| 04.04.2019 16:00| 4147| 2194493487| 52813| 0
--------------------------------------------------------------------------------------------
Гистограмма распределения запросов по максимальному времени выполнения
Запросы
SELECT
MIN(max_time) AS hist_min ,
MAX(max_time) AS hist_max ,
(( MAX(max_time) - MIN(min_time) ) / hist_columns ) as hist_width
FROM
pg_stat_history
WHERE
queryid IS NOT NULL AND
database_id = DATABASE_ID AND
snapshot_timestamp BETWEEN BEGIN_TIMEPOINT AND END_TIMEPOINT ;
SELECT
SUM(calls) AS calls
FROM
pg_stat_history
WHERE
queryid IS NOT NULL AND
database_id =DATABASE_ID AND
snapshot_timestamp BETWEEN BEGIN_TIMEPOINT AND END_TIMEPOINT AND
( max_time >= hist_current_min AND max_time < hist_current_max ) ;
|-----------------------------------------------------------------------------------------------
| MAX_TIME HISTOGRAM
| TOTAL CALLS : 33851920
| MIN TIME : 00:00:01.063
| MAX TIME : 00:02:01.869
---------------------------------------------------------------------------------
| min duration| max duration| calls
+----------------------------------+----------------------------------+----------
| 00:00:01.063( 1063.830 ms.) | 00:00:13.144( 13144.445 ms.) | 9
| 00:00:13.144( 13144.445 ms.) | 00:00:25.225( 25225.060 ms.) | 0
| 00:00:25.225( 25225.060 ms.) | 00:00:37.305( 37305.675 ms.) | 0
| 00:00:37.305( 37305.675 ms.) | 00:00:49.386( 49386.290 ms.) | 0
| 00:00:49.386( 49386.290 ms.) | 00:01:01.466( 61466.906 ms.) | 0
| 00:01:01.466( 61466.906 ms.) | 00:01:13.547( 73547.521 ms.) | 0
| 00:01:13.547( 73547.521 ms.) | 00:01:25.628( 85628.136 ms.) | 0
| 00:01:25.628( 85628.136 ms.) | 00:01:37.708( 97708.751 ms.) | 4
| 00:01:37.708( 97708.751 ms.) | 00:01:49.789( 109789.366 ms.) | 2
| 00:01:49.789( 109789.366 ms.) | 00:02:01.869( 121869.981 ms.) | 0
TOP10 Snapshots by Query per Second
Запросы
--pg_qps.sql
--Calculate Query Per Second
CREATE OR REPLACE FUNCTION pg_qps( pg_stat_history_id integer ) RETURNS double precision AS $$
DECLARE
pg_stat_history_rec record ;
prev_pg_stat_history_id integer ;
prev_pg_stat_history_rec record;
total_seconds double precision ;
result double precision;
BEGIN
result = 0 ;
SELECT *
INTO pg_stat_history_rec
FROM
pg_stat_history
WHERE id = pg_stat_history_id ;
IF pg_stat_history_rec.snapshot_timestamp IS NULL
THEN
RAISE EXCEPTION 'ERROR - Not found pg_stat_history for id = %',pg_stat_history_id;
END IF ;
--RAISE NOTICE 'pg_stat_history_id = % , snapshot_timestamp = %', pg_stat_history_id ,
pg_stat_history_rec.snapshot_timestamp ;
SELECT
MAX(id)
INTO
prev_pg_stat_history_id
FROM
pg_stat_history
WHERE
database_id = pg_stat_history_rec.database_id AND
queryid IS NULL AND
id < pg_stat_history_rec.id ;
IF prev_pg_stat_history_id IS NULL
THEN
RAISE NOTICE 'Not found previous pg_stat_history shapshot for id = %',pg_stat_history_id;
RETURN NULL ;
END IF;
SELECT *
INTO prev_pg_stat_history_rec
FROM
pg_stat_history
WHERE id = prev_pg_stat_history_id ;
--RAISE NOTICE 'prev_pg_stat_history_id = % , prev_snapshot_timestamp = %', prev_pg_stat_history_id , prev_pg_stat_history_rec.snapshot_timestamp ;
total_seconds = extract(epoch from ( pg_stat_history_rec.snapshot_timestamp - prev_pg_stat_history_rec.snapshot_timestamp ));
--RAISE NOTICE 'total_seconds = % ', total_seconds ;
--RAISE NOTICE 'calls = % ', pg_stat_history_rec.calls ;
IF total_seconds > 0
THEN
result = pg_stat_history_rec.calls / total_seconds ;
ELSE
result = 0 ;
END IF;
RETURN result ;
END
$$ LANGUAGE plpgsql;
SELECT
id ,
snapshot_timestamp ,
calls ,
total_time ,
( select pg_qps( id )) AS QPS ,
blk_read_time ,
blk_write_time
FROM
pg_stat_history
WHERE
queryid IS NULL AND
database_id = DATABASE_ID AND
snapshot_timestamp BETWEEN BEGIN_TIMEPOINT AND END_TIMEPOINT AND
( select pg_qps( id )) IS NOT NULL
ORDER BY 5 DESC
LIMIT 10
|-----------------------------------------------------------------------------------------------
| TOP10 Snapshots ordered by QueryPerSeconds numbers
-----------------------------------------------------------------------------------------------------------------------------------------------
| #| snapshot| snapshotID| calls| total dbtime| QPS| I/O time| I/O time %
+-----+------------------+-----------+-----------+----------------------------------+-----------+----------------------------------+-----------
| 1| 04.04.2019 20:04| 4161| 5758631| 00:06:30.513( 390513.926 ms.)| 1573.396| 00:00:01.470( 1470.110 ms.)| .376
| 2| 04.04.2019 17:00| 4149| 3529197| 00:11:48.830( 708830.618 ms.)| 980.332| 00:12:47.834( 767834.052 ms.)| 108.324
| 3| 04.04.2019 16:00| 4143| 3525360| 00:10:13.492( 613492.351 ms.)| 979.267| 00:08:41.396( 521396.555 ms.)| 84.988
| 4| 04.04.2019 21:03| 4163| 2781536| 00:03:06.470( 186470.979 ms.)| 785.745| 00:00:00.249( 249.865 ms.)| .134
| 5| 04.04.2019 19:03| 4159| 2890362| 00:03:16.784( 196784.755 ms.)| 776.979| 00:00:01.441( 1441.386 ms.)| .732
| 6| 04.04.2019 14:00| 4137| 2397326| 00:04:43.033( 283033.854 ms.)| 665.924| 00:00:00.024( 24.505 ms.)| .009
| 7| 04.04.2019 15:00| 4139| 2394416| 00:04:51.435( 291435.010 ms.)| 665.116| 00:00:12.025( 12025.895 ms.)| 4.126
| 8| 04.04.2019 13:00| 4135| 2373043| 00:04:26.791( 266791.988 ms.)| 659.179| 00:00:00.064( 64.261 ms.)| .024
| 9| 05.04.2019 01:03| 4167| 4387191| 00:06:51.380( 411380.293 ms.)| 609.332| 00:05:18.847( 318847.407 ms.)| 77.507
| 10| 04.04.2019 18:01| 4157| 1145596| 00:01:19.217( 79217.372 ms.)| 313.004| 00:00:01.319( 1319.676 ms.)| 1.666
Hourly Execution History with QueryPerSeconds and I/O Time
Запрос
SELECT
id ,
snapshot_timestamp ,
calls ,
total_time ,
( select pg_qps( id )) AS QPS ,
blk_read_time ,
blk_write_time
FROM
pg_stat_history
WHERE
queryid IS NULL AND
database_id = DATABASE_ID AND
snapshot_timestamp BETWEEN BEGIN_TIMEPOINT AND END_TIMEPOINT
ORDER BY 2
|-----------------------------------------------------------------------------------------------
| HOURLY EXECUTION HISTORY WITH QueryPerSeconds and I/O Time
-----------------------------------------------------------------------------------------------------------------------------------------------
| QUERY PER SECOND HISTORY
| #| snapshot| snapshotID| calls| total dbtime| QPS| I/O time| I/O time %
+-----+------------------+-----------+-----------+----------------------------------+-----------+----------------------------------+-----------
| 1| 04.04.2019 11:00| 4131| 3747| 00:00:00.835( 835.374 ms.)| 1.041| 00:00:00.000( .000 ms.)| .000
| 2| 04.04.2019 12:00| 4133| 1002722| 00:01:52.419( 112419.376 ms.)| 278.534| 00:00:00.149( 149.105 ms.)| .133
| 3| 04.04.2019 13:00| 4135| 2373043| 00:04:26.791( 266791.988 ms.)| 659.179| 00:00:00.064( 64.261 ms.)| .024
| 4| 04.04.2019 14:00| 4137| 2397326| 00:04:43.033( 283033.854 ms.)| 665.924| 00:00:00.024( 24.505 ms.)| .009
| 5| 04.04.2019 15:00| 4139| 2394416| 00:04:51.435( 291435.010 ms.)| 665.116| 00:00:12.025( 12025.895 ms.)| 4.126
| 6| 04.04.2019 16:00| 4143| 3525360| 00:10:13.492( 613492.351 ms.)| 979.267| 00:08:41.396( 521396.555 ms.)| 84.988
| 7| 04.04.2019 17:00| 4149| 3529197| 00:11:48.830( 708830.618 ms.)| 980.332| 00:12:47.834( 767834.052 ms.)| 108.324
| 8| 04.04.2019 18:01| 4157| 1145596| 00:01:19.217( 79217.372 ms.)| 313.004| 00:00:01.319( 1319.676 ms.)| 1.666
| 9| 04.04.2019 19:03| 4159| 2890362| 00:03:16.784( 196784.755 ms.)| 776.979| 00:00:01.441( 1441.386 ms.)| .732
| 10| 04.04.2019 20:04| 4161| 5758631| 00:06:30.513( 390513.926 ms.)| 1573.396| 00:00:01.470( 1470.110 ms.)| .376
| 11| 04.04.2019 21:03| 4163| 2781536| 00:03:06.470( 186470.979 ms.)| 785.745| 00:00:00.249( 249.865 ms.)| .134
| 12| 04.04.2019 23:03| 4165| 1443155| 00:01:34.467( 94467.539 ms.)| 200.438| 00:00:00.015( 15.287 ms.)| .016
| 13| 05.04.2019 01:03| 4167| 4387191| 00:06:51.380( 411380.293 ms.)| 609.332| 00:05:18.847( 318847.407 ms.)| 77.507
| 14| 05.04.2019 02:03| 4171| 189852| 00:00:10.989( 10989.899 ms.)| 52.737| 00:00:00.539( 539.110 ms.)| 4.906
| 15| 05.04.2019 03:01| 4173| 3627| 00:00:00.103( 103.000 ms.)| 1.042| 00:00:00.004( 4.131 ms.)| 4.010
| 16| 05.04.2019 04:00| 4175| 3627| 00:00:00.085( 85.235 ms.)| 1.025| 00:00:00.003( 3.811 ms.)| 4.471
| 17| 05.04.2019 05:00| 4177| 3747| 00:00:00.849( 849.454 ms.)| 1.041| 00:00:00.006( 6.124 ms.)| .721
| 18| 05.04.2019 06:00| 4179| 3747| 00:00:00.849( 849.561 ms.)| 1.041| 00:00:00.000( .051 ms.)| .006
| 19| 05.04.2019 07:00| 4181| 3747| 00:00:00.839( 839.416 ms.)| 1.041| 00:00:00.000( .062 ms.)| .007
| 20| 05.04.2019 08:00| 4183| 3747| 00:00:00.846( 846.382 ms.)| 1.041| 00:00:00.000( .007 ms.)| .001
| 21| 05.04.2019 09:00| 4185| 3747| 00:00:00.855( 855.426 ms.)| 1.041| 00:00:00.000( .065 ms.)| .008
| 22| 05.04.2019 10:00| 4187| 3797| 00:01:40.150( 100150.165 ms.)| 1.055| 00:00:21.845( 21845.217 ms.)| 21.812
Text of all SQL-selects
Запрос
SELECT
queryid ,
query
FROM
pg_stat_history
WHERE
queryid IS NOT NULL AND
database_id = DATABASE_ID AND
snapshot_timestamp BETWEEN BEGIN_TIMEPOINT AND END_TIMEPOINT
GROUP BY queryid , query
Итог
Как видно, довольно простыми средствами, можно получить достаточно много полезной информации о загруженности и состоянии базы.
Примечение:Если в запросах фиксировать queryid то получим историю по отдельному запросу(с целью экономии места отчеты по отдельному запросу опущены).
Итак, статистические данные о производительности запросов - имеются и собираются.
Первый этап «сбор статистических данных» - завершен.
Можно переходить ко второму этапу-«настройка метрик производительности».
Но это уже совсем другая история.
Продолжение следует…
#postgresql #performance #monitoring #reporting #pg_stat_statements