Horton

Thread

Commits

  1. Remove assertion based on pending_since in pgstat_report_stat()

  1. Recent pg_rewind test failures in buildfarm

    Tom Lane <tgl@sss.pgh.pa.us> — 2025-04-15T02:58:28Z

    In the last day or so, both skink and mamba have hit this
in the pg_rewind test suite [1][2]:

#3  0x01f03f7c in ExceptionalCondition (conditionName=conditionName@entry=0x2119c4c "pending_since == 0", fileName=fileName@entry=0x2119454 "pgstat.c", lineNumber=lineNumber@entry=734) at assert.c:66
#4  0x01d7994c in pgstat_report_stat (force=force@entry=true) at pgstat.c:734
#5  0x01d7a248 in pgstat_shutdown_hook (code=<optimized out>, arg=<optimized out>) at pgstat.c:615
#6  0x01d1e7c0 in shmem_exit (code=code@entry=0) at ipc.c:243
#7  0x01d1e92c in proc_exit_prepare (code=code@entry=0) at ipc.c:198
#8  0x01d1e9fc in proc_exit (code=0) at ipc.c:111
#9  0x01cd5bd0 in ProcessRepliesIfAny () at walsender.c:2294
#10 0x01cd8084 in WalSndLoop (send_data=send_data@entry=0x1cd7628 <XLogSendPhysical>) at walsender.c:2790
#11 0x01cd8f40 in StartReplication (cmd=0xfd048210) at walsender.c:960
#12 exec_replication_command (cmd_string=cmd_string@entry=0xfd53c098 "START_REPLICATION 0/3000000 TIMELINE 2") at walsender.c:2135
#13 0x01d5bd84 in PostgresMain (dbname=<optimized out>, username=<optimized out>) at postgres.c:4767

