Re: Non-reproducible AIO failure - Mailing list pgsql-hackers

On 13/06/2025 11:20 pm, Andres Freund wrote:
> Hi,
>
> On 2025-06-12 12:23:13 -0400, Andres Freund wrote:
>> On 2025-06-12 11:52:31 -0400, Andres Freund wrote:
>>> On 2025-06-12 17:22:22 +0300, Konstantin Knizhnik wrote:
>>>> On 12/06/2025 4:57 pm, Andres Freund wrote:
>>>>> The problem appears to be in that switch between "when submitted, by the IO
>>>>> worker" and "then again by the backend".  It's not concurrent access in the
>>>>> sense of two processes writing to the same value, it's that when switching
>>>>> from the worker updating ->distilled_result to the issuer looking at that, the
>>>>> issuer didn't ensure that no outdated version of ->distilled_result could be
>>>>> used.
>>>>>
>>>>> Basically, the problem is that the worker would
>>>>>
>>>>> 1) set ->distilled_result
>>>>> 2) perform a write memory barrier
>>>>> 3) set ->state to COMPLETED_SHARED
>>>>>
>>>>> and then the issuer of the IO would:
>>>>>
>>>>> 4) check ->state is COMPLETED_SHARED
>>>>> 5) use ->distilled_result
>>>>>
>>>>> The problem is that there currently is no barrier between 4 & 5, which means
>>>>> an outdated ->distilled_result could be used.
>>>>>
>>>>>
>>>>> This also explains why the issue looked so weird - eventually, after fprintfs,
>>>>> after a core dump, etc, the updated ->distilled_result result would "arrive"
>>>>> in the issuing process, and suddenly look correct.
>>>> Thank you very much for explanation.
>>>> Everything seems to be so simple after explanations, that you can not even
>>>> believe that before you think that such behavior can be only caused by
>>>> "black magic" or "OS bug":)
>>> Indeed. For a while I was really starting to doubt my sanity - not helped by
>>> the fact that I'd loose most of the mental context between reproductions (the
>>> problem did not re-occur from Saturday to Wednesday morning...).  What finally
>>> made it clearer was moving the failing assertion to earlier
>>> (pgaio_io_call_complete_local() and shared_buffer_readv_complete_local()), as
>>> that took out a lot of the time in which the problem could occur.
>>>> Certainly using outdated result can explain such behavior.
>>>> But in which particular place we loose read barrier between 4 and 5?
>>>> I see `pgaio_io_wait` which as I expect should be called by backend to wait
>>>> completion of IO.
>>>> And it calls `pgaio_io_was_recycled` to get state and it in turn enforce
>>>> read barrier:
>>>> ```
>>>>
>>>> bool
>>>> pgaio_io_was_recycled(PgAioHandle *ioh, uint64 ref_generation,
>>>> PgAioHandleState *state)
>>>> {
>>>>      *state = ioh->state;
>>>>      pg_read_barrier();
>>>>
>>>>      return ioh->generation != ref_generation;
>>>> }
>>>> ```
>>> Yes, I don't think that path has the issue.
>>>
>>> As far as I can tell the problem only ever happens if we end up reclaiming an
>>> IO while waiting for a free IO handle.
>>>
>>> The known problematic path is
>>> pgaio_io_acquire()
>>> -> pgaio_io_wait_for_free()
>>> -> pgaio_io_reclaim()
>>>
>>> In that path we don't use pgaio_io_was_recycled().  I couldn't find any other
>>> path with the same issue [1].
>>> The issue only happening while waiting for free IO handles is presumably the
>>> reason why it happend in 027_stream_regress.pl, due to the small
>>> shared_buffers used for the test io_max_concurrency is 1, which means we
>>> constantly need to wait for a free IO handles.
>> Armed with that knowledge it turns out to not be too hard to create a repro
>> that fails a lot quicker than multiple days.
>>
>> Starting postgres with
>>
>>    -c io_max_concurrency=1 -c io_combine_limit=1 -c synchronize_seqscans=false -c restart_after_crash=false -c
max_parallel_workers_per_gather=0
>>
>> and creating a test table with:
>>    create table large as select generate_series(1, 100000) a, b from generate_series(1, 100) b;
>>
>> makes the following pgbench fail within seconds for me:
>>    c=16; pgbench -c $c -j $c -M prepared -n -f <(echo "select count(*) FROM large;") -T 1000 -P 10
>>
>> (interestingly at c=8 it takes closer to a minute on average)
>>
>> Adding pg_read_barrier() before the two pgaio_io_reclaim() calls in
>> pgaio_io_wait_for_free() has so far prevented a crash.  I'll leave it running
>> for a while longer, to make sure.
>>
>> We really lack any meaningful stress testing of IO paths, or I suspect we
>> would have found this much earlier.  I wonder if we could add a smaller
>> version of the above, with a small fixed runtime (maybe 3-5s), as a
>> tap test.
> Attached is a patch that fixes the problem for me. Alexander, Konstantin,
> could you verify that it also fixes the problem for you?


I have inspected your patch and from my point of view it adds all 
necessary read barriers and so eliminates the race.
I also ran proposed test during more than 4 hours and the problem is not 
reproduced at my system (without patch it is reproduced after 100 seconds).

It's a little bit strange that pgbench is "stuck" - I have specified 
timeout 10000 seconds (-T 10000) but it didn't stop and continue working 
until 15000 seconds when I have terminated it.
There were no stuck queries: all 16 backends are running queries which 
execution takes about 2 seconds:

progress: 14960.0 s, 7.4 tps, lat 2189.006 ms stddev 133.277, 0 failed
progress: 14970.0 s, 7.3 tps, lat 2113.871 ms stddev 164.008, 0 failed
progress: 14980.0 s, 7.3 tps, lat 2038.736 ms stddev 152.869, 0 failed

Looks like there is yet another race condition now in pgbench:)




>
> Given that it does address the problem for me, I'm inclined to push this
> fairly soon, the barrier is pretty obviously required.
>
> Greetings,
>
> Andres Freund