Thread: Vacuuming problems on TOAST table

Vacuuming problems on TOAST table

From
Ofer Israeli
Date:
Hi all,
 
We have a 4-columned table that is also split up into a TOAST table, where the TOASTed entries are ~35KB each. 
The table size is 10K records.
The table is updated at a rate of ~100 updates a minute.
 
During our testing we see that the table size increases substantially.  When looking at the autovacuum log, set with default configuration, it seems that it ran for around 60 seconds (see below and note that this was a 1-minute test, i.e. only 100 updates)!
 
pid:2148 tid:0 sid:4f32a8de.864 sln:2 sst:2012-02-08 18:54:54 IST [2012-02-08 19:24:06.967 IST]DEBUG:  autovac_balance_cost(pid=4560 db=16385, rel=17881, cost_limit=200, cost_delay=20)
pid:2148 tid:0 sid:4f32a8de.864 sln:3 sst:2012-02-08 18:54:54 IST [2012-02-08 19:24:37.622 IST]DEBUG:  autovac_balance_cost(pid=4560 db=16385, rel=17881, cost_limit=200, cost_delay=20)
pid:4560 tid:0 sid:4f32af99.11d0 sln:14 sst:2012-02-08 19:23:37 IST [2012-02-08 19:24:43.518 IST]DEBUG:  scanned index "pg_toast_17881_index" to remove 1700 row versions
pid:4560 tid:0 sid:4f32af99.11d0 sln:15 sst:2012-02-08 19:23:37 IST [2012-02-08 19:24:43.518 IST]DETAIL:  CPU 0.00s/0.00u sec elapsed 0.74 sec.
pid:4560 tid:0 sid:4f32af99.11d0 sln:16 sst:2012-02-08 19:23:37 IST [2012-02-08 19:24:43.581 IST]DEBUG:  "pg_toast_17881": removed 1700 row versions in 494 pages
pid:4560 tid:0 sid:4f32af99.11d0 sln:17 sst:2012-02-08 19:23:37 IST [2012-02-08 19:24:43.581 IST]DETAIL:  CPU 0.00s/0.00u sec elapsed 0.06 sec.
pid:4560 tid:0 sid:4f32af99.11d0 sln:18 sst:2012-02-08 19:23:37 IST [2012-02-08 19:24:43.581 IST]DEBUG:  index "pg_toast_17881_index" now contains 169983 row versions in 473 pages
pid:4560 tid:0 sid:4f32af99.11d0 sln:19 sst:2012-02-08 19:23:37 IST [2012-02-08 19:24:43.581 IST]DETAIL:  1700 index row versions were removed.
 4 index pages have been deleted, 0 are currently reusable.
 CPU 0.00s/0.00u sec elapsed 0.00 sec.
pid:4560 tid:0 sid:4f32af99.11d0 sln:20 sst:2012-02-08 19:23:37 IST [2012-02-08 19:24:43.581 IST]DEBUG:  "pg_toast_17881": found 1471 removable, 169983 nonremovable row versions in 42921 pages
pid:4560 tid:0 sid:4f32af99.11d0 sln:21 sst:2012-02-08 19:23:37 IST [2012-02-08 19:24:43.581 IST]DETAIL:  0 dead row versions cannot be removed yet.
 There were 0 unused item pointers.
 495 pages contain useful free space.
 0 pages are entirely empty.
 CPU 0.00s/0.00u sec elapsed 66.36 sec.
pid:4560 tid:0 sid:4f32af99.11d0 sln:22 sst:2012-02-08 19:23:37 IST [2012-02-08 19:24:43.581 IST]LOG:  automatic vacuum of table "uepm.pg_toast.pg_toast_17881": index scans: 1
 pages: 0 removed, 42921 remain
 tuples: 1471 removed, 169983 remain
 system usage: CPU 0.00s/0.00u sec elapsed 66.36 sec
 
When setting a higher cost for the autovacuum, tried values of 2000, it ran for even longer: ~400 seconds!
 
 
The only other information that I have here is that the TOASTed data is split up into 17 sections (which makes sense considering it splits it up into 2KB sections).
 
And one more thing that seems a bit strange - after a 1-minute run, we would expect to see 1700 Tuples Updated (100*17), but instead we see 1700 Tuples Inserted (and no deletes).
 
 
Anyone have a clue on this phenomenon?
 
 
Thanks,
Ofer

Re: Vacuuming problems on TOAST table

