Thursday, August 01, 2019

PostgreSQL - Sampling pg_stat_statements

Have you ever needed to identify the top queries executed in PostgreSQL over the last 30 seconds or 5 minutes? 

In Oracle, you can conveniently retrieve this information using an ASH report. In PostgreSQL, the pg_stat_statements view is analogous to Oracle's v$sqlarea, as it stores query execution statistics since the last reset. Because these statistics are cumulative, answering the question requires sampling pg_stat_statements twice—at the beginning and end of a chosen interval—and then calculating the delta metrics.

I developed a SQL script to implement this concept by leveraging PostgreSQL's temporary table feature. The script samples pg_stat_statements twice over a specific interval (10 seconds in the example below), saves the results into temporary tables, and runs a query to identify the top SQL statements based on total execution time. 

The sample script named pss.sql is shown as follows:


someip.vpc.myco.com:/misc/denis/pgcheck [] $ cat sql/pss.sql

create temp table tmp_pss_ as select 1 as snap_id, now() as sample_time, d.* from  pg_stat_statements  d where 1=0;

insert into tmp_pss_ select 1, now(),   d.* from  pg_stat_statements  d ;
select pg_sleep(10);
insert into tmp_pss_ select 2, now(),   d.* from  pg_stat_statements  d ;


\pset format wrapped
\pset columns 150
\x


select usename, queryid, query_text, duration_s, num_calls, num_rows, total_elapsed_time_ms,
    case num_calls
        when 0 then total_elapsed_time_ms
               else  total_elapsed_time_ms/num_calls end     as ms_per_call
    , (num_blk_hits + num_blk_read)/nullif(num_calls,0)      as logical_reads_per_call
    , 100*num_blk_hits/nullif(num_blk_hits + num_blk_read,0) as hit_percent
from
(
        select u.usename, b.queryid
               , b.query  as  query_text
               , extract ( epoch from (e.sample_time - b.sample_time) ) as duration_s
               , e.calls - b.calls as num_calls
               , e.rows - b.rows as num_rows
               , e.shared_blks_hit - b.shared_blks_hit as num_blk_hits
               , e.shared_blks_read - b.shared_blks_read as num_blk_read
               , round(e.total_time - b.total_time) as total_elapsed_time_ms
        from ( select * from tmp_pss_ where snap_id=1 ) b join
             ( select * from tmp_pss_ where snap_id=2 ) e on e.userid=b.userid and  e.queryid=b.queryid and e.dbid=b.dbid join
              pg_user u on u.usesysid=b.userid
        order by total_elapsed_time_ms desc limit 10
) t;

\x


Here is a demonstration of the 10-second sampling script running against a production Aurora PostgreSQL RDS instance (note: real names have been masked):


someip.vpc.myco.com:/misc/denis/pgcheck [] $ pgconn.sh ini/appa_prusr.ini  sql/pss.sql
---------------------------Your connection inputs---------------------------
Endpoint: vcm-appa-east1a-postgre-prod-tpa-2.cxocijv8i513.us-east-1.rds.amazonaws.com
Port    : 5432
User    : appadbusr1
Database: prusrprdrds
---------------------------------------------------------------------------



------------------- You run the following sql statments ------------
create temp table tmp_pss_ as select 1 as snap_id, now() as sample_time, d.* from  pg_stat_statements  d where 1=0;

insert into tmp_pss_ select 1, now(),   d.* from  pg_stat_statements  d ;
select pg_sleep(10);
insert into tmp_pss_ select 2, now(),   d.* from  pg_stat_statements  d ;


\pset format wrapped
\pset columns 150
\x


select usename, queryid, query_text, duration_s, num_calls, num_rows, total_elapsed_time_ms,
    case num_calls
        when 0 then total_elapsed_time_ms
               else  total_elapsed_time_ms/num_calls end     as ms_per_call
    , (num_blk_hits + num_blk_read)/nullif(num_calls,0)      as logical_reads_per_call
    , 100*num_blk_hits/nullif(num_blk_hits + num_blk_read,0) as hit_percent
from
(
        select u.usename, b.queryid
               , b.query  as  query_text
               , extract ( epoch from (e.sample_time - b.sample_time) ) as duration_s
               , e.calls - b.calls as num_calls
               , e.rows - b.rows as num_rows
               , e.shared_blks_hit - b.shared_blks_hit as num_blk_hits
               , e.shared_blks_read - b.shared_blks_read as num_blk_read
               , round(e.total_time - b.total_time) as total_elapsed_time_ms
        from ( select * from tmp_pss_ where snap_id=1 ) b join
             ( select * from tmp_pss_ where snap_id=2 ) e on e.userid=b.userid and  e.queryid=b.queryid and e.dbid=b.dbid join
              pg_user u on u.usesysid=b.userid
        order by total_elapsed_time_ms desc limit 10
) t;

\x
------------------- end  -------------------------------------------


Timing is on.
SELECT 0
Time: 8.773 ms
INSERT 0 4816
Time: 12.022 ms
 pg_sleep
----------

(1 row)

Time: 10004.895 ms (00:10.005)
INSERT 0 4952
Time: 11.980 ms
Output format is wrapped.
Target width is 150.
Expanded display is on.
-[ RECORD 1 ]----------+-----------------------------------------------------------------------------------------------------------------------------
usename                | prusradm
queryid                | 2553995311
query_text             | (SELECT * FROM PRUSR.COMP_REVENUE_NONCONTRACT WHERE  ACCOUNT_NUM= I_ACCT_NUM AND   COMP_TYPE = ? ORDER BY CRTD_TIMESTAMP)
duration_s             | 10.017147
num_calls              | 30
num_rows               | 75
total_elapsed_time_ms  | 55
ms_per_call            | 1.83333333333333
logical_reads_per_call | 171
hit_percent            | 100
-[ RECORD 2 ]----------+-----------------------------------------------------------------------------------------------------------------------------
usename                | prusradm
queryid                | 3783259900
query_text             | select * from prusr.SEL_ACCT_DTL2($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13) as result
duration_s             | 10.017147
num_calls              | 38
num_rows               | 38
total_elapsed_time_ms  | 45
ms_per_call            | 1.18421052631579
logical_reads_per_call | 17
hit_percent            | 100
-[ RECORD 3 ]----------+-----------------------------------------------------------------------------------------------------------------------------
usename                | prusradm
queryid                | 274367736
query_text             | (Select                                                                                                                     +
                       | A.ACCOUNT_NUM ,                                                                                                             +
                       | ACCOUNT_NAME,                                                                                                               +
                       | ACCOUNT_TYPE ,                                                                                                              +
                       | CONTACT_FIRST_NAME       ,                                                                                                  +
                       | CONTACT_LAST_NAME       ,                                                                                                   +
                       | CONTACT_NUM ,                                                                                                               +
                       | EMAIL_ID        ,                                                                                                           +
                       | PARENT_ID        ,                                                                                                          +
                       | FIBER_READY_FLAG         ,                                                                                                  +
                       | COMP_POINT ,                                                                                                                +
                       | BILLING_POINT   ,                                                                                                           +
                       | ADDR_TYPE_FLAG,                                                                                                             +
                       | COMP_ACCOUNT_ID ,                                                                                                           +
                       | BILLING_ACCOUNT_ID      ,                                                                                                   +
                       | CAN     ,                                                                                                                   +
                       | MASTER_ORDER_NUM        ,                                                                                                   +
                       | A.MSTR_AGREEMENT_NUM,                                                                                                       +
                       | ORDER_ID        ,                                                                                                           +
                       | ACCOUNT_STATUS  ,                                                                                                           +
                       | VENDOR_ADDRESS_TYPE,                                                                                                        +
                       | ACCOUNT_ACTIVE_DATE,                                                                                                        +
                       | ACCOUNT_ACTVN_STATUS,                                                                                                       +
                       | ACCOUNT_VALDN_STATUS,                                                                                                       +
                       | AGREEMENT_SOURCE        ,                                                                                                   +
                       | STATUS  ,                                                                                                                   +
                       | CONTACT_NUM_EXT ,                                                                                                           +
                       | ACCOUNT_ADDRESS_ID,                                                                                                         +
                       | ADDRESS_TYPE    ,                                                                                                           +
                       | STREET_ADDRESS_1,                                                                                                           +
                       | STREET_ADDRESS_2        ,                                                                                                   +
                       | UNIT_TYPE       ,                                                                                                           +
                       | UNIT_VALUE,                                                                                                                 +
                       | CITY    ,                                                                                                                   +
                       | STATE   ,                                                                                                                   +
                       | ZIP_CODE        ,                                                                                                           +
                       | W9_FORM_ID,                                                                                                                 +
                       | VENDOR_ID       ,                                                                                                           +
                       | VENDOR_SEQ_NUM  ,                                                                                                           +
                       | LEASING_OFFICE_FLAG ,                                                                                                       +
                       | WF.VENDOR_ID AS LO_VENDOR_ID            ,                                                                                   +
                       | WF.VENDOR_SEQ_NUM AS LO_VENDOR_SEQ_NUM,                                                                                     +
                       | A.COMP_PROJECT_CODE AS PROJECT_CODE,                                                                                        +
                       | DIFF_PRD_STATUS,                                                                                                            +
                       | CONTRACT_UNITS,                                                                                                             +
                       | MDU_PROPERTY_ID,                                                                                                            +
                       | BILL_CONTACT_FIRST_NAME  ,                                                                                                  +
                       | BILL_CONTACT_LAST_NAME  ,                                                                                                   +
                       | BILL_CONTACT_NUM ,                                                                                                          +
                       | BILL_EMAIL_ID,                                                                                                              +
                       | BILL_CONTACT_NUM_EXT,                                                                                                       +
                       | MARKETING_STATUS,                                                                                                           +
                       | STATE_CODE,                                                                                                                 +
                       | ACTIVE_TO_PAY_COMM,                                                                                                         +
                       | COMMISSION_START_DATE,                                                                                                      +
                       | COMMISSION_END_DATE,                                                                                                        +
                       | COMMISSION_SCHEDULE,                                                                                                        +
                       | (SELECT COUNT(SRVC_ADDR_ID) FROM PRUSR.SERVICE_ADDRESS SA WHERE A.ACCOUNT_NUM=SA.HOA_ACCOUNT_NUM                            +
                       | AND VALDN_CODE >= ? AND SA.VALDN_CODE <= ?) AS VALID_ADDRESS_COUNT                                                          +
                       | FROM PRUSR.ACCOUNT A                                                                                                        +
                       | LEFT JOIN PRUSR.ACCOUNT_ADDRESS AD ON A.ACCOUNT_NUM=AD.ACCOUNT_NUM                                                          +
                       | LEFT JOIN PRUSR.W9_FORM WF ON A.ACCOUNT_NUM=WF.ACCOUNT_NUM                                                                  +
                       | WHERE A.ACCOUNT_NUM=I_ACCOUNT_NUM                                                                                           +
                       | order by ADDRESS_TYPE desc)
