What’s happening in my database?

Lately at least two people on irc asked questions similar to “how do I know how many queries there are in database, per second?“.

So, let's see what we can find out.

First of all, we can't really tell how many queries per second there are. But we can find out some other metrics, that usually can be very helpful.

These are:

how many queries are being processed now?

$ SELECT state, COUNT(*) FROM pg_stat_activity  WHERE pid <> pg_backend_pid() GROUP BY 1 ORDER BY 1;
 state  | COUNT 
--------+-------
 active |     5
 idle   |    30
(2 ROWS)

This query shows me, that at the moment of running it, I had 35 backends (connections from app/pooler), out of which 5 were doing some work (running some query), and the other 30 were idle.

The where condition above made the query ignore the connection I was using to get the stats.

We can also get some stats on query durations:

$ WITH x AS (
    SELECT
        clock_timestamp ( ) - query_start AS d
    FROM
        pg_stat_activity
    WHERE
        state = 'active'
        AND pid <> pg_backend_pid ( ) )
SELECT
    MIN ( d ),
    avg ( d ),
    MAX ( d ),
    SUM ( d )
FROM
    x;
       MIN       |       avg       |       MAX       |       SUM       
-----------------+-----------------+-----------------+-----------------
 00:00:00.000223 | 12:49:06.680476 | 22:13:02.940536 | 64:05:33.402382
(1 ROW)

This shows me that fastest query running now was 0.000223 seconds, average is almost 13 hours, and max is 22 hours.

What is so slow? We can see by running:

$ SELECT
    clock_timestamp ( ) - query_start,
    substr ( query, 1, 12 )
FROM
    pg_stat_activity
WHERE
    state = 'active'
    AND pid <> pg_backend_pid ( )
ORDER BY
    1 DESC;
    ?COLUMN?     |    substr    
-----------------+--------------
 22:15:11.788594 | autovacuum: 
 21:31:19.38845  | autovacuum: 
 20:25:26.543843 | autovacuum: 
 00:00:01.721468 | SELECT  USER
(4 ROWS)

Of course, in your application you will not use substr, but I wanted to hide details of the database. So basically, the long queries are autovacuums, which is perfectly fine.

Well, how could we go about displaying number of queries running, changing in time?

First, let's start with simple data snapshot:

$ SELECT
    CASE
        WHEN query LIKE 'autovacuum:%' THEN 'autovac'
        ELSE 'normal'
    END AS q,
    COUNT ( * )
FROM
    pg_stat_activity
WHERE
    state = 'active'
    AND pid <> pg_backend_pid ( )
GROUP BY
    q;
    q    | COUNT 
---------+-------
 autovac |     3
 normal  |     1
(2 ROWS)

Now, I will roll it up to single array:

$ WITH x AS (
    SELECT
        CASE
            WHEN query LIKE 'autovacuum:%' THEN 'autovac'
            ELSE 'normal'
        END AS q,
        COUNT ( * ) AS c
    FROM
        pg_stat_activity
    WHERE
        state = 'active'
        AND pid <> pg_backend_pid ( )
    GROUP BY
        q )
SELECT
    now()::TIMESTAMP(0),
    string_agg(
        format('%s:%s', (x).q, (x).c),
        ', '
        ORDER BY (x).q
    ) FROM x;
         now         |     string_agg      
---------------------+---------------------
 2016-06-29 10:57:54 | autovac:3, normal:1
(1 ROW)

Nice. With this “in place", we can just run it with \watch:

$ WITH x AS (
    SELECT
        CASE
            WHEN query LIKE 'autovacuum:%' THEN 'autovac'
            ELSE 'normal'
        END AS q,
        COUNT ( * ) AS c
    FROM
        pg_stat_activity
    WHERE
        state = 'active'
        AND pid <> pg_backend_pid ( )
    GROUP BY
        q )
SELECT
    now()::TIMESTAMP(0),
    string_agg(
        format('%s:%s', (x).q, (x).c),
        ', '
        ORDER BY (x).q
    ) FROM x \watch 1
 Watch every 1s Wed Jun 29 10:58:34 2016
 
         now         |     string_agg      
---------------------+---------------------
 2016-06-29 10:58:34 | autovac:3, normal:2
(1 ROW)
 
 Watch every 1s Wed Jun 29 10:58:35 2016
 
         now         |     string_agg      
---------------------+---------------------
 2016-06-29 10:58:35 | autovac:3, normal:3
(1 ROW)
 
 Watch every 1s Wed Jun 29 10:58:36 2016
 
         now         |     string_agg      
---------------------+---------------------
 2016-06-29 10:58:36 | autovac:3, normal:3
(1 ROW)
...

Not bad, but overly verbose. Luckily, we can:

$ \pset format unaligned
$ \pset tuples_only ON
$ ... the long query WITH \watch 1
2016-06-29 11:00:57|autovac:3, normal:1
2016-06-29 11:00:58|autovac:3, normal:2
2016-06-29 11:00:59|autovac:3, normal:2
...

