Horton
Menu

Thread

  1. stats.sql might fail due to shared buffers also used by parallel tests

    Alexander Lakhin <exclusion@gmail.com> — 2025-01-06T07:00:00Z

    Hello hackers,

I'd like to share my investigation of one mysterious stats.sql failure
occurred in December: [1].
The difference of the failure is:
--- C:/prog/bf/root/HEAD/pgsql/src/test/regress/expected/stats.out 2024-09-18 19:31:14.665516500 +0000
+++ C:/prog/bf/root/HEAD/pgsql.build/testrun/recovery/027_stream_regress/data/results/stats.out 2024-12-17 
09:57:08.944588500 +0000
@@ -1291,7 +1291,7 @@
  SELECT :io_sum_shared_after_writes > :io_sum_shared_before_writes;
   ?column?
  ----------
- t
+ f
  (1 row)

027_stream_regress_primary.log contains:
2024-12-17 09:57:06.778 UTC [8568:109] pg_regress/stats LOG: statement: SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs
       FROM pg_stat_io
       WHERE object = 'relation'
2024-12-17 09:57:06.779 UTC [8568:110] pg_regress/stats LOG: statement: CREATE TABLE test_io_shared(a int);
2024-12-17 09:57:06.780 UTC [8568:111] pg_regress/stats LOG: statement: INSERT INTO test_io_shared SELECT i FROM 
generate_series(1,100)i;
...
2024-12-17 09:57:06.782 UTC [8568:115] pg_regress/stats LOG: statement: CHECKPOINT;
2024-12-17 09:57:06.794 UTC [3664:40] LOG:  checkpoint starting: immediate force wait
2024-12-17 09:57:06.856 UTC [3664:41] LOG:  checkpoint complete: wrote 0 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL 
file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.062 s; sync files=0, longest=0.000 s, 
average=0.000 s; distance=1875 kB, estimate=52682 kB; lsn=0/14A2F410, redo lsn=0/14A2F3B8
2024-12-17 09:57:06.857 UTC [8568:116] pg_regress/stats LOG: statement: CHECKPOINT;
2024-12-17 09:57:06.857 UTC [3664:42] LOG:  checkpoint starting: immediate force wait
2024-12-17 09:57:06.859 UTC [3664:43] LOG:  checkpoint complete: wrote 0 buffers (0.0%), wrote 0 SLRU buffers; 0 WAL 
file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, 
average=0.000 s; distance=0 kB, estimate=47414 kB; lsn=0/14A2F4E0, redo lsn=0/14A2F488
2024-12-17 09:57:06.859 UTC [8568:117] pg_regress/stats LOG: statement: SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs
       FROM pg_stat_io
       WHERE object = 'relation'
2024-12-17 09:57:06.860 UTC [8568:118] pg_regress/stats LOG: statement: SELECT 77693 > 77693;

The corresponding test case (added by 10a082bf7, dated 2023-02-11) is:
SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs
   FROM pg_stat_io
   WHERE object = 'relation' \gset io_sum_shared_before_
...
CREATE TABLE test_io_shared(a int);
INSERT INTO test_io_shared SELECT i FROM generate_series(1,100)i;
...
CHECKPOINT;
CHECKPOINT;
...
SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs
   FROM pg_stat_get_backend_io(pg_backend_pid())
   WHERE object = 'relation' \gset my_io_sum_shared_after_
SELECT :my_io_sum_shared_after_writes >= :my_io_sum_shared_before_writes;

So, as we can see from the log above, both checkpoints wrote 0 buffers,
moreover, no other process/backend wrote any buffers.

After series of experiments, I found that this situation is possible when
other backend steals shared buffers from checkpointer, without making new
buffers dirty, and then delays flushing it's statistics.

Please find attached a reproducer for this issue: I've added two sleeps
to stats.sql and reduced parallel_schedule, but I believe it's a legal
change, which doesn't affect the test case essentially.

With bufchurn.sql running concurrently. and TEMP_CONFIG containing
shared_buffers = 1MB (as in the 027_stream_regress test in question), I can
see exactly the same failure:
$ echo 'shared_buffers = 1MB' >/tmp/extra.config; TEMP_CONFIG=/tmp/extra.config make -s check
# +++ regress check in src/test/regress +++
# initializing database system by copying initdb template
# using temp instance on port 65312 with PID 129700
ok 1         - test_setup                                356 ms
ok 2         - create_index                             1002 ms
# parallel group (2 tests):  stats bufchurn
not ok 3     + stats                                   21176 ms
...

