Performance monitoring of PostgreSQL queries. Part 1 — Reporting

Engineer — derived from Latin — means inspired.
An engineer can do everything. (c) R.Diesel.
Epigraphs.
Performance monitoring of PostgreSQL queries. Part 1 — Reporting
Or a story about why a database administrator should remember their programming past.

Preface

All names are changed. Any resemblance is purely coincidental. The material represents solely the author's personal opinion.

Disclaimer of warranties: The planned series of articles will not provide detailed and precise descriptions of the tables and scripts used. The materials cannot be used 'AS IS' right away.
Firstly, due to the large volume of material,
secondly, due to the focus on the production database of the actual client.
Therefore, the articles will present only ideas and descriptions in the most general terms.
Perhaps in the future, the system will grow to the level of being uploaded to GitHub, or perhaps not. Time will tell.

The beginning of the story - "Do you remember how it all began?».
What resulted, in broad terms- "Synthesis as one of the methods for improving PostgreSQL performance»

Why all this for me?

Well, firstly, so I don't forget myself, recalling the glorious days in retirement.
Secondly, to systematize what I've written. For I sometimes start to get confused and forget separate parts.

And most importantly — perhaps someone might find it useful and help avoid reinventing the wheel and stepping on rakes. In other words, improve one’s karma (not the Habr kind). For the most valuable thing in this world is ideas. The key is to find an idea. Bringing an idea to reality is purely a technical matter.

So, let’s begin, slowly…

Task statement.

Available:

PostgreSQL database (10.5), mixed load type (OLTP+DSS), of medium-small load, located in AWS cloud.
Database monitoring is absent, infrastructure monitoring is provided by AWS's native tools in minimal configuration.

Required:

To monitor the performance and state of the database, to find and have initial information for optimizing heavy queries to the DB.

A brief preface or analysis of solution options.

First, let's try to analyze the solution options from the perspective of a comparative analysis of benefits and drawbacks for engineers, while the management can handle the benefits and losses, as per the staffing schedule.

Option 1 - "Working on demand"

We keep everything as is. If the client is dissatisfied with something regarding the functionality or performance of the database or application, they will notify the DBA engineers via email or by creating an incident in the ticketing system.
The engineer, upon receiving the notification, will investigate the issue, propose a solution, or postpone the problem, hoping it will resolve itself, and anyway, everything will soon be forgotten.
Cookies and pastries, bruises and bumpsCookies and pastries:
1. No unnecessary actions are needed
2. There is always a way to dodge responsibility and slack off.
3. A lot of time can be spent at one's discretion.
Bruises and bumps:
1. Sooner or later, the client will ponder the essence of existence and cosmic justice in this world, and once again ask themselves the question — why am I paying these people with my money? The outcome is always the same — the only question is when the client will get bored and wave goodbye. And the feeding trough will be empty. It's sad.
2. The engineer's development is zero.
3. Challenges in planning work and load.

Option 2 - "Dancing with tambourines, selling and fitting"

Point 1- Why do we need a monitoring system? We will get everything through requests. Launching a bunch of requests to the data dictionary and dynamic views, turning on various counters, collating everything into tables, periodically analyzing lists and tables. As a result, we have beautiful or not-so-beautiful graphics, tables, reports. The main thing is to have more and more.
Point 2- Generate activity - start analyzing all of this.
Point 3- Prepare a certain document, simply call this document — "how we should organize the database."
Point 4- The client, seeing all this splendor of graphics and numbers, remains in childlike naive confidence — now everything will work out soon. And they easily and painlessly part with their money. Management is also confident — our engineers work tremendously. Load is at maximum.
Point 5- Regularly repeat Point 1.
Cookies and pastries, bruises and bumpsCookies and pastries:
1. The life of managers and engineers is simple, predictable, and filled with activity. Everything buzzes, everyone is busy.
2. The client's life is also not bad — they always believe that they just need to endure a little longer and everything will be fine. It doesn't work out, well, what can you do — this world is unfair, maybe they'll have better luck in the next life.
Bruises and bumps:
1. Sooner or later, there will be a quicker provider of a similar service who will do the same thing for a bit less. If the result is the same, why pay more? This will again lead to the loss of the income stream.
2. It's boring. Just like any meaningless activity.
3. Just like in the previous option — no development whatsoever. But for an engineer, the downside is that unlike the first option, here you need to constantly generate a database. Which takes time. Time that could be better spent on yourself. Because if you don't take care of yourself, no one else will.

Option 3 — There's no need to reinvent the wheel, just buy it and ride.

