Why does vacuum full wait after it is "done"?

Question

I am running a vacuum on a very large table.

When I run it, it says:

bacula=# VACUUM FULL VERBOSE file_partition_19
bacula-# ;
INFO:  vacuuming "public.file_partition_19"
INFO:  "file_partition_19": found 16242451 removable, 21024161 nonremovable row versions in 900380 pages
DETAIL:  0 dead row versions cannot be removed yet.
CPU 5.14s/14.42u sec elapsed 19.61 sec.
VACUUM
Time: 163784.767 ms
bacula=# 

When it does this, it shows up to the CPU line fairly quickly, then waits a long time before it shows the final two lines (+ the prompt). This is reflected in the difference in time - "elapsed 19.61 sec", compared to to the "Time:" of 163 seconds (shown because I set \timing on).

While I haven't timed them, both times are about right - start the command, wait 20 seconds, it then shows up to the "CPU" line, then waits about 3 minutes, then prints the rest.

Is this normal? Why is it happening?

Answer 1

It's mostly rebuilding all indizes on the table, which it has to do since basically "VACUUM FULL" does a full rewrite of the table. If you remove all indizes from your table, there should be almost no delay after the "CPU" line.

AFAICT, the CPU usage line is printed by a generic routine that does most of the work for other (non-FULL) vacuum modes. It is meaningless in the "VACUUM FULL" case.

If you are concerned that it takes too long, I recommend that you have a look at the "When to use VACUUM FULL and when not to" from the PostgreSQL wiki. 9 times out of 10 when people are using VACUUM FULL they actually shouldn't.

Answer 2

Based on the tag "postgres-9.3" you used for your question I am assuming that you have Postgres 9.3 version.

you can refer this link just for your own knowledge about "VACUUM" and "VACUUM FULL" for the pre-9.0 versions of Postgres.

VACUUM VS VACUUM FULL For Pre-9.0 versions of Postgres

So as you have Postgres-9.3, the documentation says following:

For clarity, 9.0 changes VACUUM FULL. As covered in the documentation, the VACUUM FULL implementation has been changed to one that's similar to using CLUSTER in older versions. This gives a slightly different set of trade-offs from the older VACUUM FULL described here. While the potential to make the database slower via index bloating had been removed by this change, it's still something you may want to avoid doing, due to the locking and general performance overhead of a VACUUM FULL.

As per the current documentation, VACUUM FULL operation not only retrieves the space from the table where records are marked deleted but it also touches every valid record in the table and tries to reorganize them in DB pages so that's how it frees up more space then just VACUUM operation. So in the VERBOS result when we see the line

CPU 5.14s/14.42u sec elapsed 19.61 sec

it is the time taken by system process to go through the table and analyze the table and retrieve the space that is already marked. Then it starts the organizing the records into page file and hence depending on how much table pages are fragmented the process will take time.

For example, if you have a new table and keep adding new records incrementally/sequentially so that new records gets added at the bottom of the page (based on the primary key defined). Now you perform delete operation in a reverse order so that records only gets deleted from the bottom of the page. Let's say you delete half of the records from the table. In this situation, there is no much page fragmentation(virtually 0) and hence when VACUMME FULL runs the second phase, it will still try to organize the valid records but because there is no fragmentation and hence it will not have to actually move any records and will finish faster.

But, above explain situation is not the way update/delete happens in real world. Real word Update/Delete on table create lots of page fragmentation and hence during the second phase VACUUM FULL process has to actually move valid records into free space at the beginning of each page and hence takes more time.

check the following sample output,

I ran for very small dummy table. even though It has only 7 rows. VACUME PROCESS (First Phase) finishes in 0.03sec(30ms) but total query reported to finish in 61ms. So that tells me even though there is nothing to reorganize the process still checks how much if it can be reorganized and hence takes time. But if I have actually lots of fragmentation and reorganize happens then it would be much more completion time depending on page fragmentation.