On Sun, Feb 9, 2014 at 12:50 PM, Tomas Vondra <tv@xxxxxxxx> 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 -- Sent via pgsql-performance mailing list (pgsql-performance@xxxxxxxxxxxxxx) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-performance