Nice. This shows some info in easy to comprehend format.

But this is just snapshot of information of currently running queries. What about queries that are too fast to be shown there? Well, we don't know the counts, but we can see how many transactions there are.

Namely, there is pg_stat_database view, which, among other columns, shows:

$ SELECT
    xact_commit,
    xact_rollback,
    tup_returned,
    tup_inserted,
    tup_updated,
    tup_deleted
FROM
    pg_stat_database
WHERE
    datname = current_database ( );
 xact_commit  | xact_rollback |  tup_returned  | tup_inserted | tup_updated | tup_deleted 
--------------+---------------+----------------+--------------+-------------+-------------
 214073969643 |       4970377 | 29185385893084 |  19757428987 |  3318592161 |  1023018705
(1 ROW)

Meaning of columns (all values are counters incrementing from some point in past, where stats were reset):

  • xact_commit – number of committed transactions
  • xact_rollback – number of rolled back transactions
  • tup_returned – sum of number of rows returned from db to application
  • tup_inserted – number of rows inserted into all tables
  • tup_updated – number of rows updated
  • tup_deleted – number of rows deleted

Now, we could get snapshot of this data, to some temp table, then wait, get data again, and show diffs, but it doesn't look all that nice. But there is better way.

First, I'll change the query to include two more columns:

$ SELECT
    now()::TIMESTAMP(0),
    EXTRACT ( 'epoch' FROM now ( ) ),
    xact_commit,
    xact_rollback,
    tup_returned,
    tup_inserted,
    tup_updated,
    tup_deleted
FROM
    pg_stat_database
WHERE
    datname = current_database ( );

Now, if I'd run it with “tuples_only", “unaligned", and “\watch", I would get something like this:

2016-06-29 11:09:23|1467198563.18746|214074734859|4970381|29185517699135|19757544579|3318599787|1023128705
2016-06-29 11:09:24|1467198564.20106|214074736452|4970381|29185517875086|19757544582|3318599803|1023128705
2016-06-29 11:09:25|1467198565.20432|214074739942|4970381|29185518748608|19757545599|3318599823|1023129719
2016-06-29 11:09:26|1467198566.2428|214074744520|4970381|29185519701829|19757545601|3318599845|1023129719

This is still far from readable, but here comes power of using command line. I can run this first:

$ \o | awk -F"|" 'NR>1 {td=$2-t;printf "%s  %10.1f  %10.1f  %10.1f  %10.1f  %10.1f  %10.1f\n", $1, ($3-c)/td, ($4-r)/td, ($5-s)/td, ($6-i)/td, ($7-u)/td, ($8-d)/td} {t=$2;c=$3;r=$4;s=$5;i=$6;u=$7;d=$8}'

This makes psql pipe output from queries to the awk command.

The awk command will calculate diffs, per second, and output them nicely formatted:

$ SELECT now()::TIMESTAMP(0), EXTRACT('epoch' FROM now()), xact_commit, xact_rollback, tup_returned, tup_inserted, tup_updated, tup_deleted FROM pg_stat_database WHERE datname = current_database() \watch 1
2016-06-29 11:14:53      3451.9         0.0   1383784.4         5.9        20.7         1.0
2016-06-29 11:14:54      3254.2         0.0    946807.5       992.0        21.7       989.0
2016-06-29 11:14:55      2806.1         0.0     86992.7         3.9        16.8         1.0
2016-06-29 11:14:56      2281.4         0.0     83585.9       990.7         9.9       987.8
2016-06-29 11:14:57      2278.3         0.0    146808.5         3.0        17.8         1.0
2016-06-29 11:14:58      2062.2         0.0     34477.9         1.0        22.7         0.0
2016-06-29 11:14:59      2106.5         0.0     13056.3       990.6        29.6       986.7

Columns are (all values are per second):

  1. committed transactions
  2. rolled back transactions
  3. returned rows
  4. inserted rows
  5. updated rows
  6. deleted rows

It's important to note that \o effects are persistent, so if I'd ctrl-c the query, and rerun it, it will still ran through awk. To end the redirection, I have to run:

$ \o

What's nice about the awk command is that I can do \watch that outputs values less frequently, but the values will still be per second (averaged):

$ SELECT ...\watch 5
2016-06-29 11:19:00      2550.9         0.0    554407.8       420.4        37.5       411.2
2016-06-29 11:19:05      2617.2         0.0    271401.1       410.1        45.9       403.1
2016-06-29 11:19:10      2292.3         0.0    647357.3       609.6        15.3       605.3
2016-06-29 11:19:15      2035.0         0.0    527849.4       210.3        19.3       203.1
2016-06-29 11:19:21      2411.6         0.0    226432.0       413.9        22.1       405.7

OK. So we know the transaction rate, we know tuple counts, but how can we know which tables are the most used?

This information is in pg_stat_all_tables, which can look like this:

$ SELECT * FROM pg_stat_all_tables LIMIT 1;
-[ RECORD 1 ]-----+------------------------------
relid             | 1293211613
schemaname        | pg_toast
relname           | pg_toast_188640
seq_scan          | 0
seq_tup_read      | 0
idx_scan          | 0
idx_tup_fetch     | 0
n_tup_ins         | 0
n_tup_upd         | 0
n_tup_del         | 0
n_tup_hot_upd     | 0
n_live_tup        | 0
n_dead_tup        | 0
last_vacuum       | 2016-02-05 07:59:47.201745+00
last_autovacuum   | 2016-06-10 06:21:55.040321+00
last_analyze      | [NULL]
last_autoanalyze  | [NULL]
vacuum_count      | 2
autovacuum_count  | 1
analyze_count     | 0
autoanalyze_count | 0

First, let's try to get the most used tables using pure sql approach. This will require couple of queries:

$ CREATE temp TABLE ts AS SELECT now(), * FROM pg_stat_all_tables ;
SELECT 467

Then I have to wait couple of seconds, and do:

$ INSERT INTO ts SELECT now(), * FROM pg_stat_all_tables;
INSERT 0 468

Sweet. Now for all tables (with the exception of ts itself) I have two rows, with different timestamps in “now" column, so I can compare them, and calculate some stats. This can be done using window functions:

