Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1uUiRQ-007UIa-Ui for pgsql-performance@arkaria.postgresql.org; Thu, 26 Jun 2025 08:58:45 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1uUiRO-00A5tL-Up for pgsql-performance@arkaria.postgresql.org; Thu, 26 Jun 2025 08:58:43 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1uUiRO-00A5tA-CK for pgsql-performance@lists.postgresql.org; Thu, 26 Jun 2025 08:58:43 +0000 Received: from mail-yw1-x112e.google.com ([2607:f8b0:4864:20::112e]) by makus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (Exim 4.96) (envelope-from ) id 1uUiRM-0044pL-0W for pgsql-performance@lists.postgresql.org; Thu, 26 Jun 2025 08:58:42 +0000 Received: by mail-yw1-x112e.google.com with SMTP id 00721157ae682-70e3980757bso7176427b3.1 for ; Thu, 26 Jun 2025 01:58:40 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20230601; t=1750928319; x=1751533119; darn=lists.postgresql.org; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:from:to:cc:subject:date:message-id:reply-to; bh=5YXzwqhy2OWnyRvWRN1rMmpVZoC1Kp02RCAtrrpJ3EU=; b=e4khehu8H1F08hrv5bGk87bLco1DOIslNyvXd01PfGUJrmti7LYYJF3bdgX91LUwz+ hesQ9S+avR+i41K6irWx8FAlMuurn1OXOc0h+HCZP2F9oZl+I6jAQlCXbc3+zP7/f54C S8oIDrddhxCvv0kGLIHBowu/jlrYNGvyxrsQ2EJZPjup7iJhe9udXWKUrGigs0TFcyvO RgMjKpuNMfjpdi4dQcjufqTT2/dpJZ4CJzAD7SiGu3SwJ2KFeipGB3h5HhhtKCOoEfSA Lco0A5sedyIoy31CUew41BR2zlPOyIAp53gZWJWCUaDnD2/fw3q3NNQ4/yi86mYtToj+ GfJg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1750928319; x=1751533119; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:x-gm-message-state:from:to:cc:subject:date:message-id :reply-to; bh=5YXzwqhy2OWnyRvWRN1rMmpVZoC1Kp02RCAtrrpJ3EU=; b=uJW/IJbJiCNo6JsBudHg6uogt5SzGQjcgdcwpgMmZ3Tg37ym/psFT4PqSRB4MXPPE4 AIZasxWeHr2E2H8BAArV2pjMr2R8m4Ul4f877oqt/iZ/sx+yA6JUUzvYq8lQV06JqCH6 0O6PLo2398nzy45XonV2fIcg3qOlsYgfLmMduN0FaNqwamicOroPkMPFVIuWxU6Gd9ow ISkjLm2bxc5UgYiinjKdhfCQqGhfsKx454xg1pZzn2s5lJ/YaqqBfWAiH8CTlYAJLnoD WvO3btWxhdMQ94X3ZUTpTZakqNCYrehzKJ/KHctrUgoltWNQo+VoX87WK5MIAFXSPXDZ W6tw== X-Forwarded-Encrypted: i=1; AJvYcCUX9xNYa7cIg4Jk37de6YC9sjvomoHLnZFOKgnD7F0UMeMKcIkRw6hQsP3W3cfKQ9A4UIBRiOTMLkedFUmVO76PRA==@lists.postgresql.org X-Gm-Message-State: AOJu0Yx5IKUCxmzMYNxCp37XHJg1BsZFrEuUZLUzcQ2Um1hR2w/UBr3p g25JpVHSAcKmLR0ddgmrKlu54p8BA+POsF3/OTi2blwz+HSj0PQdYxwGPGg7aZ1EQNmCdriPnsn T6STt+z60CsRSRNY1y8pANvculGot1zI= X-Gm-Gg: ASbGnct/xHreb5/PBn+qT6L98lLzY2hKrxwdSIox6+cyW+WxvRsmi4gR43lL89WsJsV P/iAwh/bZj8bmliuO78zp3zJEgN2uEhteRBxqn90XSrNC5DUuwsiHFhNnjO+bvLeuIgr1Yo4I24 VxCIkqXtWvDlmZez7BlEKMHoASep9LpHdx2GOtVZorA9wynX0S/+BTtQ== X-Google-Smtp-Source: AGHT+IGiZ+D4yD81KCi6+d6PAjva2bmYBLPPH9K7i+6e8hTxCGtP48OdcCMXdPO65EgDmx1xH/Jr0pEp3wO/CC0EzBM= X-Received: by 2002:a05:690c:4d43:b0:713:ff19:d046 with SMTP id 00721157ae682-7150947f1a6mr40137617b3.6.1750928318681; Thu, 26 Jun 2025 01:58:38 -0700 (PDT) MIME-Version: 1.0 References: <66879d8bd44148f2ef1dcde1eff056e6c671306e.camel@cybertec.at> <230B5D2C-5F98-49AB-8E2A-6C5FEB9F27DE@gmail.com> In-Reply-To: <230B5D2C-5F98-49AB-8E2A-6C5FEB9F27DE@gmail.com> From: James Pang Date: Thu, 26 Jun 2025 16:58:27 +0800 X-Gm-Features: Ac12FXxqroaOBseg_Y1BLD-givCdwm1lZmuMAknYkrTdBnGkZAnqpyQzV7erkdc Message-ID: Subject: Re: many sessions waiting DataFileRead and extend To: Frits Hoogland Cc: Laurenz Albe , pgsql-performance@lists.postgresql.org Content-Type: multipart/alternative; boundary="000000000000765811063875c45f" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --000000000000765811063875c45f Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable thanks for you explaination, from Postgresql perspective, is it possible to see bgwriter,or checkpointer blocking backend process reading/wrting ? or vice versa ? Thanks, James Frits Hoogland =E6=96=BC 2025=E5=B9=B46=E6=9C=88= 26=E6=97=A5=E9=80=B1=E5=9B=9B =E4=B8=8B=E5=8D=884:07=E5=AF=AB=E9=81=93=EF= =BC=9A > Postgres lives as a process in linux, and keeps its own cache, and tries > to use that as much as possible for data. This is postgres shared buffers= , > commonly called the buffer cache. > > For WAL, sessions write to the wal buffer (separate from the postgres > buffer cache), and need to write to disk upon commit with default setting= s. > Please mind wal writes commonly are performed from the wal writer, but ca= n > be done from backends too. > > (slightly simplified) When postgres processing needs to read data for > processing, it will have to do that in the postgres buffer cache and use = it > from the cache if it can find the requested buffer, and otherwise it will > have to read it from the operating system. When changes are made to data = or > metadata (such as hint bits set), the change is made to the buffer (and > before that a description of this is placed in the wal buffer). As long a= s > there are buffers available, it will perform the data changes in the buff= er > in the buffer cache. However, the buffer cache is a finite amount of > buffers, and eventually changed buffers must make it to disk (which happe= ns > upon checkpoint, and for other reasons). The important part here is that > checkpointer, bgwriter and backends all perform reads and writes. That is > what postgres sees, it only knows and sees it's performing a read or writ= e > request. > > These reads and writes are performed to the operating system, and the > operating system essentially applies the same technique for performance a= s > postgres does: if an IO is done buffered (which is default), it creates a= s > a page in the linux page cache. For reads, if the read request happens to > find the pages it requests in the linux page cache, it can serve it to th= e > postgres process without actually needing to perform an actual read reque= st > to the operating system. For buffered writes, these are always done to th= e > linux page cache, and written back by kernel writer threads asynchronousl= y. > (this is the essence, there is much more detail). Obviously, the amount > linux can cache is dependent on the amount of cache and whether the pages > for the request are in the linux page cache. For writes, it's dependent o= n > commonly the setting vm.dirty_ratio, which is a percentage from *availabl= e > *memory (commonly misunderstood as taken from total memory). > > Now, the point I am trying to make: from the postgres point of view, it's > impossible to understand whether a read or write request was served from = OS > cache by the operating system, or needed physical IO. However, the abilit= y > of the operating system to serve from cache is dependent upon the > availability of free and file memory essentially, and therefore upon > general usage of the operating system. Any action on the operating system > that needs a significant amount of memory will impact the availability of > available memory and therefore lower the amount of memory available to > caching. This all in all means that if you do something significant on th= e > operating system, it is perfectly possible to perceived that from postgre= s > as sudden drastic change in performance of IO latency, whilst from the > postgres perspective you didn't do anything different. > > Now circling back to you concrete question: if such a thing happens, that > linux all of a sudden needs to do physical IOs and let's your request wai= t > on that, instead doing logical IO, where your session has to wait on too, > but significantly less time, you might all of a sudden see all kind of IO > related waits, which you are encountering too in the case of the fast > logical IOs, but taking soo little time that you don't see it. This is > where wait event occurence and time accumulation would significantly help= , > currently we can only sample the wait event state, and thus much of that = is > never seen, and thus not known. > > *Frits Hoogland* > > > > > On 26 Jun 2025, at 08:47, James Pang wrote: > > we faced this issue 3 times this week, each time last only 2 seconds, > so not easy to run perf in peak business time to capture that, anyway, I > will try. before that, I want to understand if "os page cache" or "pg > buffer cache" can contribute to the wait_event time "extend" and > "DataFileRead", or bgwriter ,checkpoint flushing data to disk can impact > that too ? we enable bgwriter , and we see checkpointer get scheduled by > "wal" during the time, so I just increased max_wal_size to make checkpoin= t > scheduled in longer time. > > Thanks, > > James > > > Frits Hoogland =E6=96=BC 2025=E5=B9=B46=E6=9C= =8826=E6=97=A5=E9=80=B1=E5=9B=9B =E4=B8=8B=E5=8D=882:40=E5=AF=AB=E9=81=93= =EF=BC=9A > >> Okay. So it's a situation that is reproducable. >> And like was mentioned, the system time (percentage) is very high. >> Is this a physical machine, or a virtual machine? >> >> The next thing to do, is use perf to record about 20 seconds or so durin= g >> a period of time when you see this behavior (perf record -g, taking the >> backtrace with it). >> This records (samples) the backtraces of on cpu tasks, from which you >> then can derive what they are doing, for which you should see lots of ta= sks >> in kernel space, and what that is, using perf report. >> >> *Frits Hoogland* >> >> >> >> >> On 26 Jun 2025, at 04:32, James Pang wrote: >> >> thans for you suggestions, we have iowait from sar command too, copy >> here, checking with infra team not found abnormal IO activities either. >> 02:00:01 PM CPU %usr %nice %sys %iowait %irq %soft %steal >> %guest %gnice %idle >> 02:00:03 PM all 15.92 0.00 43.02 0.65 0.76 2.56 >> 0.00 0.00 0.00 37.09 >> 02:00:03 PM 0 17.59 0.00 46.73 1.01 0.50 0.50 >> 0.00 0.00 0.00 33.67 >> 02:00:03 PM 1 9.50 0.00 61.50 0.50 0.50 1.00 >> 0.00 0.00 0.00 27.00 >> 02:00:03 PM 2 20.71 0.00 44.44 1.01 0.51 0.51 >> 0.00 0.00 0.00 32.83 >> 02:00:03 PM 3 14.00 0.00 51.50 2.00 1.00 1.00 >> 0.00 0.00 0.00 30.50 >> 02:00:03 PM 4 6.57 0.00 52.53 0.51 0.51 3.54 >> 0.00 0.00 0.00 36.36 >> 02:00:03 PM 5 10.20 0.00 49.49 1.02 1.53 0.00 >> 0.00 0.00 0.00 37.76 >> 02:00:03 PM 6 27.64 0.00 41.21 0.50 0.50 0.50 >> 0.00 0.00 0.00 29.65 >> 02:00:03 PM 7 9.05 0.00 50.75 0.50 1.01 0.50 >> 0.00 0.00 0.00 38.19 >> 02:00:03 PM 8 12.18 0.00 49.75 0.51 0.51 0.51 >> 0.00 0.00 0.00 36.55 >> 02:00:03 PM 9 13.00 0.00 9.50 0.50 1.50 15.50 >> 0.00 0.00 0.00 60.00 >> 02:00:03 PM 10 15.58 0.00 46.23 0.00 0.50 0.50 >> 0.00 0.00 0.00 37.19 >> 02:00:03 PM 11 20.71 0.00 10.10 0.00 1.01 14.14 >> 0.00 0.00 0.00 54.04 >> 02:00:03 PM 12 21.00 0.00 37.00 0.50 1.00 1.00 >> 0.00 0.00 0.00 39.50 >> 02:00:03 PM 13 13.57 0.00 45.73 1.01 1.01 1.01 >> 0.00 0.00 0.00 37.69 >> 02:00:03 PM 14 18.18 0.00 39.39 1.01 0.51 0.51 0.00 >> 0.00 0.00 40.40 >> 02:00:03 PM 15 14.00 0.00 49.50 0.50 0.50 3.50 0.00 >> 0.00 0.00 32.00 >> 02:00:03 PM 16 19.39 0.00 39.80 1.02 1.53 0.51 0.00 >> 0.00 0.00 37.76 >> 02:00:03 PM 17 16.75 0.00 45.18 1.52 1.02 2.54 0.00 >> 0.00 0.00 32.99 >> 02:00:03 PM 18 12.63 0.00 50.00 0.00 1.01 0.00 0.00 >> 0.00 0.00 36.36 >> 02:00:03 PM 19 5.56 0.00 82.32 0.00 0.00 0.00 0.00 >> 0.00 0.00 12.12 >> 02:00:03 PM 20 15.08 0.00 48.24 0.50 0.50 3.52 0.00 >> 0.00 0.00 32.16 >> 02:00:03 PM 21 17.68 0.00 9.09 0.51 1.52 13.64 0.00 >> 0.00 0.00 57.58 >> 02:00:03 PM 22 13.13 0.00 43.94 0.51 0.51 0.51 0.00 >> 0.00 0.00 41.41 >> 02:00:03 PM 23 14.07 0.00 42.71 0.50 0.50 0.50 0.00 >> 0.00 0.00 41.71 >> 02:00:03 PM 24 13.13 0.00 41.92 1.01 0.51 0.51 0.00 >> 0.00 0.00 42.93 >> 02:00:03 PM 25 16.58 0.00 47.74 0.50 1.01 0.50 0.00 >> 0.00 0.00 33.67 >> 02:00:03 PM 26 16.58 0.00 46.73 0.50 1.01 0.50 0.00 >> 0.00 0.00 34.67 >> 02:00:03 PM 27 45.50 0.00 54.50 0.00 0.00 0.00 0.00 >> 0.00 0.00 0.00 >> 02:00:03 PM 28 6.06 0.00 32.32 0.00 0.51 13.13 0.00 >> 0.00 0.00 47.98 >> 02:00:03 PM 29 13.93 0.00 44.78 1.00 1.00 0.50 0.00 >> 0.00 0.00 38.81 >> 02:00:03 PM 30 11.56 0.00 57.79 0.00 0.50 1.01 0.00 >> 0.00 0.00 29.15 >> 02:00:03 PM 31 33.85 0.00 9.23 0.51 1.54 0.51 0.00 >> 0.00 0.00 54.36 >> 02:00:03 PM 32 30.15 0.00 41.71 0.50 0.50 1.51 0.00 >> 0.00 0.00 25.63 >> >> Thanks, >> >> James >> >> Frits Hoogland =E6=96=BC 2025=E5=B9=B46=E6=9C= =8825=E6=97=A5=E9=80=B1=E4=B8=89 =E4=B8=8B=E5=8D=8810:27=E5=AF=AB=E9=81=93= =EF=BC=9A >> >>> >>> >>> > On 25 Jun 2025, at 07:59, Laurenz Albe >>> wrote: >>> > >>> > On Wed, 2025-06-25 at 11:15 +0800, James Pang wrote: >>> >> 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. >>> > >>> > Run "sar -P all 1" and see if "%iowait" is high. >>> I would (strongly) advise against the use of iowait as an indicator. It >>> is a kernel approximation of time spent in IO from which cannot be use = used >>> in any sensible way other than possibly you're doing IO. >>> First of all, iowait is not a kernel state, and therefore it's taken >>> from idle. This means that if there is no, or too little, idle time, io= wait >>> that should be there is gone. >>> Second, the calculation to transfer idle time to iowait is done for >>> synchronous IO calls only. Which currently is not a problem for postgre= s >>> because it uses exactly that, but in the future it might. >>> Very roughly put, what the kernel does is keep a counter of tasks >>> currently in certain system IO calls, and then try to express that usin= g >>> iowait. The time in IO wait can't be used calculate any IO facts. >>> >>> In that sense, it puts it in the same area as the load figure: >>> indicative, but mostly useless because it doesn't give you any facts ab= out >>> what it is expressing. >>> > >>> > Check if you have transparent hugepages enabled: >>> > >>> > cat /sys/kernel/mm/transparent_hugepage/enabled >>> > >>> > If they are enabled, disable them and see if it makes a difference. >>> > >>> > I am only guessing here. >>> Absolutely. Anything that is using signficant amounts of memory and is >>> not created to take advantage of transparent hugepages will probably >>> experience more downsides from THP than it helps. >>> > >>> >> 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. >>> > >>> > One thing that almost certainly would improve your situation is to ru= n >>> fewer >>> > concurrent statements, for example by using a reasonably sized >>> connection pool. >>> This is true if the limits of the IO device, or anything towards to IO >>> device or devices are hit. >>> And in general, high "%sys", alias lots of time spent in kernel mode >>> alias system time indicates lots of time spent in system calls, which i= s >>> what the read and write calls in postgres are. >>> Therefore these figures suggest blocking for IO, for which Laurenz' >>> advise to lower the amount of concurrent sessions doing IO in general m= akes >>> sense. >>> A more nuanced analysis: if IO requests get queued, these will wait in >>> 'D' state in linux, which by definition is off cpu, and thus do not spe= nt >>> cpu (system/kernel) time. >>> >>> What sounds suspicious is that you indicate you indicate there is you >>> see no signficant change in the amount of IO in iostat. >>> >>> In order to understand this, you will have to first carefully find the >>> actual IO physical IO devices that you are using for postgres IO. >>> In current linux this can be tricky, depending on how the hardware or >>> virtual machine looks like, and how the disks are arranged in linux. >>> What you need to determine is which actual disk devices are used, and >>> what their limits are. >>> Limits for any disk are IOPS (operations per second) and MBPS (megabyte= s >>> per second -> bandwdith). >>> >>> There is an additional thing to realize, which makes this really tricky= : >>> postgres for common IO uses buffered IO. >>> Buffered IO means any read or write will use the linux buffercache, and >>> read or writes can be served from the buffercache if possible. >>> >>> So in your case, if you managed to make the database perform identical >>> read or write requests, this could result in a difference of amounts of >>> read and write IOs served from the cache, which can make an enormous >>> amounts of difference for how fast these requests are served. If someho= w >>> you managed to make the operating system choose to use the physical IO >>> path, you will see significant amounts time spent on that, which will h= ave >>> IO related wait events. >>> >>> Not a simple answer, but this is how it works. >>> >>> So I would suggest checking the difference between the situation of whe= n >>> it's doing the same which is considered well performing versus badly >>> performing. >>> >>> >>> > >>> > Yours, >>> > Laurenz Albe >>> > >>> > >>> >>> >> > --000000000000765811063875c45f Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable
thanks for you explaination,=C2=A0 from Postgresql perspec= tive, is it possible to see bgwriter,or checkpointer blocking backend proce= ss=C2=A0 reading/wrting ?=C2=A0 or vice versa ?