diff -U3 .../src/test/regress/expected/stats.out .../src/test/regress/results/stats.out
--- .../src/test/regress/expected/stats.out  2025-01-06 08:03:07.720275980 +0200
+++ .../src/test/regress/results/stats.out   2025-01-06 08:15:34.602170721 +0200
@@ -1321,7 +1321,7 @@
  SELECT :io_sum_shared_after_writes > :io_sum_shared_before_writes;
   ?column?
  ----------
- t
+ f
  (1 row)
...

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&dt=2024-12-17%2008%3A59%3A44

Best regards,
Alexander

  2. Re: stats.sql might fail due to shared buffers also used by parallel tests

    Shlok Kyal <shlok.kyal.oss@gmail.com> — 2025-07-03T06:54:50Z

    On Mon, 6 Jan 2025 at 12:30, Alexander Lakhin <exclusion@gmail.com> wrote:
>
> Hello hackers,
>
> I'd like to share my investigation of one mysterious stats.sql failure
> occurred in December: [1].
> The difference of the failure is:
> --- C:/prog/bf/root/HEAD/pgsql/src/test/regress/expected/stats.out 2024-09-18 19:31:14.665516500 +0000
> +++ C:/prog/bf/root/HEAD/pgsql.build/testrun/recovery/027_stream_regress/data/results/stats.out 2024-12-17
> 09:57:08.944588500 +0000
> @@ -1291,7 +1291,7 @@
>   SELECT :io_sum_shared_after_writes > :io_sum_shared_before_writes;
>    ?column?
>   ----------
> - t
> + f
>   (1 row)
>
> 027_stream_regress_primary.log contains:
> 2024-12-17 09:57:06.778 UTC [8568:109] pg_regress/stats LOG: statement: SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs
>        FROM pg_stat_io
>        WHERE object = 'relation'
> 2024-12-17 09:57:06.779 UTC [8568:110] pg_regress/stats LOG: statement: CREATE TABLE test_io_shared(a int);
> 2024-12-17 09:57:06.780 UTC [8568:111] pg_regress/stats LOG: statement: INSERT INTO test_io_shared SELECT i FROM
> generate_series(1,100)i;
> ...
> 2024-12-17 09:57:06.782 UTC [8568:115] pg_regress/stats LOG: statement: CHECKPOINT;
> 2024-12-17 09:57:06.794 UTC [3664:40] LOG:  checkpoint starting: immediate force wait
> 2024-12-17 09:57:06.856 UTC [3664:41] LOG:  checkpoint complete: wrote 0 buffers (0.0%), wrote 1 SLRU buffers; 0 WAL
> file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.062 s; sync files=0, longest=0.000 s,
> average=0.000 s; distance=1875 kB, estimate=52682 kB; lsn=0/14A2F410, redo lsn=0/14A2F3B8
> 2024-12-17 09:57:06.857 UTC [8568:116] pg_regress/stats LOG: statement: CHECKPOINT;
> 2024-12-17 09:57:06.857 UTC [3664:42] LOG:  checkpoint starting: immediate force wait
> 2024-12-17 09:57:06.859 UTC [3664:43] LOG:  checkpoint complete: wrote 0 buffers (0.0%), wrote 0 SLRU buffers; 0 WAL
> file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s,
> average=0.000 s; distance=0 kB, estimate=47414 kB; lsn=0/14A2F4E0, redo lsn=0/14A2F488
> 2024-12-17 09:57:06.859 UTC [8568:117] pg_regress/stats LOG: statement: SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs
>        FROM pg_stat_io
>        WHERE object = 'relation'
> 2024-12-17 09:57:06.860 UTC [8568:118] pg_regress/stats LOG: statement: SELECT 77693 > 77693;
>
> The corresponding test case (added by 10a082bf7, dated 2023-02-11) is:
> SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs
>    FROM pg_stat_io
>    WHERE object = 'relation' \gset io_sum_shared_before_
> ...
> CREATE TABLE test_io_shared(a int);
> INSERT INTO test_io_shared SELECT i FROM generate_series(1,100)i;
> ...
> CHECKPOINT;
> CHECKPOINT;
> ...
> SELECT sum(writes) AS writes, sum(fsyncs) AS fsyncs
>    FROM pg_stat_get_backend_io(pg_backend_pid())
>    WHERE object = 'relation' \gset my_io_sum_shared_after_
> SELECT :my_io_sum_shared_after_writes >= :my_io_sum_shared_before_writes;
>
> So, as we can see from the log above, both checkpoints wrote 0 buffers,
> moreover, no other process/backend wrote any buffers.
>
> After series of experiments, I found that this situation is possible when
> other backend steals shared buffers from checkpointer, without making new
> buffers dirty, and then delays flushing it's statistics.
>
> Please find attached a reproducer for this issue: I've added two sleeps
> to stats.sql and reduced parallel_schedule, but I believe it's a legal
> change, which doesn't affect the test case essentially.
>
> With bufchurn.sql running concurrently. and TEMP_CONFIG containing
> shared_buffers = 1MB (as in the 027_stream_regress test in question), I can
> see exactly the same failure:
> $ echo 'shared_buffers = 1MB' >/tmp/extra.config; TEMP_CONFIG=/tmp/extra.config make -s check
> # +++ regress check in src/test/regress +++
> # initializing database system by copying initdb template
> # using temp instance on port 65312 with PID 129700
> ok 1         - test_setup                                356 ms
> ok 2         - create_index                             1002 ms
> # parallel group (2 tests):  stats bufchurn
> not ok 3     + stats                                   21176 ms
> ...
>
> diff -U3 .../src/test/regress/expected/stats.out .../src/test/regress/results/stats.out
> --- .../src/test/regress/expected/stats.out  2025-01-06 08:03:07.720275980 +0200
> +++ .../src/test/regress/results/stats.out   2025-01-06 08:15:34.602170721 +0200
> @@ -1321,7 +1321,7 @@
>   SELECT :io_sum_shared_after_writes > :io_sum_shared_before_writes;
>    ?column?
>   ----------
> - t
> + f
>   (1 row)
> ...
>
> [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=drongo&dt=2024-12-17%2008%3A59%3A44
>

Hi Hackers,

I have also encountered a similar buildfarm failure [1].

| 1/1 + subscription                              142 ms FAIL
1/1 postgresql:regress / regress/regress ERROR           284.85s   exit status 1

diff --strip-trailing-cr -U3
c:/build-farm-local/buildroot/HEAD/pgsql/src/test/regress/expected/subscription.out
c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/regress/regress/results/subscription.out
--- c:/build-farm-local/buildroot/HEAD/pgsql/src/test/regress/expected/subscription.out
2025-06-28 20:13:02 +0900
+++ c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/regress/regress/results/subscription.out
2025-06-28 20:35:21 +0900
@@ -70,7 +70,7 @@
 SELECT :'prev_stats_reset' < stats_reset FROM
pg_stat_subscription_stats WHERE subname = 'regress_testsub';
  ?column?
 ----------
- t
+ f
 (1 row)

logs around this statement do not show unexpected thing:
2025-06-28 20:35:20.857 JST client backend[6092]
pg_regress/subscription STATEMENT:  CREATE SUBSCRIPTION
regress_testsub CONNECTION 'testconn' PUBLICATION testpub;
2025-06-28 20:35:20.857 JST client backend[6092]
pg_regress/subscription ERROR:  publication name "foo" used more than
once
2025-06-28 20:35:20.857 JST client backend[6092]
pg_regress/subscription STATEMENT:  CREATE SUBSCRIPTION
regress_testsub CONNECTION 'dbname=regress_doesnotexist' PUBLICATION
foo, testpub, foo WITH (connect = false);
2025-06-28 20:35:20.858 JST client backend[6092]
pg_regress/subscription WARNING:  subscription was created, but is not
connected
2025-06-28 20:35:20.858 JST client backend[6092]
pg_regress/subscription HINT:  To initiate replication, you must
manually create the replication slot, enable the subscription, and
refresh the subscription.
2025-06-28 20:35:20.861 JST client backend[6092]
pg_regress/subscription ERROR:  subscription "regress_testsub" already
exists

In subscription.sql, I looked at the test. The statement are like:
-- Reset the stats again and check if the new reset_stats is updated.
SELECT stats_reset as prev_stats_reset FROM pg_stat_subscription_stats
WHERE subname = 'regress_testsub' \gset
SELECT pg_stat_reset_subscription_stats(oid) FROM pg_subscription
WHERE subname = 'regress_testsub';
SELECT :'prev_stats_reset' < stats_reset FROM
pg_stat_subscription_stats WHERE subname = 'regress_testsub';

So according to me, I suspect the following causes
1) The time difference between 'prev_stats_reset' and current
'stats_reset' value is less than 1 microseconds.
'stats_reset' is of type 'timestamp with time zone' and the content of
it is like: '2025-06-30 21:01:07.925253+05:30'. So if the time
difference between 'prev_stats_reset' and current 'stats_reset' is
less than 1 microseconds. The query 'SELECT :'prev_stats_reset' <
stats_reset FROM pg_stat_subscription_stats WHERE subname =
'regress_testsub'' might return 'false' instead of 'true'.
But I was not able to reproduce such a scenario after multiple
testing. Even in high end machines, it takes at least a few
microseconds. Also there are multiple cases where we did similar
timestamp comparison in 'stats.sql' as well. And, I didn't find any
other failure related to such case. So, I feel this is not possible.

