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 1uUhdy-007I1t-EJ for pgsql-performance@arkaria.postgresql.org; Thu, 26 Jun 2025 08:07:38 +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 1uUhdw-009Ycb-E6 for pgsql-performance@arkaria.postgresql.org; Thu, 26 Jun 2025 08:07:37 +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 1uUhdv-009YcS-Qa for pgsql-performance@lists.postgresql.org; Thu, 26 Jun 2025 08:07:36 +0000 Received: from mail-ed1-x530.google.com ([2a00:1450:4864:20::530]) by makus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (Exim 4.96) (envelope-from ) id 1uUhdt-0044LY-1z for pgsql-performance@lists.postgresql.org; Thu, 26 Jun 2025 08:07:35 +0000 Received: by mail-ed1-x530.google.com with SMTP id 4fb4d7f45d1cf-6099d89a19cso1304779a12.2 for ; Thu, 26 Jun 2025 01:07:33 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20230601; t=1750925250; x=1751530050; darn=lists.postgresql.org; h=references:to:cc:in-reply-to:date:subject:mime-version:message-id :from:from:to:cc:subject:date:message-id:reply-to; bh=x0CCSqyhcfGX3apsQqRgkDIwiGSqcEFUY4gwVj2tYdc=; b=eBtDx1SxksJvv6HEQP6oLQqMLrKmdH6bh6SC4rcdUS7QrwJVefE3V8UsCW+oTl8ijJ nBmT9EDeVkhezpth+aqNiMU14M6Mpr+ZrmudTUIb86tin3TZcegir7E+qv6eyVSkaU4u z590T9iBsdSVtLyvRC38OGaYoX7TfQWWD35Bkweh5K+BhA1UM5ZUG8F8ZB+YcPstkgBJ 9DBkmITzZkg6pYhrpW3FgNmdu1lR8eBtWOJzlvDeQb7Lbv0tmvuoXC0vbxSDdUd8WbQW lnsFpO3V+orUt7WWOvamvsM6PuMM1DRD13USKR2n2hjrR4Eu9RwePIf+bW0kg29Hm7Dn PqPg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1750925250; x=1751530050; h=references:to:cc:in-reply-to:date:subject:mime-version:message-id :from:x-gm-message-state:from:to:cc:subject:date:message-id:reply-to; bh=x0CCSqyhcfGX3apsQqRgkDIwiGSqcEFUY4gwVj2tYdc=; b=oncnRjVebvunQdfe54I7QwM/qN0xMtUsfKRE58n+trD/WdDODk4kb86zJupyTrT+Ed 52hEpdKB3iD2nLMjS0+RWwgC7ICUzakHX5qsHTiW3wCvtWtHfeZ2+KrskWjnxAB5HDAg x62YYyvbTItjg9+X30s3f1BoWDl61k76mFtHGEi2V6K7P4yhVn1VFYj1nahRLqHWnnMU 7bsV4LZ8mJvlPTCR4k9Z158uusPKR8ACYk3JdQ5HecdKLor1E3hHUTlZRFP3Bo8KtEny T+PvkLY9sDkf9oWeEjfCJ3X9fb8JkmcsjFEAcF0IWL3DVslusw2+PGwMXZudxd2+kyv4 eOsw== X-Forwarded-Encrypted: i=1; AJvYcCW7Q4WxaRMXogZoh5bUOn2qBhcD/SaIe6CbI/F90PFAzZK+KW8ZQb8PqqAq4h8ZQW1dgU4IlKOdYStJVSXsi2tWXg==@lists.postgresql.org X-Gm-Message-State: AOJu0YzUxTnixbnM9fc/VMDtTojjiDrV06cptb4IxXyJyjNkr5Sm29ov A0TLFXXoA8TjlAejVgt7L/n/CfGHE2/Ntbwwn2ZULEj6IEi30itPYGxoWszQXw== X-Gm-Gg: ASbGncuokUjbQ5icjVe0vKUADREmwSC6GPTp5bH9qUxj8MWMSxWkHZ46So34oA0Iaty MAr1/p4ES11tftREyw5a5sGn6LDtux/WLMShnPBSKh7iPn2XCX7kurT1wBtQPoxv9vjWmQIMTR1 gfCPVnky0H9iFY6diJ3dMKfDIEtfNVIr7+DuhRWpycOt9GFtM2v4nXkkSUn2pOKReLUx7yxKpjg LA+1r6mzbm3cs2PJ4ZDSLCL0YYSGrB5g6IFsXGJC8ed1eLSsrdshTmYYugqTZB+yXxmiC2eyblD /vLdjdQ1qnX7JHOUL704hG+i6/5HEdwxtN7GQpzbkBTgG7za6+gmyv2prCXGBJPMhcIs0V+2mBg ctDpagrejThHeVkqdaIUG5cY0B6cLBd+e4glPZyPecrMD8Vkyoiq7g3adO/i66z3h1X8ViEhqIq xGwRNWV+xtz8wXQxyHDm9+jA== X-Google-Smtp-Source: AGHT+IFw1SkoLkaD3nZtYJcITaxlJehqjU5aBiwY8dPIq3d+5pNI16G1xXzI7bozhjthJNwUrzvmIA== X-Received: by 2002:a05:6402:2103:b0:60c:39e4:93e6 with SMTP id 4fb4d7f45d1cf-60c4d3a42efmr5342172a12.24.1750925249867; Thu, 26 Jun 2025 01:07:29 -0700 (PDT) Received: from smtpclient.apple (2001-1c04-0681-7700-c8e5-498e-3967-d25c.cable.dynamic.v6.ziggo.nl. [2001:1c04:681:7700:c8e5:498e:3967:d25c]) by smtp.gmail.com with ESMTPSA id 4fb4d7f45d1cf-60c2f484513sm3564873a12.63.2025.06.26.01.07.28 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Thu, 26 Jun 2025 01:07:29 -0700 (PDT) From: Frits Hoogland Message-Id: <230B5D2C-5F98-49AB-8E2A-6C5FEB9F27DE@gmail.com> Content-Type: multipart/alternative; boundary="Apple-Mail=_C4625584-0FA8-4E3F-95AC-BAF132A8E28A" Mime-Version: 1.0 (Mac OS X Mail 16.0 \(3826.600.51.1.1\)) Subject: Re: many sessions waiting DataFileRead and extend Date: Thu, 26 Jun 2025 10:07:18 +0200 In-Reply-To: Cc: Laurenz Albe , pgsql-performance@lists.postgresql.org To: James Pang References: <66879d8bd44148f2ef1dcde1eff056e6c671306e.camel@cybertec.at> X-Mailer: Apple Mail (2.3826.600.51.1.1) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --Apple-Mail=_C4625584-0FA8-4E3F-95AC-BAF132A8E28A Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 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.=20 For WAL, sessions write to the wal buffer (separate from the postgres = buffer cache), and need to write to disk upon commit with default = settings. Please mind wal writes commonly are performed from the wal = writer, 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 description 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 cache. However, the buffer = cache is a finite amount of buffers, and eventually 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 only knows and = sees it's performing a read or write request. These reads and writes are performed to the operating system, and the = operating system essentially applies the same technique for performance = as postgres does: if an IO is done buffered (which is default), it = creates as 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 the postgres process without actually needing to = perform an actual read request to the operating system. For buffered = writes, these are always done to the linux page cache, and written back = by kernel writer threads asynchronously. (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 on commonly the setting = vm.dirty_ratio, which is a percentage from available memory (commonly = misunderstood as taken from total memory).=20 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 ability 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 the operating system, it is perfectly possible = to perceived that from postgres 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 wait 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: >=20 > 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 = checkpoint scheduled in longer time.=20 >=20 > Thanks, >=20 > James=20 >=20 >=20 > 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? >>=20 >> 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). >> 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 = tasks in kernel space, and what that is, using perf report. >>=20 >> Frits Hoogland >>=20 >>=20 >>=20 >>=20 >>> On 26 Jun 2025, at 04:32, James Pang > wrote: >>>=20 >>> thans for you suggestions, we have iowait from sar command too, copy = here, checking with infra team not found abnormal IO activities either. =20= >>> 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 >>>=20 >>> Thanks, >>>=20 >>> James=20 >>>=20 >>> 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 >>>>=20 >>>>=20 >>>> > On 25 Jun 2025, at 07:59, Laurenz Albe > wrote: >>>> >=20 >>>> > 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. >>>> >=20 >>>> > 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, iowait 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 postgres = 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 using = iowait. The time in IO wait can't be used calculate any IO facts. >>>>=20 >>>> 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. >>>> >=20 >>>> > Check if you have transparent hugepages enabled: >>>> >=20 >>>> > cat /sys/kernel/mm/transparent_hugepage/enabled >>>> >=20 >>>> > If they are enabled, disable them and see if it makes a = difference. >>>> >=20 >>>> > 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. >>>> >=20 >>>> >> 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.=20 >>>> >=20 >>>> > One thing that almost certainly would improve your situation is = to run 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 is 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 = makes 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 = spent cpu (system/kernel) time. >>>>=20 >>>> What sounds suspicious is that you indicate you indicate there is = you see no signficant change in the amount of IO in iostat. >>>>=20 >>>> 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.=20 >>>> Limits for any disk are IOPS (operations per second) and MBPS = (megabytes per second -> bandwdith). >>>>=20 >>>> 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. >>>>=20 >>>> 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 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 events. >>>>=20 >>>> Not a simple answer, but this is how it works. >>>>=20 >>>> So I would suggest checking the difference between the situation of = when it's doing the same which is considered well performing versus = badly performing. >>>>=20 >>>>=20 >>>> >=20 >>>> > Yours, >>>> > Laurenz Albe >>>> >=20 >>>> >=20 >>>>=20 >>=20 --Apple-Mail=_C4625584-0FA8-4E3F-95AC-BAF132A8E28A Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8 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 settings. Please mind wal writes = commonly are performed from the wal writer, 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 = description 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 cache. However, the buffer cache is a finite amount of buffers, = and eventually 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 only knows and sees it's performing a read or = write request.

These reads and writes are = performed to the operating system, and the operating system essentially = applies the same technique for performance as postgres does: if an IO is = done buffered (which is default), it creates as 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 the postgres = process without actually needing to perform an actual read request to = the operating system. For buffered writes, these are always done to the = linux page cache, and written back by kernel writer threads = asynchronously. (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 on commonly the setting vm.dirty_ratio, which = is a percentage from available 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 ability 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 the = operating system, it is perfectly possible to perceived that from = postgres 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 wait 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 <jamespang886@gmail.com> 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 checkpoint scheduled in longer = time. 

Thanks,

James = ;


Frits = 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
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 during 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 tasks in kernel space, and what that is, using perf = report.

Frits = Hoogland




On 26 Jun 2025, at 04:32, James = Pang <jamespang886@gmail.com> = 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&= nbsp;

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:
>
> 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, = iowait 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 postgres = 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 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:
>
>  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 = run 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 is = 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 = makes 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 = spent 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 (megabytes = 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 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 events.

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 = performing.


>
> Yours,
> Laurenz Albe
>
>



= --Apple-Mail=_C4625584-0FA8-4E3F-95AC-BAF132A8E28A--