Re: Unusually high IO for autovacuum worker

On Fri, Feb 1, 2013 at 1:08 PM, Pavan Deolasee <pavan(dot)deolasee(at)gmail(dot)com>wrote:

>
>
> On Fri, Feb 1, 2013 at 3:24 PM, Vlad Bailescu <vlad(at)mojitosoftware(dot)com>wrote:
>
>>
>>
>> Stats show only 3 tables get frequently autovacuumed
>>
>> Table Name Tuples inserted Tuples updated Tuples deleted Tuples HOT
>> updated Live Tuples Dead Tuples Last vacuum Last autovacuum Last analyze Last
>> autoanalyze Vacuum counter Autovacuum counter Analyze counter Autoanalyze
>> counter Size vehicle_position 4689127 0 4689127 0 0 1985
>> 2013-02-01 11:46:46.441227+02 2013-01-31 14:48:00.775864+02 2013-02-01
>> 11:46:46.494234+02 0 3761 1 3754 4016 kB vehicle 2124 934640 0 924003
>> 2124 390
>> 2013-02-01 11:47:46.067695+02 2013-02-01 11:47:46.325444+02 0 1293 0 2038 2448
>> kB input_current 10032 1649206 0 1635902 10032 1728
>> 2013-02-01 11:45:46.0681+02 2013-02-01 11:45:46.215048+02 0 442 0 1294 2336
>> kB
>>
>
> So sure there are more than just one table involved here. Also, the last
> column in the
> output above shows that these are fairly large tables. In fact, if the
> last column is to be
> trusted, they are as large 37GB, 20GB and 12GB respectively. Note the kB
> at the end of
> those values. Also given the large number of inserts/deletes, I would
> doubt if the table can
> really remain that small. May be auto-vacuum is truncating most of it and
> thats why you
> see only a few MBs before it swells again by the time next vacuum cycles
> runs.
>
> Whats your rate of insertion/deletion in the first table ? You also seem
> to be updating the
> last two tables quite heavily, but most of them are HOT updates, so your
> tables should not
> bloat too much.
>
> Thanks,
> Pavan
>
> --
> Pavan Deolasee
> http://www.linkedin.com/in/pavandeolasee
>

Pavan, it seems there's a small issue with copy-paste and column
text-align. Table sizes are:

4136 kB 2448 kB 2336 kB
The actual partition tables are very large (ie: vehicle_position_y2013_m01
is 6448 MB), but they don't seem to receive so much attention.

The vehicle table gets updated very often because it has a foreign key to
vehicle_position and that changes with every batch of data.

We were able to reproduce this on a test VM with minimum workload to
trigger autovacuum. Here's the relevant log portion:

2012-12-05 00:32:57 EET LOG: database system is ready to accept connections
2012-12-05 00:32:57 EET LOG: autovacuum launcher started
2012-12-05 00:36:38 EET LOG: automatic analyze of table
"fleet.fleet.vehicle_position" system usage: CPU 0.00s/0.00u sec elapsed
0.03 sec
2012-12-05 00:37:39 EET LOG: automatic analyze of table
"fleet.fleet.vehicle_position_default" system usage: CPU 0.00s/0.15u sec
elapsed 0.99 sec
2012-12-05 00:44:23 EET LOG: automatic analyze of table
"fleet.fleet.vehicle_position" system usage: CPU 4.46s/0.61u sec elapsed
465.09 sec
2012-12-05 00:44:38 EET LOG: automatic vacuum of table
"fleet.fleet.vehicle_position": index scans: 1
pages: 8 removed, 0 remain
tuples: 64 removed, 0 remain
system usage: CPU 0.00s/0.00u sec elapsed 0.02 sec
2012-12-05 00:44:38 EET LOG: automatic analyze of table
"fleet.fleet.vehicle_position" system usage: CPU 0.00s/0.00u sec elapsed
0.00 sec
2012-12-05 00:51:40 EET LOG: automatic analyze of table
"fleet.fleet.vehicle_position" system usage: CPU 4.34s/0.53u sec elapsed
422.20 sec
2012-12-05 00:52:38 EET LOG: automatic vacuum of table
"fleet.fleet.vehicle_position": index scans: 1
pages: 10 removed, 0 remain
tuples: 30 removed, 0 remain
system usage: CPU 0.00s/0.00u sec elapsed 0.02 sec
2012-12-05 00:52:38 EET LOG: automatic analyze of table
"fleet.fleet.vehicle_position" system usage: CPU 0.00s/0.00u sec elapsed
0.00 sec

During the analyze the IO was ~800-1000 K/s

Vlad