Re: Temporarily very slow planning time after a big delete

On Mon, May 20, 2019 at 7:15 PM David Rowley <david(dot)rowley(at)2ndquadrant(dot)com>
wrote:

> It would be good if you could confirm the problem is resolved after a
> vacuum. Maybe run VACUUM VERBOSE on the table and double check
> there's not some large amount of tuples that are "nonremovable".
>

As I say, the problem resolved itself over the next couple of hours.
Perhaps something autovacuum did? Or if the index extrema hypothesis is
correct, perhaps the new rows being inserted for various users slowly
changed that situation?

I did a VACUUM overnight and got the following. The thing that stands out
to me is that one index (index_unproc_notifications_on_notifiable_type)
took 100x longer to scan than the others. That's not the index used in the
slow query, though.

INFO: vacuuming "public.notifications"
INFO: scanned index "notifications_pkey" to remove 16596527 row versions
DETAIL: CPU 12.11s/11.04u sec elapsed 39.62 sec
INFO: scanned index "index_notifications_on_person_id_and_created_at" to
remove 16596527 row versions
DETAIL: CPU 15.86s/49.85u sec elapsed 92.07 sec
INFO: scanned index "index_unproc_notifications_on_notifiable_type" to
remove 16596527 row versions
DETAIL: CPU 224.08s/10934.81u sec elapsed 11208.37 sec
INFO: scanned index "index_notifications_on_person_id_id" to remove
16596527 row versions
DETAIL: CPU 11.58s/59.54u sec elapsed 91.40 sec
INFO: scanned index "index_notifications_on_about_id" to remove 16596527
row versions
DETAIL: CPU 11.70s/57.75u sec elapsed 87.81 sec
INFO: scanned index
"index_notifications_on_notifiable_type_and_notifiable_id" to remove
16596527 row versions
DETAIL: CPU 19.95s/70.46u sec elapsed 126.08 sec
INFO: scanned index "index_notifications_on_created_at" to remove 16596527
row versions
DETAIL: CPU 5.87s/13.07u sec elapsed 30.69 sec
INFO: "notifications": removed 16596527 row versions in 2569217 pages
DETAIL: CPU 84.77s/35.24u sec elapsed 295.30 sec
INFO: index "notifications_pkey" now contains 56704023 row versions in
930088 pages
DETAIL: 902246 index row versions were removed.
570997 index pages have been deleted, 570906 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.01 sec.
INFO: index "index_notifications_on_person_id_and_created_at" now contains
56704024 row versions in 473208 pages
DETAIL: 902246 index row versions were removed.
8765 index pages have been deleted, 8743 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "index_unproc_notifications_on_notifiable_type" now contains
56705182 row versions in 1549089 pages
DETAIL: 13354803 index row versions were removed.
934133 index pages have been deleted, 182731 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.02 sec.
INFO: index "index_notifications_on_person_id_id" now contains 56705323
row versions in 331156 pages
DETAIL: 16594039 index row versions were removed.
4786 index pages have been deleted, 1674 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.01 sec.
INFO: index "index_notifications_on_about_id" now contains 56705325 row
versions in 332666 pages
DETAIL: 16596527 index row versions were removed.
11240 index pages have been deleted, 2835 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "index_notifications_on_notifiable_type_and_notifiable_id" now
contains 56705325 row versions in 666755 pages
DETAIL: 16596527 index row versions were removed.
52936 index pages have been deleted, 2693 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: index "index_notifications_on_created_at" now contains 56705331 row
versions in 196271 pages
DETAIL: 14874162 index row versions were removed.
37884 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO: "notifications": found 890395 removable, 56698057 nonremovable row
versions in 2797452 out of 2799880 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 29497175 unused item pointers.
Skipped 0 pages due to buffer pins.
0 pages are entirely empty.
CPU 452.97s/11252.42u sec elapsed 12186.90 sec.
INFO: vacuuming "pg_toast.pg_toast_27436"
INFO: index "pg_toast_27436_index" now contains 72 row versions in 2 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_27436": found 0 removable, 2 nonremovable row versions in
1 out of 36 pages
DETAIL: 0 dead row versions cannot be removed yet.
There were 3 unused item pointers.
Skipped 0 pages due to buffer pins.
0 pages are entirely empty.
CPU 0.00s/0.00u sec elapsed 0.00 sec.

Thanks,
Walter