2) pg_stat_reset_subscription_stats(oid) function did not reset the stats.
We have a shared hash 'pgStatLocal.shared_hash'. If the entry
reference (for the subscription) is not found while executing
'pg_stat_reset_subscription_stats(oid)'. It  may not be able to reset
the stats. Maybe somehow this shared hash is getting dropped..
Also, it could be failing due to the same reason as Alexander has
reproduced in another case [2].

[1]: https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hamerkop&dt=2025-06-28%2011%3A02%3A30
[2]: https://www.postgresql.org/message-id/fe0391a8-dfa9-41c3-bf1c-7ea058e40f30%40gmail.com

Thanks and Regards,
Shlok Kyal

  3. Re: stats.sql might fail due to shared buffers also used by parallel tests

    Alexander Lakhin <exclusion@gmail.com> — 2025-07-04T20:00:00Z

    Hello Shlok,

03.07.2025 09:54, Shlok Kyal wrote:
> I have also encountered a similar buildfarm failure [1].
>
> | 1/1 + subscription                              142 ms FAIL
> 1/1 postgresql:regress / regress/regress ERROR           284.85s   exit status 1
>
> diff --strip-trailing-cr -U3
> c:/build-farm-local/buildroot/HEAD/pgsql/src/test/regress/expected/subscription.out
> c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/regress/regress/results/subscription.out
> --- c:/build-farm-local/buildroot/HEAD/pgsql/src/test/regress/expected/subscription.out
> 2025-06-28 20:13:02 +0900
> +++ c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/regress/regress/results/subscription.out
> 2025-06-28 20:35:21 +0900
> @@ -70,7 +70,7 @@
>   SELECT :'prev_stats_reset' < stats_reset FROM
> pg_stat_subscription_stats WHERE subname = 'regress_testsub';
>    ?column?
>   ----------
> - t
> + f
>   (1 row)