From
Tom Lane
Date:
Ofer Israeli <oferi@checkpoint.com> writes:
> During our testing we see that the table size increases substantially.  When looking at the autovacuum log, set with
defaultconfiguration, it seems that it ran for around 60 seconds (see below and note that this was a 1-minute test,
i.e.only 100 updates)! 

autovacuum is intended to run fairly slowly, so as to not consume too
much resources.  If you think it's too slow you can adjust the
autovacuum_cost tunables.

> When setting a higher cost for the autovacuum, tried values of 2000, it ran for even longer: ~400 seconds!

That's the wrong direction, no?

            regards, tom lane

Re: Vacuuming problems on TOAST table

From
Ofer Israeli
Date:
Tom Lane wrote:
> Ofer Israeli <oferi@checkpoint.com> writes:
>> During our testing we see that the table size increases
>> substantially.  When looking at the autovacuum log, set with default
>> configuration, it seems that it ran for around 60 seconds (see below
>> and note that this was a 1-minute test, i.e. only 100 updates)!
>
> autovacuum is intended to run fairly slowly, so as to not consume too
> much resources.  If you think it's too slow you can adjust the
> autovacuum_cost tunables.
>
>> When setting a higher cost for the autovacuum, tried values of 2000,
>> it ran for even longer: ~400 seconds!
>
> That's the wrong direction, no?

The settings we used were not in the postgresql.conf file, but rather an update of the pg_autovacuum table where we set
thevac_cost_limit to 2000.  The reason for this being that we wanted this definition only for the big (TOASTed) table I
wasreferring to. 

The logged settings in the ~400 second case were:
autovac_balance_cost(pid=6224 db=16385, rel=17881, cost_limit=10, cost_delay=1)

Which comes as quite a surprise as it seems that the cost_limit is not set or am I missing something?


Thanks,
Ofer


Re: Vacuuming problems on TOAST table

From
Robert Haas
Date:
On Wed, Feb 8, 2012 at 2:59 PM, Ofer Israeli <oferi@checkpoint.com> wrote:
> The settings we used were not in the postgresql.conf file, but rather an update of the pg_autovacuum table where we
setthe vac_cost_limit to 2000.  The reason for this being that we wanted this definition only for the big (TOASTed)
tableI was referring to. 
>
> The logged settings in the ~400 second case were:
> autovac_balance_cost(pid=6224 db=16385, rel=17881, cost_limit=10, cost_delay=1)
>
> Which comes as quite a surprise as it seems that the cost_limit is not set or am I missing something?

That doesn't look right, but without step-by-step directions it will
be hard for anyone to reproduce this.  Also, what version are you
testing on?  pg_autovacuum was removed in PostgreSQL 8.4, so you must
be using PostgreSQL 8.3 or earlier.

You might at least want to make sure you're running a late enough
minor version to have this fix:

Author: Tom Lane <tgl@sss.pgh.pa.us>
Branch: master Release: REL9_1_BR [b58c25055] 2010-11-19 22:29:44 -0500
Branch: REL9_0_STABLE Release: REL9_0_2 [b5efc0940] 2010-11-19 22:28:25 -0500
Branch: REL8_4_STABLE Release: REL8_4_6 [fab2af30d] 2010-11-19 22:28:30 -0500
Branch: REL8_3_STABLE Release: REL8_3_13 [6cb9d5113] 2010-11-19 22:28:35 -0500

    Fix leakage of cost_limit when multiple autovacuum workers are active.

    When using default autovacuum_vac_cost_limit, autovac_balance_cost relied
    on VacuumCostLimit to contain the correct global value ... but after the
    first time through in a particular worker process, it didn't, because we'd
    trashed it in previous iterations.  Depending on the state of other autovac
    workers, this could result in a steady reduction of the effective
    cost_limit setting as a particular worker processed more and more tables,
    causing it to go slower and slower.  Spotted by Simon Poole (bug #5759).
    Fix by saving and restoring the GUC variables in the loop in do_autovacuum.

    In passing, improve a few comments.

    Back-patch to 8.3 ... the cost rebalancing code has been buggy since it was
    put in.

Also:

> And one more thing that seems a bit strange - after a 1-minute run, we would
> expect to see 1700 Tuples Updated (100*17), but instead we see 1700 Tuples
> Inserted (and no deletes).

I don't think TOAST ever updates chunks in place.  It just inserts and
deletes; or at least I think that's what it does.

--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company