That assert appears to be several years old, and the
008_min_recovery_point.pl test script that's triggering it hasn't
changed very recently either, so I'm baffled where to start digging.
It has the odor of a timing problem, so maybe we just started hitting
this by chance.  Still ... anybody have an idea?

			regards, tom lane

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2025-04-13%2018%3A55%3A03
[2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=mamba&dt=2025-04-15%2001%3A00%3A04

  2. Re: Recent pg_rewind test failures in buildfarm

    Alexander Law <exclusion@gmail.com> — 2025-04-15T05:00:00Z

    Hello Tom,

15.04.2025 05:58, Tom Lane wrote:
> In the last day or so, both skink and mamba have hit this
> in the pg_rewind test suite [1][2]:
>
> #3  0x01f03f7c in ExceptionalCondition (conditionName=conditionName@entry=0x2119c4c "pending_since == 0", fileName=fileName@entry=0x2119454 "pgstat.c", lineNumber=lineNumber@entry=734) at assert.c:66
> ...
>
> That assert appears to be several years old, and the
> 008_min_recovery_point.pl test script that's triggering it hasn't
> changed very recently either, so I'm baffled where to start digging.
> It has the odor of a timing problem, so maybe we just started hitting
> this by chance.  Still ... anybody have an idea?
>
> [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2025-04-13%2018%3A55%3A03
> [2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=mamba&dt=2025-04-15%2001%3A00%3A04
>

FWIW, there was also another test (028_row_filter.pl) failed due to that
assert triggered: [3].

I've managed to reproduce this failure locally when running 10 instances
of 008_min_recovery_point.pl in parallel under Valgrind.

Will try to investigate the issue during this week.

[3] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2025-04-11%2007%3A41%3A36

Best regards,
Alexander Lakhin
Neon (https://neon.tech)

  3. Re: Recent pg_rewind test failures in buildfarm

    Bertrand Drouvot <bertranddrouvot.pg@gmail.com> — 2025-04-15T05:50:32Z

    Hi,

On Tue, Apr 15, 2025 at 08:00:00AM +0300, Alexander Lakhin wrote:
> Hello Tom,
> 
> 15.04.2025 05:58, Tom Lane wrote:
> > In the last day or so, both skink and mamba have hit this
> > in the pg_rewind test suite [1][2]:
> > 
> > #3  0x01f03f7c in ExceptionalCondition (conditionName=conditionName@entry=0x2119c4c "pending_since == 0", fileName=fileName@entry=0x2119454 "pgstat.c", lineNumber=lineNumber@entry=734) at assert.c:66
> > ...
> > 
> > That assert appears to be several years old, and the
> > 008_min_recovery_point.pl test script that's triggering it hasn't
> > changed very recently either, so I'm baffled where to start digging.
> > It has the odor of a timing problem, so maybe we just started hitting
> > this by chance.  Still ... anybody have an idea?

Sorry, can't look at the details right now but it might be linked to 
039549d70f6 which is recent enough and in this area. Will give it a look once
I've time.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

  4. Re: Recent pg_rewind test failures in buildfarm

    Michael Paquier <michael@paquier.xyz> — 2025-04-15T06:02:15Z

    On Mon, Apr 14, 2025 at 10:58:28PM -0400, Tom Lane wrote:
> That assert appears to be several years old, and the
> 008_min_recovery_point.pl test script that's triggering it hasn't
> changed very recently either, so I'm baffled where to start digging.
> It has the odor of a timing problem, so maybe we just started hitting
> this by chance.  Still ... anybody have an idea?

Likely 039549d70f6a.  The proc_exit(0) calls done at this stage are
reporting that we have non-flushed stats, but we should have some
remaining around.  This sequence is part of the pgstat_shutdown_hook
callback, which has been initialized by pgstat_initialize() done for
the WAL senders in BaseInit().  It looks like we are going to need to
be more aggressive with the stats flushes, so as we have nothing left
when reaching this stage of the shutdown in ProcessRepliesIfAny().

(Sorry for the fuzzy reply, I cannot dive into all the details now,
that's just a quick take on the matter so I may be wrong with my
assumptions.)
--
Michael

  5. Re: Recent pg_rewind test failures in buildfarm

    Andres Freund <andres@anarazel.de> — 2025-04-15T10:04:54Z

    Hi,

On 2025-04-14 22:58:28 -0400, Tom Lane wrote:
> In the last day or so, both skink and mamba have hit this
> in the pg_rewind test suite [1][2]:
> 
> #3  0x01f03f7c in ExceptionalCondition (conditionName=conditionName@entry=0x2119c4c "pending_since == 0", fileName=fileName@entry=0x2119454 "pgstat.c", lineNumber=lineNumber@entry=734) at assert.c:66
> #4  0x01d7994c in pgstat_report_stat (force=force@entry=true) at pgstat.c:734
> #5  0x01d7a248 in pgstat_shutdown_hook (code=<optimized out>, arg=<optimized out>) at pgstat.c:615
> #6  0x01d1e7c0 in shmem_exit (code=code@entry=0) at ipc.c:243
> #7  0x01d1e92c in proc_exit_prepare (code=code@entry=0) at ipc.c:198
> #8  0x01d1e9fc in proc_exit (code=0) at ipc.c:111
> #9  0x01cd5bd0 in ProcessRepliesIfAny () at walsender.c:2294
> #10 0x01cd8084 in WalSndLoop (send_data=send_data@entry=0x1cd7628 <XLogSendPhysical>) at walsender.c:2790
> #11 0x01cd8f40 in StartReplication (cmd=0xfd048210) at walsender.c:960
> #12 exec_replication_command (cmd_string=cmd_string@entry=0xfd53c098 "START_REPLICATION 0/3000000 TIMELINE 2") at walsender.c:2135
> #13 0x01d5bd84 in PostgresMain (dbname=<optimized out>, username=<optimized out>) at postgres.c:4767
> 
> That assert appears to be several years old, and the
> 008_min_recovery_point.pl test script that's triggering it hasn't
> changed very recently either, so I'm baffled where to start digging.
> It has the odor of a timing problem, so maybe we just started hitting
> this by chance.  Still ... anybody have an idea?

See also https://postgr.es/m/dwrkeszz6czvtkxzr5mqlciy652zau5qqnm3cp5f3p2po74ppk%40omg4g3cc6dgq

I am fairly certain it's the fault of 039549d70f6

Greetings,

Andres Freund

  6. Re: Recent pg_rewind test failures in buildfarm

    Andres Freund <andres@anarazel.de> — 2025-04-15T10:20:51Z

    Hi,

On 2025-04-15 06:04:54 -0400, Andres Freund wrote:
> See also https://postgr.es/m/dwrkeszz6czvtkxzr5mqlciy652zau5qqnm3cp5f3p2po74ppk%40omg4g3cc6dgq

Huh, turns out my emails of the last few days had gotten stuck. I only noticed
when trying to open the above link and it was dead.  I had been wondering why
neither Bertrand nor Michael had reacted to the mail...

Greetings,

Andres Freund

  7. Re: Recent pg_rewind test failures in buildfarm

    Michael Paquier <michael@paquier.xyz> — 2025-04-21T01:17:40Z

    On Tue, Apr 15, 2025 at 05:50:32AM +0000, Bertrand Drouvot wrote:
> Sorry, can't look at the details right now but it might be linked to 
> 039549d70f6 which is recent enough and in this area. Will give it a look once
> I've time.

Playing catch-up with various things this week, and I have been
looking at this one.

So, we are triggering this assertion in the shutdown sequence of the
WAL sender because there is nothing to flush based on what the
callbacks are reporting, still pending_since could have been set by a
previous call of pgstat_report_stat(), which could come from a
PostgresMain() path for example, depending on the frequency of such
calls.  The important point is that we don't lose WAL sender stats at
shutdown, and well, we don't lose any data for the WAL sender based on
what this assertion tells us, just that there is some friction with
the new I/O and backend flush calls.

pg_stat_io has been added in v16, but isn't that something that could
be reached even today down to v15?  For example, imagine the case of a
background worker that does periodic stats reports with interactions
on existing stats.  pgstats stored in shmem has been added in v15.

Thoughts?
--
Michael

  8. Re: Recent pg_rewind test failures in buildfarm

    Bertrand Drouvot <bertranddrouvot.pg@gmail.com> — 2025-04-22T06:22:51Z

    Hi,

On Mon, Apr 21, 2025 at 10:17:40AM +0900, Michael Paquier wrote:
> On Tue, Apr 15, 2025 at 05:50:32AM +0000, Bertrand Drouvot wrote:
> > Sorry, can't look at the details right now but it might be linked to 
> > 039549d70f6 which is recent enough and in this area. Will give it a look once
> > I've time.
> 
> Playing catch-up with various things this week, and I have been
> looking at this one.
> 
> So, we are triggering this assertion in the shutdown sequence of the
> WAL sender because there is nothing to flush based on what the
> callbacks are reporting, still pending_since could have been set by a
> previous call of pgstat_report_stat(), which could come from a
> PostgresMain() path for example, depending on the frequency of such
> calls.  The important point is that we don't lose WAL sender stats at
> shutdown,

Right.

> and well, we don't lose any data for the WAL sender based on
> what this assertion tells us, just that there is some friction with
> the new I/O and backend flush calls.

I do agree.

> pg_stat_io has been added in v16, but isn't that something that could
> be reached even today down to v15?  For example, imagine the case of a
> background worker that does periodic stats reports with interactions
> on existing stats.  pgstats stored in shmem has been added in v15.
> 
> Thoughts?

Yeah, unless that might come from fc415edf8ca but I don't think that's the case.

Regards,

-- 
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

  9. Re: Recent pg_rewind test failures in buildfarm

    Michael Paquier <michael@paquier.xyz> — 2025-04-23T04:55:31Z

    On Tue, Apr 22, 2025 at 06:22:51AM +0000, Bertrand Drouvot wrote:
> Yeah, unless that might come from fc415edf8ca but I don't think that's the case.

I've been eyeing this whole area of the code for a few hours to
convince myself on HEAD, and I cannot really find a defect directly
related to it.

I am wondering if we should do a PGSTAT_BACKEND_FLUSH_WAL in the WAL
sender, but the end of any transaction happening in a logical WAL
sender would make sure that this happens on a periodic basis.

Anyway, sorry for make everybody waiting here.  I've now removed the
assertion down to v15.
--
Michael