duration_s             | 10.017147
num_calls              | 38
num_rows               | 19
total_elapsed_time_ms  | 42
ms_per_call            | 1.10526315789474
logical_reads_per_call | 158
hit_percent            | 100
-[ RECORD 4 ]----------+-----------------------------------------------------------------------------------------------------------------------------
usename                | prusradm
queryid                | 1011339641
query_text             | select sv4.C41 ,sv4.O_SQLCODE ,sv4.O_SQLSTATE ,sv4.O_MESSAGE From  PRUSR.SEL_COMM_DTL_V4(I_ACCOUNT_NUM) sv4
duration_s             | 10.017147
num_calls              | 36
num_rows               | 36
total_elapsed_time_ms  | 18
ms_per_call            | 0.5
logical_reads_per_call | 9
hit_percent            | 100
-[ RECORD 5 ]----------+-----------------------------------------------------------------------------------------------------------------------------
usename                | prusradm
queryid                | 1590377131
query_text             | SELECT TERM_DATE AS AGREEMENT_END_DATE ,                                                                                    +
                       |         (TERM_DATE - cast($1 as interval)) AS DUEL_MODE_PERIOD_BEGIN_DATE,                                                  +
                       |         (TERM_DATE+ cast($2 as interval)) AS SERVICE_TERMINATION_DATE                                                       +
                       |         FROM                                                                                                                +
                       |         PRUSR.TEMP_TERM_AGREEMENT WHERE ACCOUNT_NUM=$3 UNION SELECT                                                         +
                       |         DATE_AGREEMENT_TERMINATED AS AGREEMENT_END_DATE ,                                                                   +
                       |         (DATE_AGREEMENT_TERMINATED -cast($4 as interval) ) AS                                                               +
                       |         DUEL_MODE_PERIOD_BEGIN_DATE,                                                                                        +
                       |         (DATE_AGREEMENT_TERMINATED+cast($5 as interval)) AS SERVICE_TERMINATION_DATE FROM                                   +
                       |         PRUSR.TEMP_TERM_AGREEMENT_HIST                                                                                      +
                       |         WHERE ACCOUNT_NUM= $6 UNION SELECT                                                                                  +
                       |         DATE_REQUESTED AS AGREEMENT_END_DATE                                                                                +
                       |         ,                                                                                                                   +
                       |         (DATE_REQUESTED -cast($7 as interval)) AS DUEL_MODE_PERIOD_BEGIN_DATE,                                              +
                       |         (DATE_REQUESTED+cast($8 as interval)) AS SERVICE_TERMINATION_DATE FROM                                              +
                       |         PRUSR.TEMP_TERM_AGREEMENT_FALLOUT WHERE ACCOUNT_NUM= $9