Thanks,<= /div>

James=C2=A0

Frits Hoogl= and <frits.hoogland@gmail.co= m> =E6=96=BC 2025=E5=B9=B46=E6=9C=8826=E6=97=A5=E9=80=B1=E5=9B=9B = =E4=B8=8B=E5=8D=884:07=E5=AF=AB=E9=81=93=EF=BC=9A
Postgres lives as a process in linux= , and keeps its own cache, and tries to use that as much as possible for da= ta. This is postgres shared buffers, commonly called the buffer cache.=C2= =A0

For WAL, sessions write to the wal buffer (separate from t= he postgres buffer cache), and need to write to disk upon commit with defau= lt settings. Please mind wal writes commonly are performed from the wal wri= ter, but can be done from backends too.

(slightly = simplified) When postgres processing needs to read data for processing, it = will have to do that in the postgres buffer cache and use it from the cache= if it can find the requested buffer, and otherwise it will have to read it= from the operating system. When changes are made to data or metadata (such= as hint bits set), the change is made to the buffer (and before that a des= cription of this is placed in the wal buffer). As long as there are buffers= available, it will perform the data changes in the buffer in the buffer ca= che. However, the buffer cache is a finite amount of buffers, and eventuall= y changed buffers must make it to disk (which happens upon checkpoint, and = for other reasons). The important part here is that checkpointer, bgwriter = and backends all perform reads and writes. That is what postgres sees, it o= nly knows and sees it's performing a read or write request.
<= br>
These reads and writes are performed to the operating system,= and the operating system essentially applies the same technique for perfor= mance as postgres does: if an IO is done buffered (which is default), it cr= eates as a page in the linux page cache. For reads, if the read request hap= pens to find the pages it requests in the linux page cache, it can serve it= to the postgres process without actually needing to perform an actual read= request to the operating system. For buffered writes, these are always don= e to the linux page cache, and written back by kernel writer threads asynch= ronously. (this is the essence, there is much more detail). Obviously, the = amount linux can cache is dependent on the amount of cache and whether the = pages for the request are in the linux page cache. For writes, it's dep= endent on commonly the setting vm.dirty_ratio, which is a percentage from <= i>available memory (commonly misunderstood as taken from total memory).= =C2=A0