Engineers at other companies don't eat pizza washed down with beer for nothing (ah, the good old days of 90s Petersburg). Let's use monitoring systems that are built, debugged, and working, and that actually deliver benefits (at least to their creators).
Cookies and pastries, bruises and bumpsCookies and pastries:
1. There's no need to waste time coming up with something that has already been invented. Just take it and use it.
2. Monitoring systems are not written by fools, and they are definitely useful.
3. Working monitoring systems typically provide useful filtered information.
Bruises and bumps:
1. In this case, an engineer is not really an engineer, but merely a user of someone else's product. Or a user.
2. You need to convince the client of the necessity to buy something they really don't want to deal with and shouldn't have to, especially since the budget for the year has been set and won't change. Then you have to allocate a separate resource to adjust it for a specific system. So first, you need to pay, pay, and pay again. And the client is stingy. That's the norm of this life.

What to do — Chernyshevsky? Your question is quite pertinent. (c)

In this specific case and situation, you can approach it just a bit differently — let's create our own monitoring system.
Performance monitoring of PostgreSQL queries. Part 1 — Reporting
Well, not a system in the full sense of the word; that's too grand a term and presumptuous, but at least we can simplify the task a bit and gather more information for resolving performance incidents. So we don't find ourselves in a situation where you say, 'Go there, I don't know where, find that, I don't know what.'

What are the pros and cons of this option:

Pros:
1. It's interesting. At least it's more interesting than constant 'shrink datafile, alter tablespace, etc.'
2. These are new skills and new development. This will eventually lead to well-deserved rewards sooner or later.
Cons:
1. You will have to work. Work a lot.
2. You will need to regularly explain the meaning and prospects of all activities.
3. Something will have to be sacrificed, as the only resource available to an engineer — time — is limited by the universe.
4. The most frightening and unpleasant thing — is that it might result in something like "Not a mouse, not a frog, but an unknown creature."

Those who don't take risks don't drink champagne.
So — the most interesting part begins.

The general idea — schematically

Performance monitoring of PostgreSQL queries. Part 1 — Reporting
(The illustration is taken from the article «Synthesis as one of the methods for improving PostgreSQL performance»)

Explanation:

  • In the target database, the standard PostgreSQL extension — "pg_stat_statements" is installed.
  • In the monitoring database, we create a set of service tables to store the history of pg_stat_statements at the initial stage and to configure metrics and monitoring in the future.
  • On the monitoring host, we create a set of bash scripts, including for generating incidents in the ticketing system.

Service tables

To start, here is a simplified schematic ERD of what we ended up with:
Performance monitoring of PostgreSQL queries. Part 1 — Reporting
Brief description of tablesendpoint — host, connection point to the instance
database — database parameters
pg_stat_history — historical table for storing temporal snapshots of the pg_stat_statements view of the target database
metric_glossary — performance metrics glossary
metric_config — configuration of individual metrics
metric — a specific metric for the query being monitored
metric_alert_history — history of performance alerts
log_query — service table for storing parsed entries from the PostgreSQL log file loaded from AWS
baseline — parameters of the time period used as a baseline
checkpoint — configuration of metrics for checking the state of the database
checkpoint_alert_history — history of alerts for database state checking metrics
pg_stat_db_queries — service table for active queries
activity_log — service table for activity log
trap_oid — service table for trap configuration

Stage 1 — we collect statistical information about performance and obtain reports

The table is used to store statistical information pg_stat_history
Structure of the pg_stat_history table

                                          Table "public.pg_stat_history"
       Column        |            Type             |                          Modifiers
---------------------+-----------------------------+-------------------------------------------
 id                  | integer                     | not null default nextval('pg_stat_history_id_seq'::regclass)
 snapshot_timestamp  | timestamp without time zone |
 database_id         | integer                     |
 dbid                | oid                         |
 userid              | oid                         |
 queryid             | bigint                      |
 query               | text                        |
 calls               | bigint                      |
 total_time          | double precision            |
 min_time            | double precision            |
 max_time            | double precision            |
 mean_time           | double precision            |
 stddev_time         | double precision            |
 rows                | bigint                      |
 shared_blks_hit     | bigint                      |
 shared_blks_read    | bigint                      |
 shared_blks_dirtied | bigint                      |
 shared_blks_written | bigint                      |
 local_blks_hit      | bigint                      |
 local_blks_read     | bigint                      |
 local_blks_dirtied  | bigint                      |
 local_blks_written  | bigint                      |
 temp_blks_read      | bigint                      |
 temp_blks_written   | bigint                      |
 blk_read_time       | double precision            |
 blk_write_time      | double precision            |
 baseline_id         | integer                     |
