Re: Why does autovacuum run in so small blocks?

In response to hubert depesz lubaczewski <depesz@depesz.com>:

> hi,
> I have strange situation with one table.
>
> base info: pg 8.4.8
>
> here is info from pg_stat_all_tables about i:
>               now              | relid | n_tup_ins | n_tup_upd | n_tup_del | n_tup_hot_upd | n_live_tup | n_dead_tup
|      last_autovacuum 
>
-------------------------------+-------+-----------+-----------+-----------+---------------+------------+------------+------------------------------
>  2011-11-09 21:07:02.250232+00 | xxx   |      4184 |   1069977 |         0 |        621580 |       4184 |          0
|2011-11-09 21:06:35.23673+00 
>  2011-11-09 21:07:22.312616+00 | xxx   |      4184 |   1069977 |         0 |        621580 |       4184 |          0
|2011-11-09 21:06:35.23673+00 
>  2011-11-09 21:07:42.377629+00 | xxx   |      4184 |   1069977 |         0 |        621580 |       4184 |          0
|2011-11-09 21:06:35.23673+00 
>  2011-11-09 21:08:02.491853+00 | xxx   |      4184 |   1069977 |         0 |        621580 |       4184 |          0
|2011-11-09 21:06:35.23673+00 
>  2011-11-09 21:08:22.575746+00 | xxx   |      4184 |   1069977 |         0 |        621580 |       4184 |          0
|2011-11-09 21:06:35.23673+00 
>  2011-11-09 21:08:42.641988+00 | xxx   |      4184 |   1069977 |         0 |        621580 |       4184 |          0
|2011-11-09 21:06:35.23673+00 
>  2011-11-09 21:09:02.705319+00 | xxx   |      4184 |   1069977 |         0 |        621580 |       4184 |          0
|2011-11-09 21:06:35.23673+00 
>  2011-11-09 21:09:22.769856+00 | xxx   |      4184 |   1069977 |         0 |        621580 |       4184 |          0
|2011-11-09 21:06:35.23673+00 
>  2011-11-09 21:09:42.837779+00 | xxx   |      4184 |   1069977 |         0 |        621580 |       4184 |          0
|2011-11-09 21:06:35.23673+00 
>  2011-11-09 21:10:02.903242+00 | xxx   |      4184 |   1069977 |         0 |        621580 |       4184 |          0
|2011-11-09 21:06:35.23673+00 
>  2011-11-09 21:10:23.315874+00 | xxx   |      4184 |   1070484 |         0 |        621949 |       4184 |        507
|2011-11-09 21:06:35.23673+00 
>  2011-11-09 21:10:43.38273+00  | xxx   |      4184 |   1070484 |         0 |        621949 |       4184 |        507
|2011-11-09 21:10:24.161642+00 
>  2011-11-09 21:11:03.44763+00  | xxx   |      4184 |   1070484 |         0 |        621949 |       4184 |        507
|2011-11-09 21:10:24.161642+00 
>  2011-11-09 21:11:23.51432+00  | xxx   |      4184 |   1070484 |         0 |        621949 |       4184 |          0
|2011-11-09 21:11:20.879516+00 
>  2011-11-09 21:11:43.576631+00 | xxx   |      4184 |   1070484 |         0 |        621949 |       4184 |          0
|2011-11-09 21:11:20.879516+00 
>  2011-11-09 21:12:03.643183+00 | xxx   |      4184 |   1070484 |         0 |        621949 |       4184 |          0
|2011-11-09 21:11:20.879516+00 
>  2011-11-09 21:12:23.699986+00 | xxx   |      4184 |   1070484 |         0 |        621949 |       4184 |          0
|2011-11-09 21:11:20.879516+00 
>  2011-11-09 21:12:43.762559+00 | xxx   |      4184 |   1070484 |         0 |        621949 |       4184 |          0
|2011-11-09 21:11:20.879516+00 
>  2011-11-09 21:13:03.8274+00   | xxx   |      4184 |   1070484 |         0 |        621949 |       4184 |          0
|2011-11-09 21:11:20.879516+00 
>
> as you can see within ~ 5 minutes, there were no inserts, just some updates.
> Which explains (kind of) the autovacuum at 21:10:24.161642+00
> but why was there another one at 21:11:20.879516+00?
>
> In logs I see:
>
> 2011-11-09 21:06:35.236 GMT::@:[6957]:LOG:  automatic vacuum of table "public.xxx": index scans: 1
>         pages: 0 removed, 1094 remain
>         tuples: 704 removed, 2990 remain
>         system usage: CPU 0.00s/0.01u sec elapsed 0.10 sec
> --
> 2011-11-09 21:10:24.161 GMT::@:[8161]:LOG:  automatic vacuum of table "public.xxx": index scans: 0
>         pages: 0 removed, 1094 remain
>         tuples: 0 removed, 3516 remain
>         system usage: CPU 0.00s/0.00u sec elapsed 0.05 sec
> --
> 2011-11-09 21:11:20.879 GMT::@:[8467]:LOG:  automatic vacuum of table "public.xxx": index scans: 1
>         pages: 0 removed, 1094 remain
>         tuples: 507 removed, 2938 remain
>         system usage: CPU 0.00s/0.01u sec elapsed 0.01 sec
>
> the question basically is - why do we have so many vacuums?
> especially the ones that don't do anything?

My guess would be that the vacuum was triggered by updates, but there were
active transactions that prevented vacuum from cleaning up the dead tuples,
so it came back later and was able to clean them up at that time.

Would need to do a little more in-depth research/monitoring to determine
if that guess is correct or not.

--
Bill Moran
http://www.potentialtech.com
http://people.collaborativefusion.com/~wmoran/