$ WITH data_with_diffs AS (
    SELECT
        schemaname,
        relname,
        EXTRACT('epoch' FROM now - lag(now) OVER (partition BY schemaname, relname ORDER BY now)) AS time_diff,
        COALESCE(seq_scan, 0) - lag(COALESCE(seq_scan, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS seq_scan_diff,
        COALESCE(seq_tup_read, 0) - lag(COALESCE(seq_tup_read, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS seq_tup_read_diff,
        COALESCE(idx_scan, 0) - lag(COALESCE(idx_scan, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS idx_scan_diff,
        COALESCE(idx_tup_fetch, 0) - lag(COALESCE(idx_tup_fetch, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS idx_tup_fetch_diff,
        COALESCE(n_tup_ins, 0) - lag(COALESCE(n_tup_ins, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS n_tup_ins_diff,
        COALESCE(n_tup_upd, 0) - lag(COALESCE(n_tup_upd, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS n_tup_upd_diff,
        COALESCE(n_tup_del, 0) - lag(COALESCE(n_tup_del, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS n_tup_del_diff,
        COALESCE(n_tup_hot_upd, 0) - lag(COALESCE(n_tup_hot_upd, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS n_tup_hot_upd_diff
    FROM ts
), just_diffs AS (
    SELECT
        schemaname, relname,
        seq_scan_diff / time_diff AS seq_scan_ps,
        seq_tup_read_diff / time_diff AS seq_tup_read_ps,
        idx_scan_diff / time_diff AS idx_scan_ps,
        idx_tup_fetch_diff / time_diff AS idx_tup_fetch_ps,
        n_tup_ins_diff / time_diff AS n_tup_ins_ps,
        n_tup_upd_diff / time_diff AS n_tup_upd_ps,
        n_tup_del_diff / time_diff AS n_tup_del_ps,
        n_tup_hot_upd_diff / time_diff AS n_tup_hot_upd_ps
    FROM
        data_with_diffs
    WHERE
        time_diff IS NOT NULL
)
SELECT * FROM just_diffs;

if you're not clear what seq_scan/seq_tup_read/idx_scan/idx_tup_fetch/n_tup_* columns are, please check the docs.

output from this might look like this:

     schemaname     |               relname                |    seq_scan_ps     |  seq_tup_read_ps  |    idx_scan_ps     |  idx_tup_fetch_ps  |    n_tup_ins_ps    |    n_tup_upd_ps    |    n_tup_del_ps    |  n_tup_hot_upd_ps  
--------------------+--------------------------------------+--------------------+-------------------+--------------------+--------------------+--------------------+--------------------+--------------------+--------------------
 xy                 | t1                                   |                  0 |                 0 |                  0 |                  0 |                  0 |                  0 |                  0 |                  0
 abcdefghi          | t2                                   |                  0 |                 0 |                  0 |                  0 |                  0 |                  0 |                  0 |                  0
 abcdefghi          | t3                                   |   1.17102071010696 |  696235.006896908 |   22.9762339327883 |   22.9762339327883 |                  0 |   1.41330085702564 |                  0 |   1.41330085702564
 abcdefghi          | t4                                   | 0.0807600489728937 |                 0 |   2.22090134675458 |   3.43230208134798 |                  0 |                  0 |                  0 |                  0
 abcdefghi          | t5                                   |                  0 |                 0 |                  0 |                  0 |                  0 |                  0 |                  0 |                  0
 abcdefghi          | t6                                   |                  0 |                 0 |                  0 |                  0 |                  0 |                  0 |                  0 |                  0

And now I can also get just “top 10" from each of category (with some additional formatting to avoid having to deal with ugly values):

$ WITH data_with_diffs AS (
    SELECT
        schemaname,
        relname,
        EXTRACT('epoch' FROM now - lag(now) OVER (partition BY schemaname, relname ORDER BY now)) AS time_diff,
        COALESCE(seq_scan, 0) - lag(COALESCE(seq_scan, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS seq_scan_diff,
        COALESCE(seq_tup_read, 0) - lag(COALESCE(seq_tup_read, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS seq_tup_read_diff,
        COALESCE(idx_scan, 0) - lag(COALESCE(idx_scan, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS idx_scan_diff,
        COALESCE(idx_tup_fetch, 0) - lag(COALESCE(idx_tup_fetch, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS idx_tup_fetch_diff,
        COALESCE(n_tup_ins, 0) - lag(COALESCE(n_tup_ins, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS n_tup_ins_diff,
        COALESCE(n_tup_upd, 0) - lag(COALESCE(n_tup_upd, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS n_tup_upd_diff,
        COALESCE(n_tup_del, 0) - lag(COALESCE(n_tup_del, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS n_tup_del_diff,
        COALESCE(n_tup_hot_upd, 0) - lag(COALESCE(n_tup_hot_upd, 0)) OVER (partition BY schemaname, relname ORDER BY now) AS n_tup_hot_upd_diff
    FROM ts
), just_diffs AS (
    SELECT
        schemaname, relname,
        seq_scan_diff / time_diff AS seq_scan_ps,
        seq_tup_read_diff / time_diff AS seq_tup_read_ps,
        idx_scan_diff / time_diff AS idx_scan_ps,
        idx_tup_fetch_diff / time_diff AS idx_tup_fetch_ps,
        n_tup_ins_diff / time_diff AS n_tup_ins_ps,
        n_tup_upd_diff / time_diff AS n_tup_upd_ps,
        n_tup_del_diff / time_diff AS n_tup_del_ps,
        n_tup_hot_upd_diff / time_diff AS n_tup_hot_upd_ps
    FROM
        data_with_diffs
    WHERE
        time_diff IS NOT NULL
)
SELECT
    schemaname,
    relname,
    seq_scan_ps::NUMERIC(10,2),
    seq_tup_read_ps::NUMERIC(10,2),
    idx_scan_ps::NUMERIC(10,2),
    idx_tup_fetch_ps::NUMERIC(10,2),
    n_tup_ins_ps::NUMERIC(10,2),
    n_tup_upd_ps::NUMERIC(10,2),
    n_tup_del_ps::NUMERIC(10,2),
    n_tup_hot_upd_ps::NUMERIC(10,2)
FROM just_diffs
ORDER BY seq_tup_read_ps DESC
LIMIT 10;
 schemaname |          relname           | seq_scan_ps | seq_tup_read_ps | idx_scan_ps | idx_tup_fetch_ps | n_tup_ins_ps | n_tup_upd_ps | n_tup_del_ps | n_tup_hot_upd_ps 
------------+----------------------------+-------------+-----------------+-------------+------------------+--------------+--------------+--------------+------------------
 abcdefghi  | some_table_1               |        1.17 |       696235.01 |       22.98 |            22.98 |         0.00 |         1.41 |         0.00 |             1.41
 abcdefghi  | some_table_2               |        0.52 |        67596.81 |        0.00 |             0.00 |         0.00 |         0.00 |         0.00 |             0.00
 abcdefghi  | some_table_3               |        0.24 |        23797.24 |        5.98 |             4.24 |         0.00 |         0.00 |         0.00 |             0.00
 abcdefghi  | some_table_4               |        0.57 |        22572.68 |      109.43 |           175.33 |         0.00 |         0.00 |         0.00 |             0.00
 abcdefghi  | some_table_5               |       29.68 |         9029.78 |        0.00 |             0.00 |         0.00 |         0.00 |         0.00 |             0.00
 abcdefghi  | some_table_6               |      113.35 |         2040.24 |        0.00 |             0.00 |         0.00 |         0.00 |         0.00 |             0.00
 abcdefghi  | some_table_7               |        0.04 |          372.71 |        0.00 |             0.00 |         0.00 |         0.00 |        10.10 |             0.00
 abcdefghi  | some_table_8               |        7.07 |          148.40 |        0.00 |             0.00 |         0.00 |         0.00 |         0.00 |             0.00
 pg_catalog | pg_class                   |        0.04 |           71.39 |       35.53 |            34.52 |         0.04 |         0.00 |         0.00 |             0.00
 pg_catalog | pg_index                   |        0.04 |           39.86 |       14.98 |            20.80 |         0.00 |         0.00 |         0.00 |             0.00
(10 ROWS)

Obviously I can sort it using any key I want to see what's the deal with inserts, or anything like this.

The question now is, can I do something like I did for transaction count previously, and just show top-10 every so often, most active tables?

We could use AWK, again, but this seems slightly more complex scenario, so let's try different approach. We will start with query:

$ SELECT now()::TIMESTAMP(0), EXTRACT('epoch' FROM now()), COUNT(*) OVER (), schemaname || '.' || relname AS TABLE_NAME, seq_scan, seq_tup_read, idx_scan, idx_tup_fetch, n_tup_ins, n_tup_upd, n_tup_del, n_tup_hot_upd FROM pg_stat_all_tables;
         now         |    date_part     | COUNT |        TABLE_NAME        | seq_scan | seq_tup_read | idx_scan  | idx_tup_fetch | n_tup_ins | n_tup_upd | n_tup_del | n_tup_hot_upd 
---------------------+------------------+-------+--------------------------+----------+--------------+-----------+---------------+-----------+-----------+-----------+---------------
 2016-06-29 12:19:51 | 1467202790.53523 |   467 | pg_toast.pg_toast_188640 |        0 |            0 |         0 |             0 |         0 |         0 |         0 |             0
 2016-06-29 12:19:51 | 1467202790.53523 |   467 | pg_toast.pg_toast_188626 |        0 |            0 |     27542 |         28088 |       549 |         0 |       371 |             0
 2016-06-29 12:19:51 | 1467202790.53523 |   467 | pg_toast.pg_toast_189395 |        0 |            0 | 109601683 |     281576929 |    484364 |         0 |    318048 |             0
...

I added the 3rd column, so that my filtering script will know how many rows to expect, so it will not have to wait for “next" batch of data to print current one.

Now, I need the script. It can be written in virtually any language on earth, as long as it supports reading from stdin, and writing to stdout. So, let's try ruby:

#!/usr/bin/env ruby
# encoding: utf-8
 
require 'pp'
 
state=:outside
data_count=0
$header=[]
 
$old={}
$new={:data => {}}
 
def show_top_10
  time_diff=$new[:epoch]-$old[:epoch]
  diffs={}
  $new[:data].each do |table, columns|
    next unless $old[:data].include? table
    diffs[table]=columns.zip($old[:data][table]).map { |i| (i[0]-i[1])/time_diff }
  end
  top_10=diffs.sort { |a,b| b[1][0] <=> a[1][0] }[0,9]
 
  puts "\n>>> Top 10, by #{$header[0]} (per second), from #{$old[:when]} to #{$new[:when]}:"
 
  max_table_length=top_10.map { |x| x[0].length }.max
  max_table_length=11 if max_table_length < 11
  printf " %-#{max_table_length}s", "table name:"
 
  column_lengths=$header.map { |h| h.length+1 > 10 ? h.length+1 : 10 }
 
  $header.zip(column_lengths).each do |h, len|
    printf " | %-#{len}s", "#{h}:"
  end
  printf "\n"
 
  puts(([max_table_length] + column_lengths).map { |l| "="*(l+2) }.join('+'))
 
  top_10.each do | table, data |
    printf " %-#{max_table_length}s", table
    data.zip(column_lengths).each do |v, len|
      printf " | %#{len}.2f", v
    end
    printf "\n"
  end
 
  puts(([max_table_length] + column_lengths).map { |l| "="*(l+2) }.join('+'))
end
 
def finalize_block
  show_top_10 unless $old.empty?
  $old=$new
  $new={:data => {}}
end
 
$stdin.each_line do |l|
  columns=l.chomp.split %r{\s*\|\s*};
  if ( state == :outside ) && ( l.match(%r{^\s*now\s*\|}) )
    state=:header
    $header=columns[4..-1].map { |c| c.strip }
  end
  if ( state == :header ) && ( l.match(%r{^\s*\d+-\d+-\d+} ) )
    state=:data
    data_count=columns[2].to_i
  end
  if ( state == :data )
    $new[:when]=columns[0]
    $new[:epoch]=columns[1].to_f
    $new[:data][columns[3]]=columns[4..-1].map { |x| x.to_f }
    data_count-=1
    if data_count == 0
      state=:outside
      finalize_block
    end
  end
end

So, it's not the nicest code I ever written, but it does the job.

Now, I just save it as ~/filter.rb, chmod 755 ~/filter.rb, and then in psql, I can:

$ \o | ~/FILTER.rb
$ SELECT
    now ( ) ::TIMESTAMP ( 0 ),
    EXTRACT ( 'epoch' FROM now ( ) ),
    COUNT ( * ) OVER ( ),
    schemaname || '.' || relname AS TABLE_NAME,
    seq_scan,
    seq_tup_read,
    idx_scan,
    idx_tup_fetch,
    n_tup_ins,
    n_tup_upd,
    n_tup_del,
    n_tup_hot_upd
FROM
    pg_stat_all_tables
\watch 1

And I'm getting:

>>> Top 10, BY seq_scan (per SECOND), FROM  2016-06-29 13:02:42 TO  2016-06-29 13:02:43:
 TABLE name:                      | seq_scan:  | seq_tup_read: | idx_scan:  | idx_tup_fetch: | n_tup_ins: | n_tup_upd: | n_tup_del: | n_tup_hot_upd:
==================================+============+===============+============+================+============+============+============+================
 xxxxxxxxxxxxxxxxxxxxxxxxxxxx     |      93.86 |      29676.66 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxx          |      18.20 |        112.06 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
 pg_catalog.pg_am                 |       6.70 |          6.70 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx |       5.75 |          0.00 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxx           |       3.83 |          0.00 |     401.29 |        1302.53 |       0.00 |       0.00 |       0.00 |           0.00
 pg_catalog.pg_namespace          |       0.96 |        457.80 |      42.14 |          35.44 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxx            |       0.96 |          0.00 |     698.20 |        1910.70 |       0.00 |      10.54 |       0.00 |          10.54
 pg_catalog.pg_class              |       0.96 |       1693.29 |      58.42 |          58.42 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxx          |       0.96 |     140074.89 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
==================================+============+===============+============+================+============+============+============+================
 
>>> Top 10, BY seq_scan (per SECOND), FROM  2016-06-29 13:02:43 TO  2016-06-29 13:02:44:
 TABLE name:                             | seq_scan:  | seq_tup_read: | idx_scan:  | idx_tup_fetch: | n_tup_ins: | n_tup_upd: | n_tup_del: | n_tup_hot_upd:
=========================================+============+===============+============+================+============+============+============+================
 xxxxxxxxxxxxxxxxxxxxxxxxxxxx            |      77.28 |      24152.29 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxx                 |       7.73 |         36.71 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxx                         |       4.83 |          0.00 |     162.30 |         162.30 |       0.00 |       0.97 |       0.00 |           0.97
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx        |       2.90 |          0.00 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxxxxxx             |       1.93 |          0.00 |       8.69 |           8.69 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx |       1.93 |          0.00 |       5.80 |           0.00 |       2.90 |       0.00 |       0.00 |           0.00
 pg_catalog.pg_class                     |       0.97 |       1707.98 |      14.49 |          14.49 |       0.00 |       0.00 |       0.00 |           0.00
 pg_catalog.pg_namespace                 |       0.97 |        461.77 |       5.80 |           4.83 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx        |       0.97 |          0.00 |      25.12 |          25.12 |       0.00 |       0.00 |       0.00 |           0.00
=========================================+============+===============+============+================+============+============+============+================
 
>>> Top 10, BY seq_scan (per SECOND), FROM  2016-06-29 13:02:44 TO  2016-06-29 13:02:45:
 TABLE name:                      | seq_scan:  | seq_tup_read: | idx_scan:  | idx_tup_fetch: | n_tup_ins: | n_tup_upd: | n_tup_del: | n_tup_hot_upd:
==================================+============+===============+============+================+============+============+============+================
 xxxxxxxxxxxxxxxxxxxxxxxxxxxx     |      95.25 |      30116.83 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxx          |      17.50 |        102.05 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx |       3.89 |          0.00 |      19.44 |          18.47 |       0.97 |       0.00 |       0.00 |           0.00
 pg_catalog.pg_am                 |       3.89 |          3.89 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxx                  |       3.89 |          0.00 |     312.00 |         312.00 |       0.00 |       5.83 |       0.00 |           4.86
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx |       3.89 |          0.00 |       0.00 |           0.00 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxx            |       2.92 |          0.00 |     859.20 |        2773.94 |       0.00 |      22.35 |       0.00 |          22.35
 xxxxxxxxxxxxxxxxxxxxxx           |       1.94 |          0.00 |     468.48 |        1589.14 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxx            |       1.94 |          0.00 |    4131.76 |        2960.56 |       0.00 |       2.92 |       0.00 |           2.92
==================================+============+===============+============+================+============+============+============+================
...

I can also change the query, so that first column is, for example, idx_tup_fetch, to get top 10 by this column:

SELECT
    now ( ) ::TIMESTAMP ( 0 ),
    EXTRACT ( 'epoch' FROM now ( ) ),
    COUNT ( * ) OVER ( ),
    schemaname || '.' || relname AS TABLE_NAME,
    idx_tup_fetch,
    seq_scan,
    seq_tup_read,
    idx_scan,
    n_tup_ins,
    n_tup_upd,
    n_tup_del,
    n_tup_hot_upd
FROM
    pg_stat_all_tables \watch 1
 
>>> Top 10, BY idx_tup_fetch (per SECOND), FROM  2016-06-29 13:07:13 TO  2016-06-29 13:07:14:
 TABLE name:                           | idx_tup_fetch: | seq_scan:  | seq_tup_read: | idx_scan:  | n_tup_ins: | n_tup_upd: | n_tup_del: | n_tup_hot_upd:
=======================================+================+============+===============+============+============+============+============+================
 xxxxxxxxxxxxxxxxxxxxxxxx              |        7948.60 |       0.00 |          0.00 |     118.62 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxx                    |        3799.69 |       0.00 |          0.00 |    1925.47 |       0.00 |       0.00 |    1897.95 |           0.00
 xxxxxxxxxxxxxxxxxx                    |        3564.34 |       0.00 |          0.00 |    3623.18 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxx                 |        3521.64 |       0.00 |          0.00 |     919.56 |       0.95 |       0.95 |       0.00 |           0.95
 xxxxxxxxxxxxxxxxxxxxx                 |        2182.64 |       0.95 |          0.00 |     625.37 |       0.00 |      15.18 |       0.00 |          14.23
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx  |        1762.24 |       0.00 |          0.00 |    1457.62 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxx                 |        1406.38 |       0.00 |          0.00 |     316.01 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx |        1206.15 |       0.00 |          0.00 |     143.30 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxx                     |        1149.21 |       0.00 |          0.00 |    1151.11 |       0.00 |       0.00 |       0.00 |           0.00
=======================================+================+============+===============+============+============+============+============+================
 
>>> Top 10, BY idx_tup_fetch (per SECOND), FROM  2016-06-29 13:07:14 TO  2016-06-29 13:07:15:
 TABLE name:                         | idx_tup_fetch: | seq_scan:  | seq_tup_read: | idx_scan:  | n_tup_ins: | n_tup_upd: | n_tup_del: | n_tup_hot_upd:
=====================================+================+============+===============+============+============+============+============+================
 xxxxxxxxxxxxxxxxxxxxxxxx            |        4723.02 |       0.00 |          0.00 |      69.79 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxx                  |        2872.06 |       0.00 |          0.00 |    1934.15 |       0.00 |       0.96 |    1912.16 |           0.96
 xxxxxxxxxxxxxxxxxx                  |        2518.31 |       0.00 |          0.00 |    2537.43 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxxxxxx         |        2470.51 |       0.00 |          0.00 |     513.41 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxx               |        1791.69 |       0.96 |          0.00 |     638.66 |       0.00 |       7.65 |       0.00 |           7.65
 xxxxxxxxxxxxxxxxxxxxx               |        1605.25 |       0.96 |          0.00 |    2400.71 |       0.00 |       2.87 |       0.00 |           2.87
 xxxxxxxxxxxxxxxxxxxxx               |        1582.31 |       0.00 |          0.00 |     602.33 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx |        1138.69 |       0.00 |          0.00 |      51.63 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxx                   |        1111.92 |       0.00 |          0.00 |    1111.92 |       0.00 |       0.96 |       0.00 |           0.96
=====================================+================+============+===============+============+============+============+============+================
 
>>> Top 10, BY idx_tup_fetch (per SECOND), FROM  2016-06-29 13:07:15 TO  2016-06-29 13:07:16:
 TABLE name:                 | idx_tup_fetch: | seq_scan:  | seq_tup_read: | idx_scan:  | n_tup_ins: | n_tup_upd: | n_tup_del: | n_tup_hot_upd:
=============================+================+============+===============+============+============+============+============+================
 xxxxxxxxxxxxxxxxxxxxxxxx    |        4407.18 |       0.00 |          0.00 |      62.57 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxx       |        3589.86 |       0.96 |          0.00 |     983.87 |       2.89 |       5.78 |       0.00 |           4.81
 xxxxxxxxxxxxxxxxxxxxx       |        3407.91 |       0.00 |          0.00 |    2727.29 |       0.00 |      28.88 |       0.00 |          27.92
 xxxxxxxxxxxxxxxxxx          |        2889.98 |       0.00 |          0.00 |     978.09 |       0.00 |       0.00 |     962.69 |           0.00
 xxxxxxxxxxxxxxxxxx          |        2442.34 |       0.00 |          0.00 |    2476.03 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxx       |        2389.39 |       0.96 |          0.00 |     554.51 |       0.00 |       8.66 |       0.00 |           8.66
 xxxxxxxxxxxxxxxxx           |        1137.90 |       0.00 |          0.00 |    1137.90 |       0.00 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxxxxxx |        1093.61 |       0.00 |          0.00 |     333.09 |       0.00 |       0.00 |       0.00 |           0.00
 pg_toast.pg_toast_188768    |         811.54 |       0.00 |          0.00 |     204.09 |       0.00 |       0.00 |       0.00 |           0.00
=============================+================+============+===============+============+============+============+============+================
...

And if I'm worried about writes, I can introduce artificial metric that calculates “estimated" cost of writes:

SELECT
    now ( ) ::TIMESTAMP ( 0 ),
    EXTRACT ( 'epoch' FROM now ( ) ),
    COUNT ( * ) OVER ( ),
    schemaname || '.' || relname AS TABLE_NAME,
    n_tup_ins + n_tup_upd * 1.5 + n_tup_del + n_tup_hot_upd AS write_cost,
    n_tup_ins,
    n_tup_upd,
    n_tup_del,
    n_tup_hot_upd
FROM
    pg_stat_all_tables \watch 1
 
>>> Top 10, BY write_cost (per SECOND), FROM  2016-06-29 13:09:38 TO  2016-06-29 13:09:39:
 TABLE name:                   | write_cost: | n_tup_ins: | n_tup_upd: | n_tup_del: | n_tup_hot_upd:
===============================+=============+============+============+============+================
 xxxxxxxxxxxxxxxxxxxxx         |      967.02 |     967.02 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxx            |      967.02 |       0.00 |       0.00 |     967.02 |           0.00
 xxxxxxxxxxxxxxxxxxxxx         |       26.59 |       0.00 |      10.64 |       0.00 |          10.64
 xxxxxxxxxxxxxxxxx             |       16.92 |       0.00 |       6.77 |       0.00 |           6.77
 xxxxxxxxxxxxxxx               |       14.51 |       0.00 |       5.80 |       0.00 |           5.80
 xxxxxxxxxxxxxxxxxxxxxxxxxx    |       14.51 |       0.00 |       5.80 |       0.00 |           5.80
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxx |       10.15 |       0.00 |       6.77 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxx          |        9.67 |       0.00 |       3.87 |       0.00 |           3.87
 xxxxxxxxxxxxxxxxxx            |        7.74 |       0.00 |       3.87 |       0.00 |           1.93
===============================+=============+============+============+============+================
 
>>> Top 10, BY write_cost (per SECOND), FROM  2016-06-29 13:09:39 TO  2016-06-29 13:09:40:
 TABLE name:                             | write_cost: | n_tup_ins: | n_tup_upd: | n_tup_del: | n_tup_hot_upd:
=========================================+=============+============+============+============+================
 xxxxxxxxxxxxxxxxxx                      |     1945.67 |       0.00 |       0.97 |    1943.24 |           0.97
 xxxxxxxxxxxxxxxxxxxxx                   |     1943.24 |    1943.24 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx |       85.02 |       0.00 |      34.01 |       0.00 |          34.01
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxx           |       35.95 |       3.89 |      21.38 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxx                   |       30.61 |       0.00 |      12.63 |       0.00 |          11.66
 xxxxxxxxxxxxxxxxxxxxxxxxxx              |       16.03 |       0.00 |       6.80 |       0.00 |           5.83
 xxxxxxxxxxxxxxx                         |       14.57 |       0.00 |       5.83 |       0.00 |           5.83
 xxxxxxxxxxxxxxxxxxxx                    |        9.72 |       0.00 |       3.89 |       0.00 |           3.89
 xxxxxxxxxxxxxxxxxxxx                    |        9.23 |       0.00 |       4.86 |       0.00 |           1.94
=========================================+=============+============+============+============+================
 
>>> Top 10, BY write_cost (per SECOND), FROM  2016-06-29 13:09:40 TO  2016-06-29 13:09:41:
 TABLE name:                             | write_cost: | n_tup_ins: | n_tup_upd: | n_tup_del: | n_tup_hot_upd:
=========================================+=============+============+============+============+================
 xxxxxxxxxxxxxxxxxxxxx                   |      962.77 |     962.77 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxx                      |      962.77 |       0.00 |       0.00 |     962.77 |           0.00
 xxxxxxxxxxxxxxxxxxxxx                   |       37.55 |       0.00 |      15.40 |       0.00 |          14.44
 xxxxxxxxxxxxxxxxxxxxxxxxxx              |       20.70 |       0.00 |       8.66 |       0.00 |           7.70
 xxxxxxxxxxxxxxxxxxxx                    |       16.85 |       0.00 |       6.74 |       0.00 |           6.74
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxx           |       16.37 |       1.93 |       9.63 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxxxxxxxxxx              |       11.55 |      11.55 |       0.00 |       0.00 |           0.00
 xxxxxxxxxxxxxxxxxx                      |       11.07 |       1.93 |       4.81 |       0.00 |           1.93
 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx |        9.63 |       9.63 |       0.00 |       0.00 |           0.00
=========================================+=============+============+============+============+================

Aside from these tables, you can be also interested in pg_statio_all_tables, which shows specific information about how many blocks were read, or found in shared_buffers for each table, and their indexes, toast tables, and toast table indexes.

But, as you get the initial data I showed above, you should be pretty well informed about what's going on in the DB, what are “the numbers" and potential hot-spots.

Hope it helps 🙂

3 thoughts on “What’s happening in my database?”

  1. @Lesovsky:

    my problem with these tools is that I want to know where they get the data from. And when I know, it’s easier for me to just write a query, with optional one-liner for formatting, than to learn the tools.

    But, I do understand that not everybody knows all pg_stat* views, so it definitely could be useful 🙂

  2. Great info! Thanks for showing your steps in building the query in addition to the final result.

Comments are closed.