duration_s             | 10.017147
num_calls              | 19
num_rows               | 0
total_elapsed_time_ms  | 12
ms_per_call            | 0.631578947368421
logical_reads_per_call | 68
hit_percent            | 100
-[ RECORD 6 ]----------+-----------------------------------------------------------------------------------------------------------------------------
usename                | prusradm
queryid                | 1137626341
query_text             | select sv5.C41, sv5.C7 ,sv5.O_SQLCODE ,sv5.O_SQLSTATE ,sv5.O_MESSAGE From  PRUSR.SEL_COMM_DTL_V4(I_ACCOUNT_NUM) sv5
duration_s             | 10.017147
num_calls              | 10
num_rows               | 10
total_elapsed_time_ms  | 3
ms_per_call            | 0.3
logical_reads_per_call | 8
hit_percent            | 100
-[ RECORD 7 ]----------+-----------------------------------------------------------------------------------------------------------------------------
usename                | prusradm
queryid                | 3486729767
query_text             | SELECT GRACE_PERIOD FROM PRUSR.AGREEMENT WHERE MSTR_AGREEMENT_NUM IN (SELECT MSTR_AGREEMENT_NUM FROM PRUSR.ACCOUNT WHERE ACC.
                       |.OUNT_NUM=$1)
duration_s             | 10.017147
num_calls              | 38
num_rows               | 38
total_elapsed_time_ms  | 2
ms_per_call            | 0.0526315789473684
logical_reads_per_call | 7
hit_percent            | 100
-[ RECORD 8 ]----------+-----------------------------------------------------------------------------------------------------------------------------
usename                | prusradm
queryid                | 168909306
query_text             | SELECT AP.* FROM PRUSR.AGREEMENT_PRODUCTS                                                                                   +
                       |                         AP , PRUSR.ACCOUNT A WHERE A.MSTR_AGREEMENT_NUM =                                                   +
                       |                         AP.MSTR_AGREEMENT_NUM AND A.ACCOUNT_NUM = $1 AND AP.ACTIVE                                          +
                       |                         = ? ORDER                                                                                           +
                       |                         BY PRODUCT_ID
duration_s             | 10.017147
num_calls              | 19
num_rows               | 0
total_elapsed_time_ms  | 1
ms_per_call            | 0.0526315789473684
logical_reads_per_call | 6
hit_percent            | 100
-[ RECORD 9 ]----------+-----------------------------------------------------------------------------------------------------------------------------
usename                | prusradm
queryid                | 3140360803
query_text             | SELECT                                                                                                                      +
                       | COMMSN_AUTO_UPD                        FROM PRUSR.AGREEMENT AG ,PRUSR.ACCOUNT A                                             +
                       | WHERE A.MSTR_AGREEMENT_NUM=AG.MSTR_AGREEMENT_NUM                                                                            +
                       | AND A.ACCOUNT_NUM= I_ACCOUNT_NUM
