Feedback-ID: id4a34324:Fastmail
Date: Mon, 10 Feb 2025 18:53:01 -0500
From: Andres Freund <andres@anarazel.de>
To: Jelte Fennema-Nio <postgres@jeltef.nl>
Cc: Tom Lane <tgl@sss.pgh.pa.us>, torikoshia <torikoshia@oss.nttdata.com>, 
	pgsql-hackers@postgresql.org, rjuju123@gmail.com, Bruce Momjian <bruce@momjian.us>
Subject: Re: RFC: Allow EXPLAIN to Output Page Fault Information
Message-ID: <dfnb7me4hsbdb6mxlosxcfvh4xjdk5qoy42piuu2ahblwmocyf@ma3bh552myoe>
References: <CAM6-o=BE=oewSsdNKrbbNjR2muzQR49STXsuta+Wpq6CSyxTag@mail.gmail.com>
 <2c9d6eaf26df17bec13bb03bf1e9bcbb@oss.nttdata.com>
 <CAGECzQRvcLx44N3zd_DGCjY02XX4AqXX8mq4BiS8C9Froy+Jhg@mail.gmail.com>
 <CAGECzQQdc-k=M2fMCKa98kVZntc=6d3rpd6edt8Qs45cayfUeQ@mail.gmail.com>
 <myw76agwrlmisvamwbfl6ibxgwh5glzitydiwnfmtb5aui232i@274yxxtnbnsp>
 <2035079.1739124342@sss.pgh.pa.us>
 <CAGECzQTm6oEEY4yO_FO0ZBtUuJX+pYiXhw2GPPRMzq_5DP5_fQ@mail.gmail.com>
 <edvo7bpgi7rcthj7btsduleep4j6dcnsx3a2aqrwmybetttmkw@g5chr66cckg6>
 <CAGECzQTydZ33miLd=KdbfrV17RowRGBwQrS28hZ0i6+YhetYgg@mail.gmail.com>
 <mzjytadtjqv4knvwukppaol5zx2qzt2bkuqvjlo4rjawvhn4ql@qmdf64qkmxjo>
MIME-Version: 1.0
Content-Type: text/plain; charset=utf-8
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <mzjytadtjqv4knvwukppaol5zx2qzt2bkuqvjlo4rjawvhn4ql@qmdf64qkmxjo>
Archived-At: <https://www.postgresql.org/message-id/dfnb7me4hsbdb6mxlosxcfvh4xjdk5qoy42piuu2ahblwmocyf%40ma3bh552myoe>
Precedence: bulk

Hi,

On 2025-02-10 18:30:56 -0500, Andres Freund wrote:
> On 2025-02-10 23:52:17 +0100, Jelte Fennema-Nio wrote:
> > On Mon, 10 Feb 2025 at 14:31, Andres Freund <andres@anarazel.de> wrote:
> > > But this will also not work with AIO w/ Buffered IO. Which we hope to use much
> > > more commonly.
> >
> > To be clear, here you mean worker based AIO right? Because it would
> > work with io_uring based AIO, right?
>
> I mostly meant worker based AIO, yes. I haven't checked how accurately these
> are kept for io_uring. I would hope they are...

It does look like it is tracked.


> > > If suddenly I have to reimplement something like this to work with worker
> > > based IO, it'll certainly take longer to get to AIO.
> >
> > I totally understand. But in my opinion it would be completely fine to
> > decide that these new IO stats are simply not available for worker
> > based IO. Just like they're not available for Windows either with this
> > patch.
>
> The thing is that you'd often get completely misleading stats. Some of the IO
> will still be done by the backend itself, so there will be a non-zero
> value. But it will be a significant undercount, because the asynchronously
> executed IO won't be tracked (if worker mode is used).

<clear cache>

postgres[985394][1]=# SHOW io_method ;
┌───────────┐
│ io_method │
├───────────┤
│ worker    │
└───────────┘
(1 row)

postgres[985394][1]=# EXPLAIN ANALYZE SELECT count(*) FROM manyrows ;
┌──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│                                                        QUERY PLAN                                                        │
├──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ Aggregate  (cost=17906.00..17906.01 rows=1 width=8) (actual time=199.494..199.494 rows=1 loops=1)                        │
│   Buffers: shared read=5406                                                                                              │
│   I/O Timings: shared read=57.906                                                                                        │
│   ->  Seq Scan on manyrows  (cost=0.00..15406.00 rows=1000000 width=0) (actual time=0.380..140.671 rows=1000000 loops=1) │
│         Buffers: shared read=5406                                                                                        │
│         I/O Timings: shared read=57.906                                                                                  │
│ Planning:                                                                                                                │
│   Buffers: shared hit=41 read=12                                                                                         │
│   Storage I/O: read=192 times write=0 times                                                                              │
│ Planning Time: 1.869 ms                                                                                                  │
│ Execution Time: 199.554 ms                                                                                               │
└──────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘


<clear cache>


postgres[1014152][1]=# SHOW io_method ;
┌───────────┐
│ io_method │
├───────────┤
│ io_uring  │
└───────────┘
(1 row)


postgres[1014152][1]=# EXPLAIN ANALYZE SELECT count(*) FROM manyrows ;
┌─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┐
│                                                       QUERY PLAN                                                        │
├─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┤
│ Aggregate  (cost=17906.00..17906.01 rows=1 width=8) (actual time=111.591..111.593 rows=1 loops=1)                       │
│   Buffers: shared read=5406                                                                                             │
│   I/O Timings: shared read=14.342                                                                                       │
│   ->  Seq Scan on manyrows  (cost=0.00..15406.00 rows=1000000 width=0) (actual time=0.161..70.843 rows=1000000 loops=1) │
│         Buffers: shared read=5406                                                                                       │
│         I/O Timings: shared read=14.342                                                                                 │
│ Planning:                                                                                                               │
│   Buffers: shared hit=41 read=12                                                                                        │
│   Storage I/O: read=192 times write=0 times                                                                             │
│ Planning Time: 1.768 ms                                                                                                 │
│ Execution:                                                                                                              │
│   Storage I/O: read=86496 times write=0 times                                                                           │
│ Execution Time: 111.670 ms                                                                                              │
└─────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┘


Independent to of this, it's probably not good that we're tracking shared
buffer hits after io combining, if I interpret this correctly... That looks to
be an issue in master, not just the AIO branch.

Greetings,

Andres Freund