Now, the point I am trying to make: from th= e postgres point of view, it's impossible to understand whether a read = or write request was served from OS cache by the operating system, or neede= d physical IO. However, the ability of the operating system to serve from c= ache is dependent upon the availability of free and file memory essentially= , and therefore upon general usage of the operating system. Any action on t= he operating system that needs a significant amount of memory will impact t= he availability of available memory and therefore lower the amount of memor= y available to caching. This all in all means that if you do something sign= ificant on the operating system, it is perfectly possible to perceived that= from postgres as sudden drastic change in performance of IO latency, whils= t from the postgres perspective you didn't do anything different.
=

Now circling back to you concrete question: if such a t= hing happens, that linux all of a sudden needs to do physical IOs and let&#= 39;s your request wait on that, instead doing logical IO, where your sessio= n has to wait on too, but significantly less time, you might all of a sudde= n see all kind of IO related waits, which you are encountering too in the c= ase of the fast logical IOs, but taking soo little time that you don't = see it. This is where wait event occurence and time accumulation would sign= ificantly help, currently we can only sample the wait event state, and thus= much of that is never seen, and thus not known.

<= div>
Frits Hoogland

<= /div>


On 26 Jun 2025, at 08:47, James Pan= g <jamespang= 886@gmail.com> wrote:

=C2=A0 =C2=A0we= faced this issue 3 times this week, each time last only 2 seconds, so not = easy to run perf in peak business time to capture that, anyway, I will try.= before that, I want to understand if "os page cache" or "pg= buffer cache" can contribute to the wait_event time "extend"= ; and "DataFileRead", or bgwriter ,checkpoint flushing data to di= sk can impact that too ?=C2=A0 we enable bgwriter , and we see checkpointer= get scheduled by "wal" during the time, so I just increased max_= wal_size to make checkpoint scheduled in longer time.=C2=A0

<= div>Thanks,

James=C2=A0


Fr= its Hoogland <frits.hoogland@gmail.com> =E6=96=BC 2025=E5=B9=B46=E6=9C=8826=E6= =97=A5=E9=80=B1=E5=9B=9B =E4=B8=8B=E5=8D=882:40=E5=AF=AB=E9=81=93=EF=BC=9A<= br>
Okay. So it= 's a situation that is reproducable.
And like was mentioned, the sy= stem time (percentage) is very high.
Is this a physical machine, = or a virtual machine?

The next thing to do, is use= perf to record about 20 seconds or so during a period of time when you see= this behavior (perf record -g, taking the backtrace with it).
Th= is records (samples) the backtraces of on cpu tasks, from which you then ca= n derive what they are doing, for which you should see lots of tasks in ker= nel space, and what that is, using perf report.