Thank you for your attention to this! Yes, I also noticed that failure,
but could not reproduce it yet.

> So according to me, I suspect the following causes
> 1) The time difference between 'prev_stats_reset' and current
> 'stats_reset' value is less than 1 microseconds.
> 'stats_reset' is of type 'timestamp with time zone' and the content of
> it is like: '2025-06-30 21:01:07.925253+05:30'. So if the time
> difference between 'prev_stats_reset' and current 'stats_reset' is
> less than 1 microseconds. The query 'SELECT :'prev_stats_reset' <
> stats_reset FROM pg_stat_subscription_stats WHERE subname =
> 'regress_testsub'' might return 'false' instead of 'true'.
> But I was not able to reproduce such a scenario after multiple
> testing. Even in high end machines, it takes at least a few
> microseconds. Also there are multiple cases where we did similar
> timestamp comparison in 'stats.sql' as well. And, I didn't find any
> other failure related to such case. So, I feel this is not possible.

Did you try that on Windows (hamerkop is a Windows animal)? IIUC,
GetCurrentTimestamp() -> gettimeofday() implemented on Windows via
GetSystemTimePreciseAsFileTime(), and it has 100ns resolution,
according to [1].

I tried it on a Windows VM and saw the following numbers:
SELECT :'prev_stats_reset' < stats_reset, :'prev_stats_reset', stats_reset FROM pg_stat_subscription_stats WHERE subname 
= 'regress_testsub';
  ?column? |              ?column?               | stats_reset
----------+-------------------------------------+-------------------------------------
  t        | Fri Jul 04 11:46:10.224323 2025 PDT | Fri Jul 04 11:46:10.224975 2025 PDT
  (1 row)

that is, the difference is about 600 ns — if I could make the VM 6x faster
or run the test on a bare metal, maybe I'd get the test failed.

Although the overall duration of the subscription doesn't differ much:
My VM:
# parallel group (2 tests):  subscription publication
ok 164       + publication                               806 ms
ok 165       + subscription                              210 ms
vs
hamerkop:
# parallel group (2 tests):  subscription publication
ok 164       + publication                              2383 ms
not ok 165   + subscription                              142 ms

So probably the failure is caused by something else.

> 2) pg_stat_reset_subscription_stats(oid) function did not reset the stats.
> We have a shared hash 'pgStatLocal.shared_hash'. If the entry
> reference (for the subscription) is not found while executing
> 'pg_stat_reset_subscription_stats(oid)'. It  may not be able to reset
> the stats. Maybe somehow this shared hash is getting dropped..
> Also, it could be failing due to the same reason as Alexander has

I don't think 2) is relevant here, because shared buffers shouldn't affect
subscription's statistics.