duration_s             | 10.017147
num_calls              | 38
num_rows               | 19
total_elapsed_time_ms  | 1
ms_per_call            | 0.0263157894736842
logical_reads_per_call | 5
hit_percent            | 100
-[ RECORD 10 ]---------+-----------------------------------------------------------------------------------------------------------------------------
usename                | prusradm
queryid                | 2723406496
query_text             | SELECT COUNT(*)              FROM PRUSR.COMP_AGREEMENT WHERE ACCOUNT_NUM=I_ACCT_NUM
duration_s             | 10.017147
num_calls              | 47
num_rows               | 47
total_elapsed_time_ms  | 1
ms_per_call            | 0.0212765957446809
logical_reads_per_call | 3
hit_percent            | 100

Time: 5204.974 ms (00:05.205)
Expanded display is off.


I have also incorporated this logic into pgcheck, a tool I developed. Using pgcheck makes it even easier to specify the sampling duration and the number of top queries to retrieve. The example below shows a 5-minute sample for the top 5 queries:



someip.vpc.myco.com:/misc/denis/pgcheck [] $  pgcheck.py ini/appa_prusr.ini  -psss --limit 5 --delta 300
Trying to obtain connection info from the configuation file  ini/appa_prusr.ini ...

****************************  SQL TEXT ********************************


                 select usename, queryid, query_text, duration_s, num_calls, num_rows, total_elapsed_time_ms,
                         case num_calls
                           when 0 then total_elapsed_time_ms
                           else  total_elapsed_time_ms/num_calls end  as  ms_per_call,
                           (num_blk_hits + num_blk_read)/nullif(num_calls,0)  as logical_reads_per_call,
                           100*num_blk_hits/nullif(num_blk_hits + num_blk_read,0) hit_percent
                           ,num_blk_hits
                           ,num_blk_read
                           ,begin_snap_time
                        from
                        (
                                select u.usename, b.queryid
                                       , substr(b.query, 1,500) query_text
                                       , extract ( epoch from (e.sample_time - b.sample_time) ) as duration_s
                                       , e.calls - b.calls as num_calls
                                       , e.rows - b.rows as num_rows
                                       , e.shared_blks_hit - b.shared_blks_hit as num_blk_hits
                                       , e.shared_blks_read - b.shared_blks_read as num_blk_read
                                       , round(e.total_time - b.total_time) as total_elapsed_time_ms
                                       , b.sample_time as begin_snap_time
                                from ( select * from tmp_pss_ where snap_id=1 ) b join
                                     ( select * from tmp_pss_ where snap_id=2 ) e on e.userid=b.userid and  e.queryid=b.queryid and e.dbid=b.dbid join
                                      pg_user u on u.usesysid=b.userid
                                order by total_elapsed_time_ms desc limit 5) t


***********************************************************************



=================  Sampling top 5 SQLs from pg_stat_statment view for duration 300s order by total elapsed time  =====================
usename                | prusradm
queryid                | 2553995311
begin_snap_time        | 2019-07-30 21:36:34.001250+00:00
duration secs          |     300.07
num_calls              |        571
num_row                |       1519
total elapsed_time_ms  |     1050.0
ms_per_call            | 1.83887915937
logical_reads_per_call |        170
num_blk_hits           |      97335
num_blk_reads          |          0
hit_percent            | 100
query_text             |
         (SELECT * FROM PRUSR.COMP_REVENUE_NONCONTRACT WHERE  ACCOUNT_NUM= I_ACCT_NUM AND   COMP_TYPE = ? ORDER BY CRTD_TIMESTAMP)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
