Re: Bloated tables and why is vacuum full the only option

On Sun, Feb 9, 2014 at 12:50 PM, Tomas Vondra <tv(at)fuzzy(dot)cz> wrote:
> Also, when you're running the weekly VACUUM, do VACUUM (VERBOSE) and
> post it here. That might at least help us eliminate some of the usual
> suspects.

I have the full dump if relevant. The relevant extract for:

Report:
1. public.full_bid_logs
2551219 of 4417505 pages wasted (57.8%), 19 GB of 34 GB.
2. public.non_bid_logs
814076 of 1441728 pages wasted (56.5%), 6360 MB of 11 GB.
3. public.click_logs
631630 of 2252999 pages wasted (28.0%), 4935 MB of 17 GB.
4. public.full_impression_logs
282298 of 762238 pages wasted (37.0%), 2205 MB of 5955 MB.

Most of which appear on the log regarding cancelled autovacuums (on
Wednesday, which suggests it's because of the manual vacuum itself
since they run on Wednesdays):

/media/data/pgsql9/data/pg_log/postgresql-Wed.log:LOG: sending cancel
to blocking autovacuum PID 30000
/media/data/pgsql9/data/pg_log/postgresql-Wed.log:ERROR: canceling
autovacuum task
/media/data/pgsql9/data/pg_log/postgresql-Wed.log:CONTEXT: automatic
vacuum of table "mat.public.aggregated_tracks_hourly_full"
/media/data/pgsql9/data/pg_log/postgresql-Wed.log:LOG: sending cancel
to blocking autovacuum PID 30000
/media/data/pgsql9/data/pg_log/postgresql-Wed.log:ERROR: canceling
autovacuum task
/media/data/pgsql9/data/pg_log/postgresql-Wed.log:CONTEXT: automatic
vacuum of table "mat.public.bid_logs"
/media/data/pgsql9/data/pg_log/postgresql-Wed.log:LOG: sending cancel
to blocking autovacuum PID 30000
/media/data/pgsql9/data/pg_log/postgresql-Wed.log:ERROR: canceling
autovacuum task
/media/data/pgsql9/data/pg_log/postgresql-Wed.log:CONTEXT: automatic
vacuum of table "mat.public.full_impression_logs"
/media/data/pgsql9/data/pg_log/postgresql-Wed.log:LOG: sending cancel
to blocking autovacuum PID 30000
/media/data/pgsql9/data/pg_log/postgresql-Wed.log:ERROR: canceling
autovacuum task
/media/data/pgsql9/data/pg_log/postgresql-Wed.log:CONTEXT: automatic
vacuum of table "mat.public.non_bid_logs"

Note: the bid_logs one up there was the one I vacuumed full, so that's
why it's not showing on pg bloat report.

(manual) Vacuum verbose follows:

...
INFO: vacuuming "public.full_bid_logs"
INFO: scanned index "full_bid_logs_pkey" to remove 11416990 row versions
DETAIL: CPU 16.49s/133.42u sec elapsed 2660.01 sec.
INFO: "full_bid_logs": removed 11416990 row versions in 171209 pages
DETAIL: CPU 5.28s/5.18u sec elapsed 610.86 sec.
INFO: index "full_bid_logs_pkey" now contains 267583488 row versions
in 2207958 pages
DETAIL: 10206852 index row versions were removed.
3852 index pages have been deleted, 3010 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.04 sec.
INFO: "full_bid_logs": found 4625843 removable, 29252597 nonremovable
row versions in 402582 out of 4417505 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 2408853 unused item pointers.
0 pages are entirely empty.
CPU 30.10s/145.42u sec elapsed 4317.03 sec.
INFO: analyzing "public.full_bid_logs"
INFO: "full_bid_logs": scanned 30000 of 4417505 pages, containing
1802104 live rows and 0 dead rows; 30000 rows in sample, 211394515
estimated total rows
...
INFO: vacuuming "public.non_bid_logs"
INFO: scanned index "non_bid_logs_pkey" to remove 10137502 row versions
DETAIL: CPU 1.55s/23.23u sec elapsed 325.36 sec.
INFO: scanned index "non_bid_logs_created_idx" to remove 10137502 row versions
DETAIL: CPU 1.60s/23.40u sec elapsed 332.35 sec.
INFO: "non_bid_logs": removed 10137502 row versions in 116848 pages
DETAIL: CPU 3.60s/1.36u sec elapsed 403.18 sec.
INFO: index "non_bid_logs_pkey" now contains 41372799 row versions in
176455 pages
DETAIL: 10106519 index row versions were removed.
29944 index pages have been deleted, 11887 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "non_bid_logs_created_idx" now contains 41384156 row
versions in 184580 pages
DETAIL: 10137502 index row versions were removed.
45754 index pages have been deleted, 18310 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: "non_bid_logs": found 1378107 removable, 4283511 nonremovable
row versions in 163702 out of 1451616 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 1345761 unused item pointers.
0 pages are entirely empty.
CPU 9.28s/49.42u sec elapsed 1378.98 sec.
INFO: "non_bid_logs": suspending truncate due to conflicting lock request
INFO: "non_bid_logs": truncated 1451616 to 1441728 pages
DETAIL: CPU 0.18s/0.20u sec elapsed 6.98 sec.
INFO: "non_bid_logs": stopping truncate due to conflicting lock request
INFO: analyzing "public.non_bid_logs"
INFO: "non_bid_logs": scanned 30000 of 1441728 pages, containing
874070 live rows and 0 dead rows; 30000 rows in sample, 47720462
estimated total rows
...
INFO: vacuuming "public.click_logs"
INFO: scanned index "click_logs_pkey" to remove 9594881 row versions
DETAIL: CPU 7.34s/67.36u sec elapsed 1194.09 sec.
INFO: "click_logs": removed 9594881 row versions in 135032 pages
DETAIL: CPU 4.36s/2.06u sec elapsed 485.08 sec.
INFO: index "click_logs_pkey" now contains 155456958 row versions in
968791 pages
DETAIL: 9579492 index row versions were removed.
2283 index pages have been deleted, 1008 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.63 sec.
INFO: "click_logs": found 5502098 removable, 24781508 nonremovable
row versions in 398918 out of 2252999 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 1447127 unused item pointers.
0 pages are entirely empty.
CPU 20.54s/74.54u sec elapsed 2796.24 sec.
INFO: "click_logs": stopping truncate due to conflicting lock request
INFO: vacuuming "pg_toast.pg_toast_16563"
INFO: index "pg_toast_16563_index" now contains 0 row versions in 1 pages
DETAIL: 0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: "pg_toast_16563": found 0 removable, 0 nonremovable row
versions in 0 out of 0 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 0 unused item pointers.
0 pages are entirely empty.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: analyzing "public.click_logs"
INFO: "click_logs": scanned 30000 of 2252999 pages, containing
2057564 live rows and 0 dead rows; 30000 rows in sample, 113618340
estimated total rows
...
INFO: vacuuming "public.full_impression_logs"
INFO: scanned index "full_impression_logs_pkey" to remove 4982049 row versions
DETAIL: CPU 4.50s/27.49u sec elapsed 658.99 sec.
INFO: "full_impression_logs": removed 4982049 row versions in 45983 pages
DETAIL: CPU 1.41s/1.00u sec elapsed 168.53 sec.
INFO: index "full_impression_logs_pkey" now contains 61634251 row
versions in 531050 pages
DETAIL: 759542 index row versions were removed.
29 index pages have been deleted, 29 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.01 sec.
INFO: "full_impression_logs": found 0 removable, 758433 nonremovable
row versions in 48383 out of 763267 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 20689 unused item pointers.
0 pages are entirely empty.
CPU 6.40s/28.80u sec elapsed 879.32 sec.
INFO: "full_impression_logs": truncated 763267 to 762238 pages
DETAIL: CPU 0.00s/0.00u sec elapsed 0.05 sec.
INFO: analyzing "public.full_impression_logs"
INFO: "full_impression_logs": scanned 30000 of 762238 pages,
containing 2415147 live rows and 0 dead rows; 30000 rows in sample,
41836806 estimated total rows