Frits Hoogland




On 26 Jun 2025, at 04:32, James Pan= g <jamespang= 886@gmail.com> wrote:

thans for you s= uggestions, we have iowait from sar command too, copy here, checking with i= nfra team not found abnormal IO activities either.=C2=A0=C2=A0
02:00:01= PM =C2=A0CPU =C2=A0 =C2=A0%usr =C2=A0 %nice =C2=A0 =C2=A0%sys %iowait =C2= =A0 =C2=A0%irq =C2=A0 %soft =C2=A0%steal =C2=A0%guest =C2=A0%gnice =C2=A0 %= idle
02:00:03 PM =C2=A0all=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A015.92 =C2=A0= =C2=A00.00 =C2=A0 43.02 =C2=A0 =C2=A00.65 =C2=A0 =C2=A00.76 =C2=A0 =C2=A02= .56 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 37.09
0= 2:00:03 PM =C2=A0 =C2=A00=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A017.59 =C2=A0 =C2= =A00.00 =C2=A0 46.73 =C2=A0 =C2=A01.01 =C2=A0 =C2=A00.50 =C2=A0 =C2=A00.50 = =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 33.67
02:00= :03 PM =C2=A0 =C2=A01=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 9.50=C2=A0 =C2=A0 = =C2=A00.00 =C2=A0 61.50 =C2=A0 =C2=A00.50 =C2=A0 =C2=A00.50 =C2=A0 =C2=A01.= 00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 27.00
02= :00:03 PM =C2=A0 =C2=A02=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 20.71 =C2=A0 =C2= =A00.00 =C2=A0 44.44 =C2=A0 =C2=A01.01 =C2=A0 =C2=A00.51 =C2=A0 =C2=A00.51 = =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 32.83
02:00= :03 PM =C2=A0 =C2=A03=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A014.00 =C2=A0 =C2=A00= .00 =C2=A0 51.50 =C2=A0 =C2=A02.00 =C2=A0 =C2=A01.00 =C2=A0 =C2=A01.00 =C2= =A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 30.50
02:00:03= PM =C2=A0 =C2=A04=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 6.57=C2=A0 =C2=A0 =C2= =A00.00 =C2=A0 52.53 =C2=A0 =C2=A00.51 =C2=A0 =C2=A00.51 =C2=A0 =C2=A03.54 = =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 36.36
02:00= :03 PM =C2=A0 =C2=A05=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 10.20 =C2=A0 =C2=A0= 0.00 =C2=A0 49.49 =C2=A0 =C2=A01.02 =C2=A0 =C2=A01.53 =C2=A0 =C2=A00.00 =C2= =A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 37.76
02:00:03= PM =C2=A0 =C2=A06=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 27.64 =C2=A0 =C2=A00.0= 0 =C2=A0 41.21 =C2=A0 =C2=A00.50 =C2=A0 =C2=A00.50 =C2=A0 =C2=A00.50 =C2=A0= =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 29.65
02:00:03 PM= =C2=A0 =C2=A07=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 9.05 =C2=A0 =C2=A00.00 = =C2=A0 50.75 =C2=A0 =C2=A00.50 =C2=A0 =C2=A01.01 =C2=A0 =C2=A00.50 =C2=A0 = =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 38.19
02:00:03 PM = =C2=A0 =C2=A08=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 12.18 =C2=A0 =C2=A00.00 = =C2=A0 49.75 =C2=A0 =C2=A00.51 =C2=A0 =C2=A00.51 =C2=A0 =C2=A00.51 =C2=A0 = =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 36.55
02:00:03 PM = =C2=A0 =C2=A09=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 13.00 =C2=A0 =C2=A00.00 = =C2=A0 =C2=A09.50 =C2=A0 =C2=A00.50 =C2=A0 =C2=A01.50 =C2=A0 15.50 =C2=A0 = =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 60.00
02:00:03 PM = =C2=A0 10=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A015.58 =C2=A0 =C2=A00.00 =C2=A0 4= 6.23 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.50 =C2=A0 =C2=A00.50 =C2=A0 =C2=A00.0= 0 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 37.19
02:00:03 PM =C2=A0 11= =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 20.71 =C2=A0 =C2=A00.00 =C2=A0 10.10 =C2= =A0 =C2=A00.00 =C2=A0 =C2=A01.01 =C2=A0 14.14 =C2=A0 =C2=A00.00 =C2=A0 =C2= =A00.00 =C2=A0 =C2=A00.00 =C2=A0 54.04
02:00:03 PM =C2=A0 12=C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A021.00 =C2=A0 =C2=A00.00 =C2=A0 37.00 =C2=A0 =C2=A00= .50 =C2=A0 =C2=A01.00 =C2=A0 =C2=A01.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00= =C2=A0 =C2=A00.00 =C2=A0 39.50
02:00:03 PM =C2=A0 13=C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A013.57 =C2=A0 =C2=A00.00 =C2=A0 45.73 =C2=A0 =C2=A01.01 =C2= =A0 =C2=A01.01 =C2=A0 =C2=A01.01 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0= =C2=A00.00 =C2=A0 37.69
02:00:03 PM =C2=A0 14 =C2=A0 18.18 =C2=A0 =C2= =A00.00 =C2=A0 39.39 =C2=A0 =C2=A01.01 =C2=A0 =C2=A00.51 =C2=A0 =C2=A00.51 = =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 40.40
02:00= :03 PM =C2=A0 15 =C2=A0 14.00 =C2=A0 =C2=A00.00 =C2=A0 49.50 =C2=A0 =C2=A00= .50 =C2=A0 =C2=A00.50 =C2=A0 =C2=A03.50 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00= =C2=A0 =C2=A00.00 =C2=A0 32.00
02:00:03 PM =C2=A0 16 =C2=A0 19.39 =C2= =A0 =C2=A00.00 =C2=A0 39.80 =C2=A0 =C2=A01.02 =C2=A0 =C2=A01.53 =C2=A0 =C2= =A00.51 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 37.76<= br>02:00:03 PM =C2=A0 17 =C2=A0 16.75 =C2=A0 =C2=A00.00 =C2=A0 45.18 =C2=A0= =C2=A01.52 =C2=A0 =C2=A01.02 =C2=A0 =C2=A02.54 =C2=A0 =C2=A00.00 =C2=A0 = =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 32.99
02:00:03 PM =C2=A0 18 =C2=A0 1= 2.63 =C2=A0 =C2=A00.00 =C2=A0 50.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A01.01 =C2= =A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0= 36.36
02:00:03 PM =C2=A0 19 =C2=A0 =C2=A05.56 =C2=A0 =C2=A00.00 =C2=A0 = 82.32 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.= 00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 12.12
02:00:03 PM =C2=A0 2= 0 =C2=A0 15.08 =C2=A0 =C2=A00.00 =C2=A0 48.24 =C2=A0 =C2=A00.50 =C2=A0 =C2= =A00.50 =C2=A0 =C2=A03.52 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A0= 0.00 =C2=A0 32.16
02:00:03 PM =C2=A0 21 =C2=A0 17.68 =C2=A0 =C2=A00.00 = =C2=A0 =C2=A09.09 =C2=A0 =C2=A00.51 =C2=A0 =C2=A01.52 =C2=A0 13.64 =C2=A0 = =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 57.58
02:00:03 PM = =C2=A0 22 =C2=A0 13.13 =C2=A0 =C2=A00.00 =C2=A0 43.94 =C2=A0 =C2=A00.51 =C2= =A0 =C2=A00.51 =C2=A0 =C2=A00.51 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0= =C2=A00.00 =C2=A0 41.41
02:00:03 PM =C2=A0 23 =C2=A0 14.07 =C2=A0 =C2= =A00.00 =C2=A0 42.71 =C2=A0 =C2=A00.50 =C2=A0 =C2=A00.50 =C2=A0 =C2=A00.50 = =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 41.71
02:00= :03 PM =C2=A0 24 =C2=A0 13.13 =C2=A0 =C2=A00.00 =C2=A0 41.92 =C2=A0 =C2=A01= .01 =C2=A0 =C2=A00.51 =C2=A0 =C2=A00.51 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00= =C2=A0 =C2=A00.00 =C2=A0 42.93
02:00:03 PM =C2=A0 25 =C2=A0 16.58 =C2= =A0 =C2=A00.00 =C2=A0 47.74 =C2=A0 =C2=A00.50 =C2=A0 =C2=A01.01 =C2=A0 =C2= =A00.50 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 33.67<= br>02:00:03 PM =C2=A0 26 =C2=A0 16.58 =C2=A0 =C2=A00.00 =C2=A0 46.73 =C2=A0= =C2=A00.50 =C2=A0 =C2=A01.01 =C2=A0 =C2=A00.50 =C2=A0 =C2=A00.00 =C2=A0 = =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 34.67
02:00:03 PM =C2=A0 27 =C2=A0 4= 5.50 =C2=A0 =C2=A00.00 =C2=A0 54.50 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2= =A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0= =C2=A00.00
02:00:03 PM =C2=A0 28 =C2=A0 =C2=A06.06 =C2=A0 =C2=A00.00 = =C2=A0 32.32 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.51 =C2=A0 13.13 =C2=A0 =C2=A0= 0.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 47.98
02:00:03 PM =C2=A0= 29 =C2=A0 13.93 =C2=A0 =C2=A00.00 =C2=A0 44.78 =C2=A0 =C2=A01.00 =C2=A0 = =C2=A01.00 =C2=A0 =C2=A00.50 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2= =A00.00 =C2=A0 38.81
02:00:03 PM =C2=A0 30 =C2=A0 11.56 =C2=A0 =C2=A00.0= 0 =C2=A0 57.79 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.50 =C2=A0 =C2=A01.01 =C2=A0= =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 29.15
02:00:03 PM= =C2=A0 31 =C2=A0 33.85 =C2=A0 =C2=A00.00 =C2=A0 =C2=A09.23 =C2=A0 =C2=A00.= 51 =C2=A0 =C2=A01.54 =C2=A0 =C2=A00.51 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 = =C2=A0 =C2=A00.00 =C2=A0 54.36
02:00:03 PM =C2=A0 32 =C2=A0 30.15 =C2=A0= =C2=A00.00 =C2=A0 41.71 =C2=A0 =C2=A00.50 =C2=A0 =C2=A00.50 =C2=A0 =C2=A01= .51 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 =C2=A00.00 =C2=A0 25.63
<= /div>