usename                | prusradm
queryid                | 274367736
begin_snap_time        | 2019-07-30 21:36:34.001782+00:00
duration secs          |     300.07
num_calls              |        716
num_row                |        394
total elapsed_time_ms  |      787.0
ms_per_call            | 1.09916201117
logical_reads_per_call |        123
num_blk_hits           |      88139
num_blk_reads          |          0
hit_percent            | 100
query_text             |
         (Select
A.ACCOUNT_NUM ,
ACCOUNT_NAME,
ACCOUNT_TYPE ,
CONTACT_FIRST_NAME       ,
CONTACT_LAST_NAME       ,
CONTACT_NUM ,
EMAIL_ID        ,
PARENT_ID        ,
FIBER_READY_FLAG         ,
COMP_POINT ,
BILLING_POINT   ,
ADDR_TYPE_FLAG,
COMP_ACCOUNT_ID ,
BILLING_ACCOUNT_ID      ,
CAN     ,
MASTER_ORDER_NUM        ,
A.MSTR_AGREEMENT_NUM,
ORDER_ID        ,
ACCOUNT_STATUS  ,
VENDOR_ADDRESS_TYPE,
ACCOUNT_ACTIVE_DATE,
ACCOUNT_ACTVN_STATUS,
ACCOUNT_VALDN_STATUS,
AGREEMENT_SOURCE        ,
STATUS  ,
CONTACT_NUM_EXT ,
ACCOUNT_ADDRESS_ID,
ADDRESS_TYPE    ,
STREET_ADDRESS_1,
STR
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
usename                | prusradm
queryid                | 3783259900
begin_snap_time        | 2019-07-30 21:36:34.003112+00:00
duration secs          |     300.07
num_calls              |        716
num_row                |        716
total elapsed_time_ms  |      567.0
ms_per_call            | 0.791899441341
logical_reads_per_call |         18
num_blk_hits           |      12934
num_blk_reads          |          0
hit_percent            | 100
query_text             |
         select * from prusr.SEL_ACCT_DTL2($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13) as result
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
usename                | prusradm
queryid                | 1011339641
begin_snap_time        | 2019-07-30 21:36:34.001504+00:00
duration secs          |     300.07
num_calls              |        643
num_row                |        643
total elapsed_time_ms  |      223.0
ms_per_call            | 0.346811819596
logical_reads_per_call |         11
num_blk_hits           |       7226
num_blk_reads          |          0
hit_percent            | 100
query_text             |
         select sv4.C41 ,sv4.O_SQLCODE ,sv4.O_SQLSTATE ,sv4.O_MESSAGE From  PRUSR.SEL_COMM_DTL_V4(I_ACCOUNT_NUM) sv4
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
usename                | prusradm
queryid                | 1590377131
begin_snap_time        | 2019-07-30 21:36:34.000081+00:00
duration secs          |     300.07
num_calls              |        358
num_row                |          0
total elapsed_time_ms  |      216.0
ms_per_call            | 0.603351955307
logical_reads_per_call |         68
num_blk_hits           |      24344
num_blk_reads          |          0
hit_percent            | 100
query_text             |
         SELECT TERM_DATE AS AGREEMENT_END_DATE ,
        (TERM_DATE - cast($1 as interval)) AS DUEL_MODE_PERIOD_BEGIN_DATE,
        (TERM_DATE+ cast($2 as interval)) AS SERVICE_TERMINATION_DATE
        FROM
        PRUSR.TEMP_TERM_AGREEMENT WHERE ACCOUNT_NUM=$3 UNION SELECT
        DATE_AGREEMENT_TERMINATED AS AGREEMENT_END_DATE ,
        (DATE_AGREEMENT_TERMINATED -cast($4 as interval) ) AS
        DUEL_MODE_PERIOD_BEGIN_DATE,
        (DATE_AGREEMENT_TERMINATED+cast($5 as interval)) AS SERVICE_TERMINATION_DATE FROM
        PRUSR.TEMP_TERM_AGREEMENT_HIST
        WHERE ACC
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~


I hope this post offers a useful approach for your PostgreSQL performance monitoring and troubleshooting needs! 

Summary 


PostgreSQL's pg_stat_statements view tracks cumulative statistics; therefore, by sampling this view twice over a specific interval, you can calculate delta metrics to identify the most resource-intensive SQL queries. This offers an effective troubleshooting approach similar to Oracle's ASH reports.