> Hi all, > > I hit an obscure bug in 2.2.2, which is also present in HEAD. > > Here's the backend debugging output: > > 2009-06-24 15:12:37 DEBUG: pid 55600: new_connection: connecting 0 backend > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length: slot: 0 > length: 8 > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master > slot: 0 length: 25 > 2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: client_encoding > value: UTF8 > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master > slot: 0 length: 23 > 2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: DateStyle value: > ISO, MDY > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master > slot: 0 length: 25 > 2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: integer_datetimes > value: on > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master > slot: 0 length: 27 > 2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: IntervalStyle > value: postgres > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master > slot: 0 length: 20 > 2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: is_superuser > value: on > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master > slot: 0 length: 25 > 2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: server_encoding > value: UTF8 > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master > slot: 0 length: 26 > 2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: server_version > value: 8.2.13 > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master > slot: 0 length: 30 > 2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: > session_authorization value: swm > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master > slot: 0 length: 36 > 2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: > standard_conforming_strings value: off > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master > slot: 0 length: 26 > 2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: TimeZone value: > Europe/Paris > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length: slot: 0 > length: 12 > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_send_auth_ok: send pid 55633 to > frontend > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend Z NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_process_query: kind from backend: > Z > 2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length: slot: 0 > length: 5 > 2009-06-24 15:12:37 DEBUG: pid 55600: ReadyForQuery: message length: 5 > 2009-06-24 15:12:37 DEBUG: pid 55600: ReadyForQuery: transaction state: I > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend P(50) > 2009-06-24 15:12:37 DEBUG: pid 55600: Parse: portal name > <pg8000_statement_0> > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend 1 NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend D(44) > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend t NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend n NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48) > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend P(50) > 2009-06-24 15:12:37 DEBUG: pid 55600: Parse: portal name > <pg8000_statement_1> > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend 1 NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend D(44) > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend t NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend n NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48) > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend P(50) > 2009-06-24 15:12:37 DEBUG: pid 55600: Parse: portal name > <pg8000_statement_2> > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend 1 NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend D(44) > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend t NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend n NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48) > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend P(50) > 2009-06-24 15:12:37 DEBUG: pid 55600: Parse: portal name <> > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend 1 NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend D(44) > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend t NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend T NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48) > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend B(42) > 2009-06-24 15:12:37 DEBUG: pid 55600: bind message: portal_name > pg8000_portal_3 stmt_name > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend 2 NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend D(44) > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend T NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48) > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend E(45) > 2009-06-24 15:12:37 DEBUG: pid 55600: Execute: portal name <pg8000_portal_3> > 2009-06-24 15:12:37 DEBUG: pid 55600: waiting for backend completing the > query > 2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from > 0 th backend C NUM_BACKENDS: 1 > 2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48) > > We hang there indefinitely. > > As it turns out, the C (command complete) message from the backend is never > forwarded to the front end. There's nothing left to be sync'd when we > forward the 'H' (sync) message so everyone waits forever.
Thanks for the info. I assume you mean Flush, rather than Sync. > Attached is a simple patch which resolves this issue. > > The function itself seems dangerous to me. We should probably make sure we > flush all messages, always. This will future proof pgpool against protocol > changes and further bugs. You are right. I have added pool_flush() calls after SimpleForwardToFrontend() call to make sure that messages are always flushed. The only concern is, adding extra pool_flush() might cause performance down. So I did some tests using pgbench -S, and found nothing has been changed regarding performance after patching. So far, so good. -- Tatsuo Ishii SRA OSS, Inc. Japan _______________________________________________ Pgpool-hackers mailing list [email protected] http://pgfoundry.org/mailman/listinfo/pgpool-hackers
