Обсуждение: Why does autovacuum run in so small blocks?
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-0921:06:35.23673+00
2011-11-09 21:07:22.312616+00 | xxx | 4184 | 1069977 | 0 | 621580 | 4184 | 0 |
2011-11-0921:06:35.23673+00
2011-11-09 21:07:42.377629+00 | xxx | 4184 | 1069977 | 0 | 621580 | 4184 | 0 |
2011-11-0921:06:35.23673+00
2011-11-09 21:08:02.491853+00 | xxx | 4184 | 1069977 | 0 | 621580 | 4184 | 0 |
2011-11-0921:06:35.23673+00
2011-11-09 21:08:22.575746+00 | xxx | 4184 | 1069977 | 0 | 621580 | 4184 | 0 |
2011-11-0921:06:35.23673+00
2011-11-09 21:08:42.641988+00 | xxx | 4184 | 1069977 | 0 | 621580 | 4184 | 0 |
2011-11-0921:06:35.23673+00
2011-11-09 21:09:02.705319+00 | xxx | 4184 | 1069977 | 0 | 621580 | 4184 | 0 |
2011-11-0921:06:35.23673+00
2011-11-09 21:09:22.769856+00 | xxx | 4184 | 1069977 | 0 | 621580 | 4184 | 0 |
2011-11-0921:06:35.23673+00
2011-11-09 21:09:42.837779+00 | xxx | 4184 | 1069977 | 0 | 621580 | 4184 | 0 |
2011-11-0921:06:35.23673+00
2011-11-09 21:10:02.903242+00 | xxx | 4184 | 1069977 | 0 | 621580 | 4184 | 0 |
2011-11-0921:06:35.23673+00
2011-11-09 21:10:23.315874+00 | xxx | 4184 | 1070484 | 0 | 621949 | 4184 | 507 |
2011-11-0921:06:35.23673+00
2011-11-09 21:10:43.38273+00 | xxx | 4184 | 1070484 | 0 | 621949 | 4184 | 507 |
2011-11-0921:10:24.161642+00
2011-11-09 21:11:03.44763+00 | xxx | 4184 | 1070484 | 0 | 621949 | 4184 | 507 |
2011-11-0921:10:24.161642+00
2011-11-09 21:11:23.51432+00 | xxx | 4184 | 1070484 | 0 | 621949 | 4184 | 0 |
2011-11-0921:11:20.879516+00
2011-11-09 21:11:43.576631+00 | xxx | 4184 | 1070484 | 0 | 621949 | 4184 | 0 |
2011-11-0921:11:20.879516+00
2011-11-09 21:12:03.643183+00 | xxx | 4184 | 1070484 | 0 | 621949 | 4184 | 0 |
2011-11-0921:11:20.879516+00
2011-11-09 21:12:23.699986+00 | xxx | 4184 | 1070484 | 0 | 621949 | 4184 | 0 |
2011-11-0921:11:20.879516+00
2011-11-09 21:12:43.762559+00 | xxx | 4184 | 1070484 | 0 | 621949 | 4184 | 0 |
2011-11-0921:11:20.879516+00
2011-11-09 21:13:03.8274+00 | xxx | 4184 | 1070484 | 0 | 621949 | 4184 | 0 |
2011-11-0921: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?
Best regards,
depesz
--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/
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/
On Wed, Nov 09, 2011 at 04:37:50PM -0500, Bill Moran wrote:
> 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.
makes perfect sense, thanks.
Best regards,
depesz
--
The best thing about modern society is how easy it is to avoid contact with it.
http://depesz.com/