March 9th, 2016 by depesz | Tags: , , , | No comments »
Did it help? If yes - maybe you can help me?

On 9th of March, Robert Haas committed patch:

Add a generic command progress reporting facility.
 
Using this facility, any utility command can report the target relation
upon which it is operating, if there is one, and up to 10 64-bit
counters; the intent of this is that users should be able to figure out
what a utility command is doing without having to resort to ugly hacks
like attaching strace to a backend.
 
As a demonstration, this adds very crude reporting to lazy vacuum; we
just report the target relation and nothing else.  A forthcoming patch
will make VACUUM report a bunch of additional data that will make this
much more interesting.  But this gets the basic framework in place.
 
Vinayak Pokale, Rahila Syed, Amit Langote, Robert Haas, reviewed by
Kyotaro Horiguchi, Jim Nasby, Thom Brown, Masahiko Sawada, Fujii Masao,
and Masanori Oyama.

This will be very cool. Now, it's just a nice thing to have, but thanks to this patch, we will (hopefully) get progress information from variety of commands, like vacuums, copy, create index, and so on.

Basically, it provides a framework for any command to provide progress information that you can query separately, from another pg session.

Currently, it merely reports table being currently vacuumed, when you're running vacuum (not vacuum full though).

How does it work?

First, let's create some test tables:

$ seq 1 20 | sed "s/.*/create table t& as select i, repeat('depesz', 100) as payload from generate_series(1,1000000) i;/" | psql -e

This created 20 tables: t1-t20, each with 1 million rows.

Now, I'll run vacuum in one session, and also, every 0.5s will run this query:

$ select now(), relid::regclass, * from pg_stat_get_progress_info('VACUUM');

This is new system function that returns information on progresses.

So, I ran, in psql session:

\timing
vacuum;

and, in the same time, on another console, I ran:

$ while true; do psql -c "select now(), relid::regclass, * from pg_stat_get_progress_info('VACUUM')"; sleep 0.5; done

And it showed (among other lines):

...
              now              | relid | pid  | datid | relid | param1 | param2 | param3 | param4 | param5 | param6 | param7 | param8 | param9 | param10 
-------------------------------+-------+------+-------+-------+--------+--------+--------+--------+--------+--------+--------+--------+--------+---------
 2016-03-09 19:41:07.758661+01 | t19   | 7977 | 16386 | 16736 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |       0
(1 row)
 
              now              | relid | pid  | datid | relid | param1 | param2 | param3 | param4 | param5 | param6 | param7 | param8 | param9 | param10 
-------------------------------+-------+------+-------+-------+--------+--------+--------+--------+--------+--------+--------+--------+--------+---------
 2016-03-09 19:41:08.267304+01 | t19   | 7977 | 16386 | 16736 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |       0
(1 row)
 
              now              | relid | pid  | datid | relid | param1 | param2 | param3 | param4 | param5 | param6 | param7 | param8 | param9 | param10 
-------------------------------+-------+------+-------+-------+--------+--------+--------+--------+--------+--------+--------+--------+--------+---------
 2016-03-09 19:41:08.773858+01 | t20   | 7977 | 16386 | 16742 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |       0
(1 row)
 
             now              | relid | pid  | datid | relid | param1 | param2 | param3 | param4 | param5 | param6 | param7 | param8 | param9 | param10 
------------------------------+-------+------+-------+-------+--------+--------+--------+--------+--------+--------+--------+--------+--------+---------
 2016-03-09 19:41:09.28681+01 | t20   | 7977 | 16386 | 16742 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |       0
(1 row)
...
              now              |     relid     | pid  | datid | relid | param1 | param2 | param3 | param4 | param5 | param6 | param7 | param8 | param9 | param10 
-------------------------------+---------------+------+-------+-------+--------+--------+--------+--------+--------+--------+--------+--------+--------+---------
 2016-03-09 19:41:17.434411+01 | pg_constraint | 7977 | 16386 |  2606 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |       0
(1 row)
 
             now              |    relid     | pid  | datid | relid | param1 | param2 | param3 | param4 | param5 | param6 | param7 | param8 | param9 | param10 
------------------------------+--------------+------+-------+-------+--------+--------+--------+--------+--------+--------+--------+--------+--------+---------
 2016-03-09 19:41:18.05066+01 | pg_aggregate | 7977 | 16386 |  2600 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |       0
(1 row)
 
              now              |   relid    | pid  | datid | relid | param1 | param2 | param3 | param4 | param5 | param6 | param7 | param8 | param9 | param10 
-------------------------------+------------+------+-------+-------+--------+--------+--------+--------+--------+--------+--------+--------+--------+---------
 2016-03-09 19:41:18.556741+01 | pg_rewrite | 7977 | 16386 |  2618 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |      0 |       0
(1 row)
...

Pretty cool, I have to admit. It would be better to have more information (total number of pages across all tables, pages-already-vacuumed), but this is just first, initial progress information, and it looks very, very promising.

Thanks a lot to all involved.

Leave a comment