MIME-Version: 1.0
From: James Pang <jamespang886@gmail.com>
Date: Wed, 25 Jun 2025 11:15:08 +0800
Message-ID: 
 <CAHgTRfdDkiX5bLRCYhrP18kFJjcvs1eHvL+jUtX1Ep-Y3=cFVg@mail.gmail.com>
Subject: many sessions waiting DataFileRead and extend
To: pgsql-performance@lists.postgresql.org
Content-Type: multipart/alternative; boundary="000000000000c7f87a06385cdadc"
Archived-At: 
 <https://www.postgresql.org/message-id/CAHgTRfdDkiX5bLRCYhrP18kFJjcvs1eHvL%2BjUtX1Ep-Y3%3DcFVg%40mail.gmail.com>
Precedence: bulk

--000000000000c7f87a06385cdadc
Content-Type: text/plain; charset="UTF-8"

   pgv14, RHEL8, xfs , we suddenly see tens of sessions waiting on
"DataFileRead" and "extend", it last about 2 seconds(based on
pg_stat_activity query) , during the waiting time, "%sys" cpu increased to
80% , but from "iostat" , no high iops and io read/write latency increased
either.
   many sessions were running same "DELETE FROM xxxx" in parallel waiting
on "extend" and "DataFileRead", there are triggers in this table "After
delete" to insert/delete other tables in the tigger.

time                                                 wait_event
    count(sessions)
 2025-06-24 18:00:11.687245+00 | DataFileFlush           |     1
 2025-06-24 18:00:11.687245+00 | DataFileWrite            |     1
 2025-06-24 18:00:11.687245+00 | PgSleep                    |     1
 2025-06-24 18:00:11.687245+00 | DataFileExtend          |     7
 2025-06-24 18:00:11.687245+00 | ProcArrayGroupUpdate |     1
 2025-06-24 18:00:11.687245+00 | WALWrite                    |     5
 2025-06-24 18:00:11.687245+00 | extend                         |    55
 2025-06-24 18:00:11.687245+00 | DataFileRead              |    45
 2025-06-24 18:00:11.687245+00 | DataFilePrefetch         |     2

Thanks,

James

--000000000000c7f87a06385cdadc
Content-Type: text/html; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable

<div dir=3D"ltr">=C2=A0 =C2=A0pgv14, RHEL8, xfs , we suddenly see tens of s=
essions waiting on &quot;DataFileRead&quot; and &quot;extend&quot;, it last=
 about 2 seconds(based on pg_stat_activity query) , during the waiting time=
, &quot;%sys&quot; cpu increased to 80% , but from &quot;iostat&quot; , no =
high iops and io read/write latency increased either.=C2=A0=C2=A0<div>=C2=
=A0 =C2=A0many sessions were running same &quot;DELETE FROM xxxx&quot; in p=
arallel waiting on &quot;extend&quot; and &quot;DataFileRead&quot;, there a=
re triggers in this table &quot;After delete&quot; to insert/delete other t=
ables in the tigger.=C2=A0</div><div><br><div>time=C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =
=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=
=A0wait_event=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 count(=
sessions)</div><div>=C2=A02025-06-24 18:00:11.687245+00 | DataFileFlush=C2=
=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 1<br>=C2=A02025-06-24=
 18:00:11.687245+00 | DataFileWrite=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 | =C2=A0 =C2=A0 1<br>=C2=A02025-06-24 18:00:11.687245+00 | PgSleep=C2=
=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0=
 =C2=A0 1<br>=C2=A02025-06-24 18:00:11.687245+00 | DataFileExtend=C2=A0 =C2=
=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 7<br>=C2=A02025-06-24 18:00:11.687=
245+00 | ProcArrayGroupUpdate | =C2=A0 =C2=A0 1<br>=C2=A02025-06-24 18:00:1=
1.687245+00 | WALWrite=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0 =C2=A0 | =C2=A0 =C2=A0 5<br>=C2=A02025-06-24 18:00:11.687245+00 =
| extend=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=
=A0 =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A055<br>=C2=A02025-06-24 18:00:11.6872=
45+00 | DataFileRead=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 | =C2=
=A0 =C2=A045<br>=C2=A02025-06-24 18:00:11.687245+00 | DataFilePrefetch=C2=
=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0| =C2=A0 =C2=A0 2<br><div>=C2=A0</div></div>=
</div><div>Thanks,</div><div><br></div><div>James=C2=A0</div></div>

--000000000000c7f87a06385cdadc--