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

[Tomasz Chmielewski]

On 12.05.2011 00:21, Tomasz Chmielewski wrote:
> 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.

(...)

> 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;

This is also quite strange - the database where pgpool was running has this logged more than 30 minutes later:

May 12 06:00:39 db10 postgres[9430]: [10580-3] #011There were 0 unused item pointers.
May 12 06:00:39 db10 postgres[9430]: [10580-4] #0111 pages contain useful free space.
May 12 06:00:39 db10 postgres[9430]: [10580-5] #0110 pages are entirely empty.
May 12 06:00:39 db10 postgres[9430]: [10580-6] #011CPU 0.00s/0.00u sec elapsed 0.08 sec.
May 12 06:00:39 db10 pgpool: 2011-05-12 06:00:39 ERROR: pid 9429: read_kind_from_backend: 1 th kind C does not match with master or majority connection kind N
May 12 06:00:39 db10 pgpool: 2011-05-12 06:00:39 ERROR: pid 9429: 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]
May 12 06:00:39 db10 postgres[9430]: [10581-1] 2011-05-12 06:00:39 SGT INFO:  "pg_toast_27375": truncated 1 to 0 pages
May 12 06:00:39 db10 postgres[9430]: [10581-2] 2011-05-12 06:00:39 SGT DETAIL:  CPU 0.00s/0.00u sec elapsed 0.00 sec.
May 12 06:00:39 db10 pgpool: 2011-05-12 06:00:39 LOG:   pid 9429: notice_backend_error: 1 fail over request from pid 9429
May 12 06:00:39 db10 pgpool: 2011-05-12 06:00:39 LOG:   pid 15697: starting degeneration. shutdown host 192.168.0.31(5432)



So it looks like VACUUM finished much earlier on one of the backends (the one which was kicked when the second backend finished) - that's expected, as only one of them gets read/write traffic.

Could it be the reason why the other backend was kicked? Is it normal when running VACUUM?


-- 
Tomasz Chmielewski
http://wpkg.org