Test 026_overwrite_contrecord fails on very slow machines (under Valgrind)

From: Alexander Lakhin <exclusion(at)gmail(dot)com>
To: pgsql-hackers <pgsql-hackers(at)postgresql(dot)org>
Cc: Andres Freund <andres(at)anarazel(dot)de>
Subject: Test 026_overwrite_contrecord fails on very slow machines (under Valgrind)
Date: 2023-10-12 11:00:00
Message-ID: e6b64481-3a7c-0046-47d2-94bf582a006d@gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

Hello hackers,

While investigating the recent skink failure [1], I've reproduced this
failure under Valgrind on a slow machine and found that this happens due to
the last checkpoint recorded in the segment 2, that is removed in the test:
The failure log contains:
2023-10-10 19:10:08.212 UTC [2144251][startup][:0] LOG:  invalid checkpoint record
2023-10-10 19:10:08.214 UTC [2144251][startup][:0] PANIC:  could not locate a valid checkpoint record

The line above:
[19:10:02.701](318.076s) ok 1 - 000000010000000000000001 differs from 000000010000000000000002
tells us about the duration of previous operations (> 5 mins).

src/test/recovery/tmp_check/log/026_overwrite_contrecord_primary.log:
2023-10-10 19:04:50.149 UTC [1845798][postmaster][:0] LOG:  database system is ready to accept connections
...
2023-10-10 19:09:49.131 UTC [1847585][checkpointer][:0] LOG: checkpoint starting: time
...
2023-10-10 19:10:02.058 UTC [1847585][checkpointer][:0] LOG: checkpoint complete: ... lsn=0/*2093980*, redo lsn=0/1F62760

And here is one more instance of this failure [2]:
2022-11-08 02:35:25.826 UTC [1614205][][:0] PANIC:  could not locate a valid checkpoint record
2022-11-08 02:35:26.164 UTC [1612967][][:0] LOG:  startup process (PID 1614205) was terminated by signal 6: Aborted

src/test/recovery/tmp_check/log/026_overwrite_contrecord_primary.log:
2022-11-08 02:29:57.961 UTC [1546469][][:0] LOG:  database system is ready to accept connections
...
2022-11-08 02:35:10.764 UTC [1611737][][2/10:0] LOG:  statement: SELECT pg_walfile_name(pg_current_wal_insert_lsn())
2022-11-08 02:35:11.598 UTC [1546469][][:0] LOG:  received immediate shutdown request

The next successful run after the failure [1] shows the following duration:
[21:34:48.556](180.150s) ok 1 - 000000010000000000000001 differs from 000000010000000000000002
And the last successful run:
[03:03:53.892](126.206s) ok 1 - 000000010000000000000001 differs from 000000010000000000000002

So to fail on the test, skink should perform at least twice slower than
usual, and may be it's an extraordinary condition indeed, but on the other
hand, may be increase checkpoint_timeout as already done in several tests
(015_promotion_pages, 038_save_logical_slots_shutdown, 039_end_of_wal, ...).

[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2023-10-10%2017%3A10%3A11
[2] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=skink&dt=2022-11-07%2020%3A27%3A11

Best regards,
Alexander

Responses

Browse pgsql-hackers by date

  From Date Subject
Next Message Amit Kapila 2023-10-12 11:14:09 pg_upgrade's interaction with pg_resetwal seems confusing
Previous Message Suraj Kharage 2023-10-12 10:42:18 Re: Server crash on RHEL 9/s390x platform against PG16