[1] https://stackoverflow.com/questions/4444090/measuring-time-with-a-resolution-of-microseconds-in-c

Best regards.
Alexander

  4. RE: stats.sql might fail due to shared buffers also used by parallel tests

    Hayato Kuroda (Fujitsu) <kuroda.hayato@fujitsu.com> — 2025-07-15T07:33:10Z

    Dear Alexander,

> > So according to me, I suspect the following causes
> > 1) The time difference between 'prev_stats_reset' and current
> > 'stats_reset' value is less than 1 microseconds.
> > 'stats_reset' is of type 'timestamp with time zone' and the content of
> > it is like: '2025-06-30 21:01:07.925253+05:30'. So if the time
> > difference between 'prev_stats_reset' and current 'stats_reset' is
> > less than 1 microseconds. The query 'SELECT :'prev_stats_reset' <
> > stats_reset FROM pg_stat_subscription_stats WHERE subname =
> > 'regress_testsub'' might return 'false' instead of 'true'.
> > But I was not able to reproduce such a scenario after multiple
> > testing. Even in high end machines, it takes at least a few
> > microseconds. Also there are multiple cases where we did similar
> > timestamp comparison in 'stats.sql' as well. And, I didn't find any
> > other failure related to such case. So, I feel this is not possible.
> 
> Did you try that on Windows (hamerkop is a Windows animal)? IIUC,
> GetCurrentTimestamp() -> gettimeofday() implemented on Windows via
> GetSystemTimePreciseAsFileTime(), and it has 100ns resolution,

Hmm. I'm not familiar with the Windows environment, but I have the doubt for it.

GetSystemTimePreciseAsFileTime() returns FILETIME structure, which represents the
time UTC with 100-nanosecod intervals [1]. The stack overflow seemed to refer it.
However, the document for GetSystemTimePreciseAsFileTime() says that the
resolution is < 1 us [2]. Also, MS doc [3] does not say that
GetSystemTimePreciseAsFileTime() returns value monotonically.
Another API QueryPerformanceCounter() seems to have the monotony.

A bit old document [4] also raised the possibility:

```
Consecutive calls may return the same result. The call time is less than the
smallest increment of the system time. The granularity is in the sub-microsecond
regime. The function may be used for time measurements but some care has to be
taken: Time differences may be ZERO.
```

Also, what if the the system clock is modified during the test via NTP?

> > 2) pg_stat_reset_subscription_stats(oid) function did not reset the stats.
> > We have a shared hash 'pgStatLocal.shared_hash'. If the entry
> > reference (for the subscription) is not found while executing
> > 'pg_stat_reset_subscription_stats(oid)'. It  may not be able to reset
> > the stats. Maybe somehow this shared hash is getting dropped..
> > Also, it could be failing due to the same reason as Alexander has
> 
> I don't think 2) is relevant here, because shared buffers shouldn't affect
> subscription's statistics.

To confirm; we do not consider the possibility that pgstat_get_entry_ref() returns
NULL right?

[1]: https://learn.microsoft.com/en-us/windows/win32/api/minwinbase/ns-minwinbase-filetime
[2]: https://learn.microsoft.com/en-us/windows/win32/api/sysinfoapi/nf-sysinfoapi-getsystemtimepreciseasfiletime
[3]: https://learn.microsoft.com/en-us/windows/win32/sysinfo/acquiring-high-resolution-time-stamps
[4]: http://www.windowstimestamp.com/description#:~:text=2.1.4.2.%C2%A0%C2%A0Desktop%20Applications%3A%20GetSystemTimePreciseAsFileTime()

Best regards,
Hayato Kuroda
FUJITSU LIMITED

  5. Re: stats.sql might fail due to shared buffers also used by parallel tests

    Alexander Lakhin <exclusion@gmail.com> — 2025-07-20T08:00:01Z

    Hello Kuroda-san,

Thank you for your attention to this!

15.07.2025 10:33, Hayato Kuroda (Fujitsu) wrote:
> GetSystemTimePreciseAsFileTime() returns FILETIME structure, which represents the
> time UTC with 100-nanosecod intervals [1]. The stack overflow seemed to refer it.
> However, the document for GetSystemTimePreciseAsFileTime() says that the
> resolution is < 1 us [2]. Also, MS doc [3] does not say that
> GetSystemTimePreciseAsFileTime() returns value monotonically.
> Another API QueryPerformanceCounter() seems to have the monotony.
>
> A bit old document [4] also raised the possibility:
>
> ```
> Consecutive calls may return the same result. The call time is less than the
> smallest increment of the system time. The granularity is in the sub-microsecond
> regime. The function may be used for time measurements but some care has to be
> taken: Time differences may be ZERO.
> ```
>
> Also, what if the the system clock is modified during the test via NTP?

Yeah, I made a simple test for GetSystemTimePreciseAsFileTime() and
confirmed that in my VM it provides sub-microsecond precision. Regarding
NTP, I think the second failure of this ilk [1] makes this cause close to
impossible. (Can't wait for the third one to gather more information.)

>>> 2) pg_stat_reset_subscription_stats(oid) function did not reset the stats.
>>> We have a shared hash 'pgStatLocal.shared_hash'. If the entry
>>> reference (for the subscription) is not found while executing
>>> 'pg_stat_reset_subscription_stats(oid)'. It  may not be able to reset
>>> the stats. Maybe somehow this shared hash is getting dropped..
>>> Also, it could be failing due to the same reason as Alexander has
>> I don't think 2) is relevant here, because shared buffers shouldn't affect
>> subscription's statistics.
> To confirm; we do not consider the possibility that pgstat_get_entry_ref() returns
> NULL right?

I've held a simple experiment with a modification like this:
@@ -1078,6 +1078,7 @@ pgstat_reset_entry(PgStat_Kind kind, Oid dboid, uint64 objid, TimestampTz ts)
      Assert(!pgstat_get_kind_info(kind)->fixed_amount);

      entry_ref = pgstat_get_entry_ref(kind, dboid, objid, false, NULL);
+if (rand() % 3 == 0) entry_ref = NULL;
      if (!entry_ref || entry_ref->shared_entry->dropped)

and got several failures like:
--- .../postgresql/src/test/regress/expected/subscription.out 2025-04-25 10:27:32.851554400 -0700
+++ .../postgresql/build/testrun/regress/regress/results/subscription.out 2025-07-20 00:05:05.667903300 -0700
@@ -56,7 +56,7 @@
  SELECT subname, stats_reset IS NULL stats_reset_is_null FROM pg_stat_subscription_stats WHERE subname = 'regress_testsub';
       subname     | stats_reset_is_null
  -----------------+---------------------
- regress_testsub | f
+ regress_testsub | t
  (1 row)

  -- Reset the stats again and check if the new reset_stats is updated.
@@ -68,11 +68,9 @@
  (1 row)

  SELECT :'prev_stats_reset' < stats_reset FROM pg_stat_subscription_stats WHERE subname = 'regress_testsub';
- ?column?
-----------
- t
-(1 row)
-
+ERROR:  syntax error at or near ":"
+LINE 1: SELECT :'prev_stats_reset' < stats_reset FROM pg_stat_subscr...
+

--- .../postgresql/src/test/regress/expected/stats.out    2025-04-25 10:27:36.930322500 -0700
+++ .../postgresql/build/testrun/regress/regress/results/stats.out 2025-07-20 00:05:19.579864900 -0700
@@ -1720,7 +1720,7 @@
  SELECT :my_io_stats_pre_reset > :my_io_stats_post_backend_reset;
   ?column?
  ----------
- t
+ f
  (1 row)
...

Thus, if there is some issue with pgstat_get_entry_ref(), then it should
be specific to subscriptions and come out in that place only (given the
information we have now).

So I still suspect some Windows/concrete animal's peculiarity.

Nagata-san, could you please share the configuration of hamerkop? If it's
running inside VM, what virtualization software is used?

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hamerkop&dt=2025-07-09%2011%3A02%3A23

Best regards.
Alexander

  6. Re: stats.sql might fail due to shared buffers also used by parallel tests

    Yugo Nagata <nagata@sraoss.co.jp> — 2025-07-23T00:55:31Z

    Hello Alexander, 