Thanks,

James=C2=A0
=

= Frits Hoogland <frits.hoogland@gmail.com> =E6=96=BC 2025=E5=B9=B46=E6=9C=8825= =E6=97=A5=E9=80=B1=E4=B8=89 =E4=B8=8B=E5=8D=8810:27=E5=AF=AB=E9=81=93=EF=BC= =9A


> On 25 Jun 2025, at 07:59, Laurenz Albe <laurenz.albe@cybertec.at> wrote:<= br> >
> On Wed, 2025-06-25 at 11:15 +0800, James Pang wrote:
>> pgv14, RHEL8, xfs , we suddenly see tens of sessions waiting on &q= uot;DataFileRead" and
>> "extend", it last about 2 seconds(based on pg_stat_activ= ity query) , during the
>> waiting time, "%sys" cpu increased to 80% , but from &qu= ot;iostat" , no high iops and
>> io read/write latency increased either.
>
> Run "sar -P all 1" and see if "%iowait" is high. I would (strongly) advise against the use of iowait as an indicator. It is = a kernel approximation of time spent in IO from which cannot be use used in= any sensible way other than possibly you're doing IO.
First of all, iowait is not a kernel state, and therefore it's taken fr= om idle. This means that if there is no, or too little, idle time, iowait t= hat should be there is gone.
Second, the calculation to transfer idle time to iowait is done for synchro= nous IO calls only. Which currently is not a problem for postgres because i= t uses exactly that, but in the future it might.
Very roughly put, what the kernel does is keep a counter of tasks currently= in certain system IO calls, and then try to express that using iowait. The= time in IO wait can't be used calculate any IO facts.

