Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtp (Exim 4.84_2) (envelope-from ) id 1dPWvq-0001ic-Vw for pgsql-hackers@arkaria.postgresql.org; Mon, 26 Jun 2017 16:32:11 +0000 Received: from localhost ([127.0.0.1] helo=postgresql.org) by malur.postgresql.org with smtp (Exim 4.84_2) (envelope-from ) id 1dPWvq-0006ET-Cb for pgsql-hackers@arkaria.postgresql.org; Mon, 26 Jun 2017 16:32:10 +0000 Received: from makus.postgresql.org ([2001:4800:1501:1::229]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1dPWvo-0006CR-JA for pgsql-hackers@postgreSQL.org; Mon, 26 Jun 2017 16:32:08 +0000 Received: from sss.pgh.pa.us ([66.207.139.130]) by makus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256) (Exim 4.84_2) (envelope-from ) id 1dPWvh-0007Gf-OD for pgsql-hackers@postgreSQL.org; Mon, 26 Jun 2017 16:32:07 +0000 Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1]) by sss.pgh.pa.us (8.14.4/8.14.4) with ESMTP id v5QGW0XP021345 for ; Mon, 26 Jun 2017 12:32:00 -0400 From: Tom Lane To: pgsql-hackers@postgreSQL.org Subject: Another reason why the recovery tests take a long time MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-ID: <21343.1498494720.1@sss.pgh.pa.us> Content-Transfer-Encoding: quoted-printable Date: Mon, 26 Jun 2017 12:32:00 -0400 Message-ID: <21344.1498494720@sss.pgh.pa.us> List-Archive: List-Help: List-ID: List-Owner: List-Post: List-Subscribe: List-Unsubscribe: X-Mailing-List: pgsql-hackers Precedence: bulk Sender: pgsql-hackers-owner@postgresql.org I've found another edge-case bug through investigation of unexpectedly slow recovery test runs. It goes like this: * While streaming from master to slave, test script shuts down master while slave is left running. We soon restart the master, but meanwhile: * slave's walreceiver process fails, reporting 2017-06-26 16:06:50.209 UTC [13209] LOG: replication terminated by primary= server 2017-06-26 16:06:50.209 UTC [13209] DETAIL: End of WAL reached on timeline= 1 at 0/3000098. 2017-06-26 16:06:50.209 UTC [13209] FATAL: could not send end-of-streaming= message to primary: no COPY in progress * slave's startup process observes that walreceiver is gone and sends PMSIGNAL_START_WALRECEIVER to ask for a new one * more often than you would guess, in fact nearly 100% reproducibly for me, the postmaster receives/services the PMSIGNAL before it receives SIGCHLD for the walreceiver. In this situation sigusr1_handler just throws away the walreceiver start request, reasoning that the walreceiver is already running. * eventually, it dawns on the startup process that the walreceiver isn't starting, and it asks for a new one. But that takes ten seconds (WALRCV_STARTUP_TIMEOUT). So this looks like a pretty obvious race condition in the postmaster, which should be resolved by having it set a flag on receipt of PMSIGNAL_START_WALRECEIVER that's cleared only when it does start a new walreceiver. But I wonder whether it's intentional that the old walreceiver dies in the first place. That FATAL exit looks suspiciously like it wasn't originally-designed-in behavior. regards, tom lane --=20 Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers