Content-Type: multipart/alternative;
 boundary="------------zjzYceLsLcfRhAEFsgTJRPVb"
Message-ID: <96abefe8-fa72-41f5-8840-0517125c24e3@gmail.com>
Date: Sun, 13 Apr 2025 09:00:01 +0300
MIME-Version: 1.0
User-Agent: Mozilla Thunderbird
Subject: Re: AIO v2.5
From: Alexander Lakhin <exclusion@gmail.com>
To: Andres Freund <andres@anarazel.de>
Cc: Noah Misch <noah@leadboat.com>, pgsql-hackers@postgresql.org,
 Thomas Munro <thomas.munro@gmail.com>, Heikki Linnakangas <hlinnaka@iki.fi>,
 Robert Haas <robertmhaas@gmail.com>,
 Jakub Wartak <jakub.wartak@enterprisedb.com>,
 Jelte Fennema-Nio <postgres@jeltef.nl>, Antonin Houska <ah@cybertec.at>
References: <20250329212929.a6.nmisch@google.com>
 <usbwzckj7q3jhfx3ann3nrfnukmupbs35axvq5zfyeo6nvrzrm@onjhxs2du4st>
 <7s6fclfekpcxoaaorwrq67v4vmgixf2dcjcgznuj7vxs3ie3wq@okqbi5vabqbx>
 <20250401151159.51.nmisch@google.com>
 <kas47e54inkpgnirnr3txm5zywxkjobhbx6466sfaolmkjtnlu@xuucqvkchksl>
 <uc62i6vi5gd4bi6wtjj5poadqxolgy55e7ihkmf3mthjegb6zl@zqo7xez7sc2r>
 <q4hmkmjqxcrfx3xav5fgxwzelvwwlm6qshagvc45fbugtikf7v@hygsuz24g3lb>
 <20250402001324.e4.nmisch@google.com>
 <3fhulsvzks4khqahl6tngcnuda7pyrrl7223tmjh2x2spralm3@iisldh6pcowy>
 <8160688e-db8e-4d7d-a7e7-ff366adf9717@gmail.com>
 <4nervqmqplfr23jrjvkp5tsumi6qgouhgjqlubf7ujrudw2epb@6mszddainl4u>
 <6a6756a0-bad5-4ee5-a591-c763af289940@gmail.com>
Content-Language: en-US
In-Reply-To: <6a6756a0-bad5-4ee5-a591-c763af289940@gmail.com>
Archived-At: 
 <https://www.postgresql.org/message-id/96abefe8-fa72-41f5-8840-0517125c24e3%40gmail.com>
Precedence: bulk

This is a multi-part message in MIME format.
--------------zjzYceLsLcfRhAEFsgTJRPVb
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit

Hello Andres,

07.04.2025 22:10, Alexander Lakhin wrote:
>> I ran it for a while in a VM, it hasn't triggered yet. Neither on xfs nor on
>> tmpfs.
>
> Before sharing the script I tested it on two my machines, but I had
> anticipated that the error can be hard to reproduce. Will try to reduce
> the reproducer...

I've managed to reduce it to the following:
ulimit -n 4096

echo "
fsync = off
autovacuum = off

checkpoint_timeout = 30s

io_max_concurrency = 10
io_method = io_uring
" >> $PGDATA/postgresql.conf

pg_ctl -l server.log start

for i in `seq 1000`; do
   numjobs=$((20 + $RANDOM % 60))
   echo "iteration $i (jobs: $numjobs)"
   date
   for ((j=1;j<=numjobs;j++)); do
     (
       createdb db$j;
       for ((n=1;n<=50;n++)); do
         cat << EOF | psql -d db$j -a >>/dev/null 2>&1
DROP TABLE IF EXISTS tenk1;
CREATE TABLE tenk1 (
     unique1     int4,
     unique2     int4,
     two         int4,
     four        int4,
     ten         int4,
     twenty      int4,
     hundred     int4,
     thousand    int4,
     twothousand int4,
     fivethous   int4,
     tenthous    int4,
     odd         int4,
     even        int4,
     stringu1    name,
     stringu2    name,
     string4     name
);
COPY tenk1 FROM '.../src/test/regress/data/tenk.data';
EOF
       done;
     ) &
   done
   wait

   for ((j=1;j<=numjobs;j++)); do dropdb db$j & done
   wait
   grep -A3 -E '(ERROR|could not read blocks )' server.log && break;
done

pg_ctl stop

It fails for me as below:
iteration 13 (jobs: 25)
Sun Apr 13 05:31:47 AM UTC 2025
iteration 14 (jobs: 67)
Sun Apr 13 05:31:50 AM UTC 2025
dropdb: error: database removal failed: ERROR:  could not read blocks 0..0 in file "global/1213": Operation canceled
2025-04-13 05:31:58.930 UTC [1153451] LOG:  could not read blocks 0..0 in file "global/1213": Operation canceled
2025-04-13 05:31:58.930 UTC [1153451] CONTEXT:  completing I/O on behalf of process 1153456
2025-04-13 05:31:58.930 UTC [1153451] STATEMENT:  DROP DATABASE db5;
2025-04-13 05:31:58.930 UTC [1153456] ERROR:  could not read blocks 0..0 in file "global/1213": Operation canceled
2025-04-13 05:31:58.930 UTC [1153456] STATEMENT:  DROP DATABASE db6;
2025-04-13 05:31:58.931 UTC [1034758] LOG:  checkpoint complete: wrote 3 buffers (0.0%), wrote 0 SLRU buffers; 0 WAL 
file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.002 s; sync files=0, longest=0.000 s, 
average=0.000 s; distance=18 kB, estimate=458931 kB; lsn=16/54589E08, redo lsn=16/54586F88
2025-04-13 05:31:58.931 UTC [1034758] LOG:  checkpoint starting: immediate force wait


I reproduced this error on three different machines (all are running
Ubuntu 24.04, two with kernel version 6.8, one with 6.11), with PGDATA
located on tmpfs.

Best regards,
Alexander Lakhin
Neon (https://neon.tech)
--------------zjzYceLsLcfRhAEFsgTJRPVb
Content-Type: text/html; charset=UTF-8
Content-Transfer-Encoding: 8bit

<!DOCTYPE html>
<html>
  <head>
    <meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
  </head>
  <body>
    <div class="moz-cite-prefix">Hello Andres,<br>
      <br>
      07.04.2025 22:10, Alexander Lakhin wrote:<br>
    </div>
    <blockquote type="cite"
      cite="mid:6a6756a0-bad5-4ee5-a591-c763af289940@gmail.com"> <span
      style="white-space: pre-wrap">
</span>
      <blockquote type="cite"
cite="mid:4nervqmqplfr23jrjvkp5tsumi6qgouhgjqlubf7ujrudw2epb@6mszddainl4u">
        <blockquote type="cite"> </blockquote>
        <pre wrap="" class="moz-quote-pre">I ran it for a while in a VM, it hasn't triggered yet. Neither on xfs nor on
tmpfs.
</pre>
      </blockquote>
      <br>
      Before sharing the script I tested it on two my machines, but I
      had<br>
      anticipated that the error can be hard to reproduce. Will try to
      reduce<br>
      the reproducer...<br>
    </blockquote>
    <br>
    I've managed to reduce it to the following:<br>
    ulimit -n 4096<br>
    <br>
    echo "<br>
    fsync = off<br>
    autovacuum = off<br>
    <br>
    checkpoint_timeout = 30s<br>
    <br>
    io_max_concurrency = 10<br>
    io_method = io_uring<br>
    " &gt;&gt; $PGDATA/postgresql.conf<br>
    <br>
    pg_ctl -l server.log start<br>
    <br>
    for i in `seq 1000`; do<br>
      numjobs=$((20 + $RANDOM % 60))<br>
      echo "iteration $i (jobs: $numjobs)"<br>
      date<br>
      for ((j=1;j&lt;=numjobs;j++)); do<br>
        (<br>
          createdb db$j;<br>
          for ((n=1;n&lt;=50;n++)); do<br>
            cat &lt;&lt; EOF | psql -d db$j -a &gt;&gt;/dev/null
    2&gt;&amp;1<br>
    DROP TABLE IF EXISTS tenk1;<br>
    CREATE TABLE tenk1 (<br>
        unique1     int4,<br>
        unique2     int4,<br>
        two         int4,<br>
        four        int4,<br>
        ten         int4,<br>
        twenty      int4,<br>
        hundred     int4,<br>
        thousand    int4,<br>
        twothousand int4,<br>
        fivethous   int4,<br>
        tenthous    int4,<br>
        odd         int4,<br>
        even        int4,<br>
        stringu1    name,<br>
        stringu2    name,<br>
        string4     name<br>
    );<br>
    COPY tenk1 FROM '.../src/test/regress/data/tenk.data';<br>
    EOF<br>
          done;<br>
        ) &amp;<br>
      done<br>
      wait<br>
      <br>
      for ((j=1;j&lt;=numjobs;j++)); do dropdb db$j &amp; done<br>
      wait<br>
      grep -A3 -E '(ERROR|could not read blocks )' server.log &amp;&amp;
    break;<br>
    done<br>
    <br>
    pg_ctl stop<br>
    <br>
    It fails for me as below:<br>
    iteration 13 (jobs: 25)<br>
    Sun Apr 13 05:31:47 AM UTC 2025<br>
    iteration 14 (jobs: 67)<br>
    Sun Apr 13 05:31:50 AM UTC 2025<br>
    dropdb: error: database removal failed: ERROR:  could not read
    blocks 0..0 in file "global/1213": Operation canceled<br>
    2025-04-13 05:31:58.930 UTC [1153451] LOG:  could not read blocks
    0..0 in file "global/1213": Operation canceled<br>
    2025-04-13 05:31:58.930 UTC [1153451] CONTEXT:  completing I/O on
    behalf of process 1153456<br>
    2025-04-13 05:31:58.930 UTC [1153451] STATEMENT:  DROP DATABASE db5;<br>
    2025-04-13 05:31:58.930 UTC [1153456] ERROR:  could not read blocks
    0..0 in file "global/1213": Operation canceled<br>
    2025-04-13 05:31:58.930 UTC [1153456] STATEMENT:  DROP DATABASE db6;<br>
    2025-04-13 05:31:58.931 UTC [1034758] LOG:  checkpoint complete:
    wrote 3 buffers (0.0%), wrote 0 SLRU buffers; 0 WAL file(s) added, 0
    removed, 0 recycled; write=0.002 s, sync=0.001 s, total=0.002 s;
    sync files=0, longest=0.000 s, average=0.000 s; distance=18 kB,
    estimate=458931 kB; lsn=16/54589E08, redo lsn=16/54586F88<br>
    2025-04-13 05:31:58.931 UTC [1034758] LOG:  checkpoint starting:
    immediate force wait<br>
    <span style="font-family:monospace"><br>
    </span><br>
    I reproduced this error on three different machines (all are running<br>
    Ubuntu 24.04, two with kernel version 6.8, one with 6.11), with
    PGDATA<br>
    located on tmpfs.<br>
    <br>
    Best regards,<br>
    Alexander Lakhin<br>
    Neon (<a class="moz-txt-link-freetext" href="https://neon.tech">https://neon.tech</a>)
  </body>
</html>

--------------zjzYceLsLcfRhAEFsgTJRPVb--