In that sense, it puts it in the same area as the load figure: indicative, = but mostly useless because it doesn't give you any facts about what it = is expressing.
>
> Check if you have transparent hugepages enabled:
>
>=C2=A0 cat /sys/kernel/mm/transparent_hugepage/enabled
>
> If they are enabled, disable them and see if it makes a difference. >
> I am only guessing here.
Absolutely. Anything that is using signficant amounts of memory and is not = created to take advantage of transparent hugepages will probably experience= more downsides from THP than it helps.
>
>> many sessions were running same "DELETE FROM xxxx" in pa= rallel waiting on "extend"
>> and "DataFileRead", there are triggers in this table &qu= ot;After delete" to insert/delete
>> other tables in the tigger.
>
> One thing that almost certainly would improve your situation is to run= fewer
> concurrent statements, for example by using a reasonably sized connect= ion pool.
This is true if the limits of the IO device, or anything towards to IO devi= ce or devices are hit.
And in general, high "%sys", alias lots of time spent in kernel m= ode alias system time indicates lots of time spent in system calls, which i= s what the read and write calls in postgres are.
Therefore these figures suggest blocking for IO, for which Laurenz' adv= ise to lower the amount of concurrent sessions doing IO in general makes se= nse.
A more nuanced analysis: if IO requests get queued, these will wait in '= ;D' state in linux, which by definition is off cpu, and thus do not spe= nt cpu (system/kernel) time.

What sounds suspicious is that you indicate you indicate there is you see n= o signficant change in the amount of IO in iostat.

In order to understand this, you will have to first carefully find the actu= al IO physical IO devices that you are using for postgres IO.
In current linux this can be tricky, depending on how the hardware or virtu= al machine looks like, and how the disks are arranged in linux.
What you need to determine is which actual disk devices are used, and what = their limits are.
Limits for any disk are IOPS (operations per second) and MBPS (megabytes pe= r second -> bandwdith).

There is an additional thing to realize, which makes this really tricky: po= stgres for common IO uses buffered IO.
Buffered IO means any read or write will use the linux buffercache, and rea= d or writes can be served from the buffercache if possible.

So in your case, if you managed to make the database perform identical read= or write requests, this could result in a difference of amounts of read an= d write IOs served from the cache, which can make an enormous amounts of di= fference for how fast these requests are served. If somehow you managed to = make the operating system choose to use the physical IO path, you will see = significant amounts time spent on that, which will have IO related wait eve= nts.

Not a simple answer, but this is how it works.

So I would suggest checking the difference between the situation of when it= 's doing the same which is considered well performing versus badly perf= orming.


>
> Yours,
> Laurenz Albe
>
>



--000000000000765811063875c45f--