> Nagata-san, could you please share the configuration of hamerkop? If it's
> running inside VM, what virtualization software is used?
> 
> [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hamerkop&dt=2025-07-09%2011%3A02%3A23

I am not the person in charge of it, so I added the responsible email address to the CC list.
Takatsuka-san, could you please take care of this?

Regards,
Yugo Nagata

-- 
Yugo Nagata <nagata@sraoss.co.jp>

  7. Re: stats.sql might fail due to shared buffers also used by parallel tests

    Alexander Lakhin <exclusion@gmail.com> — 2025-07-23T04:00:00Z

    Hello Kuroda-san,

20.07.2025 11:00, Alexander Lakhin wrote:
>
> Yeah, I made a simple test for GetSystemTimePreciseAsFileTime() and
> confirmed that in my VM it provides sub-microsecond precision. Regarding
> NTP, I think the second failure of this ilk [1] makes this cause close to
> impossible. (Can't wait for the third one to gather more information.)

And here it is [1]:
diff --strip-trailing-cr -U3 c:/build-farm-local/buildroot/HEAD/pgsql/src/test/isolation/expected/stats.out 
c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/isolation/isolation/results/stats.out
--- c:/build-farm-local/buildroot/HEAD/pgsql/src/test/isolation/expected/stats.out 2025-07-22 20:08:30 +0900
+++ c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/isolation/isolation/results/stats.out 2025-07-22 20:30:47 +0900
@@ -3729,7 +3729,7 @@

  name |pg_stat_get_function_calls|total_above_zero|self_above_zero
  --------------+--------------------------+----------------+---------------
-test_stat_func|                         1|t |t
+test_stat_func|                         1|f |f
  (1 row)

Not related to subscriptions this time, but still related to pg_stat and
time measurement.

There was the same looking failure on caiman, which is running on
continuously updated Fedora: [2].

I could not reproduce that one either, but suspected the OS kernel:
It had 6.14.0-0.rc3.20250219git6537cfb395f3.31.fc43.x86_64 at the moment
of the failure and updated to 6.14.0-0.rc4.36.fc43.x86_64 on 2025-02-27.
There was no failures of this kind since then.

So I think we could observe such anomalies if, say, the OS kernel can't
read system clock in time (stalls for a millisecond when accessing it)...

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hamerkop&dt=2025-07-22%2011%3A02%3A15
[2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=caiman&dt=2025-02-23%2006%3A54%3A54

Best regards,
Alexander

  8. Re: [Buildfarm:84] Re: stats.sql might fail due to shared buffers also used by parallel tests

    TAKATSUKA Haruka <harukat@sraoss.co.jp> — 2025-07-23T05:48:51Z

    Hello Alexander, 

On Wed, 23 Jul 2025 00:55:37 +0000
Yugo Nagata - Buildfarm <buildfarm@ml.sraoss.co.jp> wrote:

> > Nagata-san, could you please share the configuration of hamerkop? If it's
> > running inside VM, what virtualization software is used?

It's vmware ESXi 7.0.3 (21930508).
This Windows enable auto-synchronize with 'time.windows.com'.
VMware Tools 12.1.5 build 20735119 is installed in the VM.

Thanks,
Haruka Takatsuka

> > [1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=hamerkop&dt=2025-07-09%2011%3A02%3A23
> 
> I am not the person in charge of it, so I added the responsible email address to the CC list.
> Takatsuka-san, could you please take care of this?
> 
> Regards,
> Yugo Nagata
> 
> -- 
> Yugo Nagata <nagata@sraoss.co.jp>
> Cache content lost

  9. RE: stats.sql might fail due to shared buffers also used by parallel tests

    Hayato Kuroda (Fujitsu) <kuroda.hayato@fujitsu.com> — 2025-07-23T06:15:57Z

    Dear Alexander,

> And here it is [1]:
> diff --strip-trailing-cr -U3
> c:/build-farm-local/buildroot/HEAD/pgsql/src/test/isolation/expected/stats.ou
> t
> c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/isolation/isolation/res
> ults/stats.out
> ---
> c:/build-farm-local/buildroot/HEAD/pgsql/src/test/isolation/expected/stats.ou
> t 2025-07-22 20:08:30 +0900
> +++
> c:/build-farm-local/buildroot/HEAD/pgsql.build/testrun/isolation/isolation/res
> ults/stats.out 2025-07-22 20:30:47 +0900
> @@ -3729,7 +3729,7 @@
> 
>   name |pg_stat_get_function_calls|total_above_zero|self_above_zero
>   --------------+--------------------------+----------------+---------------
> -test_stat_func|                         1|t |t
> +test_stat_func|                         1|f |f
>   (1 row)
> 
> Not related to subscriptions this time, but still related to pg_stat and
> time measurement.

It looks like for me that we measured the execution time of the function in
millisecond but it was "zero", right?

> So I think we could observe such anomalies if, say, the OS kernel can't
> read system clock in time (stalls for a millisecond when accessing it)...

I also feel like that. But if so, how should we fix tests? We must remove all
stuff which assumes the time is monotonic?

Best regards,
Hayato Kuroda
FUJITSU LIMITED

  10. Re: [Buildfarm:84] Re: stats.sql might fail due to shared buffers also used by parallel tests

    Alexander Lakhin <exclusion@gmail.com> — 2025-07-23T20:00:00Z

    Hello Takatsuka-san,

23.07.2025 08:48, TAKATSUKA Haruka wrote:
> Hello Alexander,
>
> On Wed, 23 Jul 2025 00:55:37 +0000
> Yugo Nagata - Buildfarm<buildfarm@ml.sraoss.co.jp> wrote:
>
>>> Nagata-san, could you please share the configuration of hamerkop? If it's
>>> running inside VM, what virtualization software is used?
> It's vmware ESXi 7.0.3 (21930508).
> This Windows enable auto-synchronize with 'time.windows.com'.
> VMware Tools 12.1.5 build 20735119 is installed in the VM.

Thank you for your prompt response!

I used VirtualBox, not VMWare, when trying to reproduce the issue, maybe
that's the reason why I failed. It looks like VMWare has it's own
specifics related to timekeeping: [1].

Maybe you could try tools.syncTime = "0" by any chance?

There is also an interesting note in VMware Tools 11 docs [2]:
If the clock on the guest operating system is ahead of the clock on the
host, VMware Tools causes the clock on the guest to run more slowly until
the clocks are synchronized.

But still it's hard to say without experimentation whether this can cause
the observed effect.

[1] https://knowledge.broadcom.com/external/article?legacyId=1318
[2] 
https://techdocs.broadcom.com/us/en/vmware-cis/vsphere/tools/11-1-0/vmware-tools-administration-11-1-0/configuring-vmware-tools-components/using-vmware-tools-configuration-utility/enable-periodic-time-synchronization.html

Best regards,
Alexander

  11. Re: [Buildfarm:84] Re: stats.sql might fail due to shared buffers also used by parallel tests

    TAKATSUKA Haruka <harukat@sraoss.co.jp> — 2025-07-24T00:49:13Z

    On Wed, 23 Jul 2025 23:00:00 +0300
Alexander Lakhin <exclusion@gmail.com> wrote:

{snip}
> >>> Nagata-san, could you please share the configuration of hamerkop? If it's
> >>> running inside VM, what virtualization software is used?
> > It's vmware ESXi 7.0.3 (21930508).
> > This Windows enable auto-synchronize with 'time.windows.com'.
> > VMware Tools 12.1.5 build 20735119 is installed in the VM.
> 
> Thank you for your prompt response!
> 
> I used VirtualBox, not VMWare, when trying to reproduce the issue, maybe
> that's the reason why I failed. It looks like VMWare has it's own
> specifics related to timekeeping: [1].
> 
> Maybe you could try tools.syncTime = "0" by any chance?

It has been already tools.syncTime = "0" so far.
I confirmed the following GUI setting.

VM Options
  VMware Tools
    Time "Synchronize guest time with host":  unchecked

Thanks,
Haruka Takatsuka

  12. Re: stats.sql might fail due to shared buffers also used by parallel tests

    Alexander Lakhin <exclusion@gmail.com> — 2025-07-26T09:00:01Z

    Hello Kuroda-san and Takatsuka-san,

24.07.2025 03:49, TAKATSUKA Haruka wrote:
> {snip}
>> Maybe you could try tools.syncTime = "0" by any chance?
> It has been already tools.syncTime = "0" so far.
> I confirmed the following GUI setting.
> ...


23.07.2025 09:15, Hayato Kuroda (Fujitsu) wrote:
> It looks like for me that we measured the execution time of the function in
> millisecond but it was "zero", right?

Yes, my understanding is the same.

>> So I think we could observe such anomalies if, say, the OS kernel can't
>> read system clock in time (stalls for a millisecond when accessing it)...
> I also feel like that. But if so, how should we fix tests? We must remove all
> stuff which assumes the time is monotonic?

 From what Takatsuka-san shared on hamerkop's configuration, I still
suspect there could be some platform specifics there. I've found another
interesting reading on the subject, which describes effects of CPU
pressure and mentions other low-level parameters, e. g.
monitor_control.virtual_rdtsc: [1].

Probably there could be some experiments performed there to measure the
maximum timer resolution (e. g. with a simple program attached).

I also observed a failure of pg_stat_statements on ARMv7 device in the past:
--- .../contrib/pg_stat_statements/expected/entry_timestamp.out 2024-04-11 07:20:32.563588101 +0300
+++ .../contrib/pg_stat_statements/results/entry_timestamp.out 2024-04-15 11:16:00.217396694 +0300
@@ -45,7 +45,7 @@
  WHERE query LIKE '%STMTTS%';
   total | minmax_plan_zero | minmax_exec_zero | minmax_stats_since_after_ref | stats_since_after_ref
  -------+------------------+------------------+------------------------------+-----------------------
-     2 |                0 |                0 |                            0 |                     0
+     2 |                0 |                1 |                            0 |                     0
  (1 row)

with clocksource =  32k_counter, which gave me the maximum resolution
0.030517 sec.

So if to choose fixing tests, then it's not clear to me, what lowest timer
resolution to consider acceptable.

[1] https://www.vmware.com/docs/vmware_timekeeping

Best regards,
Alexander