Vacuuming problems on TOAST table - Mailing list pgsql-performance
| From | Ofer Israeli |
|---|---|
| Subject | Vacuuming problems on TOAST table |
| Date | |
| Msg-id | 217DDBC2BB1E394CA9E7446337CBDEF20102C056BFBE@il-ex01.ad.checkpoint.com Whole thread Raw |
| Responses |
Re: Vacuuming problems on TOAST table
(Tom Lane <tgl@sss.pgh.pa.us>)
|
| List | pgsql-performance |
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
pgsql-performance by date: