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
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
