public inbox for [email protected]  

help / color / mirror / Atom feed

From: Alexander Lakhin <[email protected]>
To: Andres Freund <[email protected]>
To: Thomas Munro <[email protected]>
Cc: Tom Lane <[email protected]>
Cc: Andrew Dunstan <[email protected]>
Cc: pgsql-hackers <[email protected]>
Subject: Re: Why is src/test/modules/committs/t/002_standby.pl flaky?
Date: Sun, 16 Jan 2022 14:00:00 +0300
Message-ID: <[email protected]> (raw)
In-Reply-To: <[email protected]>
References: <[email protected]>
	<CA+hUKG+o_QzN1LrEPGJLa6JiZU4DpLRybkwZjdCErs2qsB6axg@mail.gmail.com>
	<[email protected]>
	<CA+hUKGLP+j9vuyJ2U8m+xKgx-gfCA9aJqfrchH0dWUCgYwr4eQ@mail.gmail.com>
	<[email protected]>
	<[email protected]>
	<CA+hUKGKFajQiUMerS4h_=eCNKoXMYoYSkyvwMZip7WV3KUckrg@mail.gmail.com>
	<CA+hUKGK1QszjvPC_bchaQ8-DUF4jMTyqxgXpsi4L8YhN=NLpcA@mail.gmail.com>
	<[email protected]>
	<CA+hUKGK4VWGN=pLgbkU_aud4O5ZAACx1dRDk5uw8Jt_jVAk66Q@mail.gmail.com>
	<[email protected]>

Hello Andres,
15.01.2022 01:44, Andres Freund wrote:
> What about instead giving WalReceiverConn an internal WaitEventSet, and using
> that consistently? I've attached a draft for that.
>
> Alexander, could you test with that patch applied?
Unfortunately, this patch doesn't fix the issue. The test
commit_ts/002_standby still fails (on iterations 3, 1, 8 for me).
With the debugging logging added:
...
elog(LOG, "libpqrcv_wait() before WaitEventSetWait(%p)", conn->wes);
    nevents = WaitEventSetWait(conn->wes, timeout, &event, 1,
wait_event_info);
elog(LOG, "libpqrcv_wait() after WaitEventSetWait");
...
elog(LOG, "WaitEventSetWaitBlock before WaitForMultipleObjects(%p)",
set->handles);
    rc = WaitForMultipleObjects(set->nevents + 1, set->handles, FALSE,
                                cur_timeout);
elog(LOG, "WaitEventSetWaitBlock aftet WaitForMultipleObjects");
...
and so on.

I see in 002_standby_standby.log
...
2022-01-16 13:31:36.244 MSK [1336] LOG:  libpqrcv_receive PQgetCopyData
returned: 145
2022-01-16 13:31:36.244 MSK [1336] LOG:  libpqrcv_receive PQgetCopyData
returned: 0
2022-01-16 13:31:36.244 MSK [1336] LOG:  libpqrcv_wait() before
WaitEventSetWait(000000000063ABA8)
2022-01-16 13:31:36.244 MSK [1336] LOG:  WaitEventSetWait before
WaitEventSetWaitBlock(000000000063ABA8)
2022-01-16 13:31:36.244 MSK [1336] LOG:  WaitEventSetWaitBlock before
WaitForMultipleObjects(000000000063AC30)
2022-01-16 13:31:36.244 MSK [2820] LOG:  WaitEventSetWaitBlock aftet
WaitForMultipleObjects
2022-01-16 13:31:36.244 MSK [2820] LOG:  WaitEventSetWait after
WaitEventSetWaitBlock
2022-01-16 13:31:36.244 MSK [1336] LOG:  WaitEventSetWaitBlock aftet
WaitForMultipleObjects
2022-01-16 13:31:36.244 MSK [1336] LOG:  WaitEventSetWait after
WaitEventSetWaitBlock
2022-01-16 13:31:36.244 MSK [1336] LOG:  libpqrcv_wait() after
WaitEventSetWait
2022-01-16 13:31:36.244 MSK [1336] LOG:  libpqrcv_receive PQgetCopyData
returned: 0
2022-01-16 13:31:36.244 MSK [1336] LOG:  libpqrcv_wait() before
WaitEventSetWait(000000000063ABA8)
2022-01-16 13:31:36.244 MSK [1336] LOG:  WaitEventSetWait before
WaitEventSetWaitBlock(000000000063ABA8)
2022-01-16 13:31:36.244 MSK [1336] LOG:  WaitEventSetWaitBlock before
WaitForMultipleObjects(000000000063AC30)
2022-01-16 13:31:36.244 MSK [2820] LOG:  WaitEventSetWait before
WaitEventSetWaitBlock(0000000000649FB8)
2022-01-16 13:31:36.244 MSK [2820] LOG:  WaitEventSetWaitBlock before
WaitForMultipleObjects(000000000064A020)
2022-01-16 13:31:36.247 MSK [1336] LOG:  WaitEventSetWaitBlock aftet
WaitForMultipleObjects
2022-01-16 13:31:36.247 MSK [1336] LOG:  WaitEventSetWait after
WaitEventSetWaitBlock
2022-01-16 13:31:36.247 MSK [1336] LOG:  libpqrcv_wait() after
WaitEventSetWait
2022-01-16 13:31:36.247 MSK [1336] LOG:  libpqrcv_receive PQgetCopyData
returned: -1
2022-01-16 13:31:36.247 MSK [1336] LOG:  libpqrcv_receive before
libpqrcv_PQgetResult(1)
2022-01-16 13:31:36.247 MSK [1336] LOG:  libpqrcv_receive
libpqrcv_PQgetResult(1) returned 0000000000692400
2022-01-16 13:31:36.247 MSK [1336] LOG:  libpqrcv_receive before
libpqrcv_PQgetResult(2)
2022-01-16 13:31:36.247 MSK [1336] LOG:  libpqrcv_wait() before
WaitEventSetWait(000000000063ABA8)
2022-01-16 13:31:36.247 MSK [1336] LOG:  WaitEventSetWait before
WaitEventSetWaitBlock(000000000063ABA8)
2022-01-16 13:31:36.247 MSK [1336] LOG:  WaitEventSetWaitBlock before
WaitForMultipleObjects(000000000063AC30)
2022-01-16 13:31:36.368 MSK [984] LOG:  WaitEventSetWaitBlock aftet
WaitForMultipleObjects
2022-01-16 13:31:36.368 MSK [984] LOG:  WaitEventSetWait after
WaitEventSetWaitBlock
...
After that, the process 1336 hangs till shutdown.

Best regards,
Alexander

view thread (38+ messages)  latest in thread

reply

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Reply to all the recipients using the --to and --cc options:
  reply via email

  To: [email protected]
  Cc: [email protected], [email protected], [email protected], [email protected], [email protected]
  Subject: Re: Why is src/test/modules/committs/t/002_standby.pl flaky?
  In-Reply-To: <[email protected]>

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

This inbox is served by agora; see mirroring instructions
for how to clone and mirror all data and code used for this inbox