[Pgpool-general] one of backends kicked after "VACUUM ANALYZE"

Wed May 11 22:21:25 UTC 2011

I removed a large number of records from a table (~38 mln out of ~40 mln), after which I've started "VACUUM VERBOSE ANALYZE my_table".

Near the very end, pgpool kicked one of the backends - is it expected? Please advise. I'm running pgpool-3.0.3.

(...)
INFO:  index "core_extevent_protocol_id" now contains 1549814 row versions in 152408 pages
DETAIL:  39686783 index row versions were removed.
146917 index pages have been deleted, 8965 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  "core_extevent": found 443485 removable, 1549814 nonremovable row versions in 2707895 pages
DETAIL:  0 dead row versions cannot be removed yet.
There were 39320666 unused item pointers.
2649435 pages contain useful free space.
0 pages are entirely empty.
CPU 101.70s/236.60u sec elapsed 3381.22 sec.
WARNING:  relation "public.core_extevent" contains more than "max_fsm_pages" pages with useful free space
HINT:  Consider using VACUUM FULL on this relation or increasing the configuration parameter "max_fsm_pages".
INFO:  vacuuming "pg_toast.pg_toast_27375"
INFO:  scanned index "pg_toast_27375_index" to remove 4 row versions
DETAIL:  CPU 0.00s/0.00u sec elapsed 0.01 sec.
INFO:  "pg_toast_27375": removed 4 row versions in 1 pages
DETAIL:  CPU 0.00s/0.00u sec elapsed 0.02 sec.
INFO:  index "pg_toast_27375_index" now contains 0 row versions in 2 pages
DETAIL:  4 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.
ERROR:  kind mismatch among backends. Possible last query was: "VACUUM VERBOSE ANALYZE core_extevent;" kind details are: 0[N: "pg_toast_27375": found 4 removable, 0 nonremovable row versions in 1 pages] 1[C]
HINT:  check data consistency among db nodes
server closed the connection unexpectedly
	This probably means the server terminated abnormally
	before or while processing the request.
The connection to the server was lost. Attempting reset: Succeeded.

The "kicked" backend contains this - the only error I see there is "SGT ERROR:  canceling autovacuum task":

May 12 05:22:44 db20 postgres[27590]: [64-1] 2011-05-12 05:22:44 SGT INFO:  "core_extevent": found 36756505 removable, 1549821 nonremovable row versions in 2737848 pages
May 12 05:22:44 db20 postgres[27590]: [64-2] 2011-05-12 05:22:44 SGT DETAIL:  0 dead row versions cannot be removed yet.
May 12 05:22:44 db20 postgres[27590]: [64-3] #011There were 41727140 unused item pointers.
May 12 05:22:44 db20 postgres[27590]: [64-4] #0112679731 pages contain useful free space.
May 12 05:22:44 db20 postgres[27590]: [64-5] #0110 pages are entirely empty.
May 12 05:22:44 db20 postgres[27590]: [64-6] #011CPU 86.00s/209.02u sec elapsed 1105.35 sec.
May 12 05:22:44 db20 postgres[27590]: [65-1] 2011-05-12 05:22:44 SGT WARNING:  relation "public.core_extevent" contains more than "max_fsm_pages" pages with useful free
May 12 05:22:44 db20 postgres[27590]: [65-2]  space
May 12 05:22:44 db20 postgres[27590]: [65-3] 2011-05-12 05:22:44 SGT HINT:  Consider using VACUUM FULL on this relation or increasing the configuration parameter
May 12 05:22:44 db20 postgres[27590]: [65-4]  "max_fsm_pages".
May 12 05:22:44 db20 postgres[27590]: [65-5] 2011-05-12 05:22:44 SGT STATEMENT:  VACUUM VERBOSE ANALYZE core_extevent;
May 12 05:22:44 db20 postgres[27590]: [66-1] 2011-05-12 05:22:44 SGT INFO:  vacuuming "pg_toast.pg_toast_27375"
May 12 05:22:44 db20 postgres[27590]: [67-1] 2011-05-12 05:22:44 SGT INFO:  scanned index "pg_toast_27375_index" to remove 4 row versions
May 12 05:22:44 db20 postgres[27590]: [67-2] 2011-05-12 05:22:44 SGT DETAIL:  CPU 0.00s/0.00u sec elapsed 0.00 sec.
May 12 05:22:44 db20 postgres[27590]: [68-1] 2011-05-12 05:22:44 SGT INFO:  "pg_toast_27375": removed 4 row versions in 1 pages
May 12 05:22:44 db20 postgres[27590]: [68-2] 2011-05-12 05:22:44 SGT DETAIL:  CPU 0.00s/0.00u sec elapsed 0.00 sec.
May 12 05:22:44 db20 postgres[27590]: [69-1] 2011-05-12 05:22:44 SGT INFO:  index "pg_toast_27375_index" now contains 0 row versions in 2 pages
May 12 05:22:44 db20 postgres[27590]: [69-2] 2011-05-12 05:22:44 SGT DETAIL:  4 index row versions were removed.
May 12 05:22:44 db20 postgres[27590]: [69-3] #0110 index pages have been deleted, 0 are currently reusable.
May 12 05:22:44 db20 postgres[27590]: [69-4] #011CPU 0.00s/0.00u sec elapsed 0.00 sec.
May 12 05:22:44 db20 postgres[27590]: [70-1] 2011-05-12 05:22:44 SGT INFO:  "pg_toast_27375": found 4 removable, 0 nonremovable row versions in 1 pages
May 12 05:22:44 db20 postgres[27590]: [70-2] 2011-05-12 05:22:44 SGT DETAIL:  0 dead row versions cannot be removed yet.
May 12 05:22:44 db20 postgres[27590]: [70-3] #011There were 0 unused item pointers.
May 12 05:22:44 db20 postgres[27590]: [70-4] #0111 pages contain useful free space.
May 12 05:22:44 db20 postgres[27590]: [70-5] #0110 pages are entirely empty.
May 12 05:22:44 db20 postgres[27590]: [70-6] #011CPU 0.00s/0.00u sec elapsed 0.02 sec.
May 12 05:22:44 db20 postgres[27590]: [71-1] 2011-05-12 05:22:44 SGT INFO:  "pg_toast_27375": truncated 1 to 0 pages
May 12 05:22:44 db20 postgres[27590]: [71-2] 2011-05-12 05:22:44 SGT DETAIL:  CPU 0.00s/0.00u sec elapsed 0.03 sec.
May 12 05:22:45 db20 postgres[28283]: [2-1] 2011-05-12 05:22:45 SGT ERROR:  canceling autovacuum task
May 12 05:22:45 db20 postgres[28283]: [2-2] 2011-05-12 05:22:45 SGT CONTEXT:  automatic vacuum of table "champion.public.core_extevent"
May 12 05:22:45 db20 postgres[27590]: [72-1] 2011-05-12 05:22:45 SGT INFO:  analyzing "public.core_extevent"
May 12 05:23:04 db20 postgres[27590]: [73-1] 2011-05-12 05:23:04 SGT INFO:  "core_extevent": scanned 3000 of 2737907 pages, containing 1493 live rows and 0 dead rows; 1493
May 12 05:23:04 db20 postgres[27590]: [73-2]  rows in sample, 1362565 estimated total rows
May 12 05:23:04 db20 postgres[27590]: [74-1] 2011-05-12 05:23:04 SGT LOG:  duration: 1126957.051 ms  statement: VACUUM VERBOSE ANALYZE core_extevent;

-- 
Tomasz Chmielewski
http://wpkg.org