Indexes:
    "pg_stat_history_pkey" PRIMARY KEY, btree (id)
    "database_idx" btree (database_id)
    "queryid_idx" btree (queryid)
    "snapshot_timestamp_idx" btree (snapshot_timestamp)
Foreign-key constraints:
    "database_id_fk" FOREIGN KEY (database_id) REFERENCES database(id) ON DELETE CASCADE

As seen, the table is merely cumulative data of the view pg_stat_statements in the target database.

Using this table is quite straightforward

pg_stat_history it will represent the accumulated statistics of query execution for each hour. At the beginning of each hour, after the table is populated, the statistics pg_stat_statements are reset using pg_stat_statements_reset().
Note: statistics are collected for queries with execution times longer than 1 second.
Filling the pg_stat_history table

--pg_stat_history.sql
CREATE OR REPLACE FUNCTION pg_stat_history( ) RETURNS boolean AS $$
DECLARE
  endpoint_rec record ;
  database_rec record ;
  pg_stat_snapshot record ;
  current_snapshot_timestamp timestamp without time zone;
BEGIN
  current_snapshot_timestamp = date_trunc('minute',now());  
  
  FOR endpoint_rec IN SELECT * FROM endpoint 
  LOOP
    FOR database_rec IN SELECT * FROM database WHERE endpoint_id = endpoint_rec.id 
	  LOOP
	    
		RAISE NOTICE 'CREATING NEW SNAPSHOT';
		
		--Connect to the target DB	  
	    EXECUTE 'SELECT dblink_connect(''LINK1'',''host='||endpoint_rec.host||' dbname='||database_rec.name||' user=USER password=PASSWORD '')';
 
        RAISE NOTICE 'host % and dbname % ',endpoint_rec.host,database_rec.name;
		RAISE NOTICE 'Creating snapshot of pg_stat_statements for database %',database_rec.name;
		
		SELECT 
	      *
		INTO 
		  pg_stat_snapshot
	    FROM dblink('LINK1',
	      'SELECT 
	       dbid , SUM(calls),SUM(total_time),SUM(rows) ,SUM(shared_blks_hit) ,SUM(shared_blks_read) ,SUM(shared_blks_dirtied) ,SUM(shared_blks_written) , 
           SUM(local_blks_hit) , SUM(local_blks_read) , SUM(local_blks_dirtied) , SUM(local_blks_written) , SUM(temp_blks_read) , SUM(temp_blks_written) , SUM(blk_read_time) , SUM(blk_write_time)
	       FROM pg_stat_statements WHERE dbid=(SELECT oid from pg_database where datname=current_database() ) 
		   GROUP BY dbid
  	      '
	               )
	      AS t
	       ( dbid oid , calls bigint , 
  	         total_time double precision , 
	         rows bigint , shared_blks_hit bigint , shared_blks_read bigint ,shared_blks_dirtied bigint ,shared_blks_written	 bigint ,
             local_blks_hit	 bigint ,local_blks_read bigint , local_blks_dirtied bigint ,local_blks_written bigint ,
             temp_blks_read	 bigint ,temp_blks_written bigint ,
             blk_read_time double precision , blk_write_time double precision	  
	       );
		 
		INSERT INTO pg_stat_history
          ( 
		    snapshot_timestamp  ,database_id  ,
			dbid , calls  ,total_time ,
            rows ,shared_blks_hit  ,shared_blks_read  ,shared_blks_dirtied  ,shared_blks_written ,local_blks_hit , 	 
            local_blks_read,local_blks_dirtied,local_blks_written,temp_blks_read,temp_blks_written, 
            blk_read_time, blk_write_time 
		  )		  
	    VALUES
	      (
	       current_snapshot_timestamp ,
		   database_rec.id ,
	       pg_stat_snapshot.dbid ,pg_stat_snapshot.calls,
	       pg_stat_snapshot.total_time,
	       pg_stat_snapshot.rows ,pg_stat_snapshot.shared_blks_hit ,pg_stat_snapshot.shared_blks_read ,pg_stat_snapshot.shared_blks_dirtied ,pg_stat_snapshot.shared_blks_written , 
           pg_stat_snapshot.local_blks_hit , pg_stat_snapshot.local_blks_read , pg_stat_snapshot.local_blks_dirtied , pg_stat_snapshot.local_blks_written , 
	       pg_stat_snapshot.temp_blks_read , pg_stat_snapshot.temp_blks_written , pg_stat_snapshot.blk_read_time , pg_stat_snapshot.blk_write_time 	   
	      );		   
		  
        RAISE NOTICE 'Creating snapshot of pg_stat_statements for queries with min_time greater than 1000ms';
	
        FOR pg_stat_snapshot IN
          --All queries with max_time greater than 1000 ms
	      SELECT 
	        *
	      FROM dblink('LINK1',
	        'SELECT 
	         dbid , userid ,queryid,query,calls,total_time,min_time ,max_time,mean_time, stddev_time ,rows ,shared_blks_hit ,
			 shared_blks_read ,shared_blks_dirtied ,shared_blks_written , 
             local_blks_hit , local_blks_read , local_blks_dirtied , 
			 local_blks_written , temp_blks_read , temp_blks_written , blk_read_time , 
			 blk_write_time
	         FROM pg_stat_statements 
			 WHERE dbid=(SELECT oid from pg_database where datname=current_database() AND min_time >= 1000 ) 
  	        '

	                  )
	        AS t
	         ( dbid oid , userid oid , queryid bigint ,query text , calls bigint , 
  	           total_time double precision ,min_time double precision	 ,max_time double precision	 , mean_time double precision	 ,  stddev_time double precision	 , 
	           rows bigint , shared_blks_hit bigint , shared_blks_read bigint ,shared_blks_dirtied bigint ,shared_blks_written	 bigint ,
               local_blks_hit	 bigint ,local_blks_read bigint , local_blks_dirtied bigint ,local_blks_written bigint ,
               temp_blks_read	 bigint ,temp_blks_written bigint ,
               blk_read_time double precision , blk_write_time double precision	  
	         )
	    LOOP
		  INSERT INTO pg_stat_history
          ( 
		    snapshot_timestamp  ,database_id  ,
			dbid ,userid  , queryid  , query  , calls  ,total_time ,min_time ,max_time ,mean_time ,stddev_time ,
            rows ,shared_blks_hit  ,shared_blks_read  ,shared_blks_dirtied  ,shared_blks_written ,local_blks_hit , 	 
            local_blks_read,local_blks_dirtied,local_blks_written,temp_blks_read,temp_blks_written, 
            blk_read_time, blk_write_time 
		  )		  
	      VALUES
	      (
	       current_snapshot_timestamp ,
		   database_rec.id ,
	       pg_stat_snapshot.dbid ,pg_stat_snapshot.userid ,pg_stat_snapshot.queryid,pg_stat_snapshot.query,pg_stat_snapshot.calls,
	       pg_stat_snapshot.total_time,pg_stat_snapshot.min_time ,pg_stat_snapshot.max_time,pg_stat_snapshot.mean_time, pg_stat_snapshot.stddev_time ,
	       pg_stat_snapshot.rows ,pg_stat_snapshot.shared_blks_hit ,pg_stat_snapshot.shared_blks_read ,pg_stat_snapshot.shared_blks_dirtied ,pg_stat_snapshot.shared_blks_written , 
           pg_stat_snapshot.local_blks_hit , pg_stat_snapshot.local_blks_read , pg_stat_snapshot.local_blks_dirtied , pg_stat_snapshot.local_blks_written , 
	       pg_stat_snapshot.temp_blks_read , pg_stat_snapshot.temp_blks_written , pg_stat_snapshot.blk_read_time , pg_stat_snapshot.blk_write_time 	   
	      );
		  
        END LOOP;

        PERFORM dblink_disconnect('LINK1');  
				
	  END LOOP ;--FOR database_rec IN SELECT * FROM database WHERE endpoint_id = endpoint_rec.id 
    
  END LOOP;

RETURN TRUE;  
END
$$ LANGUAGE plpgsql;

As a result, after some time in the table pg_stat_history we will have a set of snapshots of the table's content pg_stat_statements of the target database.

Reporting in fact

Using simple queries, you can obtain quite useful and interesting reports.

Aggregated data for a specified time period

Query

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) AS 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

Query

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

Query

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

Query

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

Query

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
--------------------------------------------------------------------------------------------

Histogram of Query Execution Times Distribution

Requests

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 Queries per Second

Requests

--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  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

Query

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

Query

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

Summary

As can be seen, with quite simple tools, one can obtain a significant amount of useful information about the load and state of the database.

Note:If you log queryid in the queries, you will get the history for a specific query (to save space, reports for individual queries have been omitted).

Thus, statistics on query performance are available and being collected.
The first stage, 'data collection', is complete.

You can move on to the second stage—'performance metric tuning'.
Performance monitoring of PostgreSQL queries. Part 1 — Reporting

But that's a completely different story.

To be continued…

Source: habr.com

Buy reliable website hosting with DDoS protection, VPS VDS servers 🔥 Buy reliable website hosting with DDoS protection, VPS VDS servers | ProHoster