many_sessions_waiting_extend_Datafileread_but_no_ioload_spike
application/octet-stream
Filename: many_sessions_waiting_extend_Datafileread_but_no_ioload_spike
Type: application/octet-stream
Part: 0
this is another timeslot, Issue summary as below,
we see database session waiting on "extend" and "DataFileRead" suddenly , and database logs show many sessions blocking on extension.then we getting active session spike alert(in our monitoring tool)
from OS tools, sar, top, iostat we did see very high %sys cpu, and many sessions suddenly %cpu is very high too, iowait is low and iostat show read/write delay less than 1ms.
no connection storm(fork)
infra team help check storage, no abnormal IO and IO latency increased either, from top command output, all session %cpu increased a lot ,compared with other peak time.
1.
--database logs show many session suddenly waiting on extend, and many session waiting on "DataFileRead"
2025-06-24 18:00:11.368 xxxx:[1865315]:[4-1]:mbsLOG: process 1865315 still waiting for ExclusiveLock on extension of relation 14658239 of database 16384 after 1000.161 ms
2025-06-24 18:00:11.368 xxxx:mbs@pgaaweb:[1865315]:[5-1]:mbsDETAIL: Process holding the lock: 1748100. Wait queue: 232658, 606235, 1865315, 1939296, 1368901, 2472806, 2072266, 963893, 1304751, 1084094, 875968, 451652, 672314, 1240983, 2085501, 851401, 2043926, 2522611, 889816, 191663, 1090944, 536057, 1810868, 1240510, 1195564, 1067298.
and no connection storm at that time,
we did not find connection storm , just after server slowdown,
connection storm (fork started)
# grep "connection authori" postgresql.log.2025-06-24 | grep "2025-06-24 18:00:11" | wc -l
14
# grep "connection authori" postgresql.log.2025-06-24 | grep "2025-06-24 18:00:09" | wc -l
0
# grep "connection receiv" postgresql.log.2025-06-24 | grep "2025-06-24 18:00:09" | wc -l
1
# grep "connection receiv" postgresql.log.2025-06-24 | grep "2025-06-24 18:00:10" | wc -l
12
# grep "connection receiv" postgresql.log.2025-06-24 | grep "2025-06-24 18:00:11" | wc -l
15
2.sar output
06:00:10 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
06:00:12 PM all 17.06 0.00 77.00 0.09 0.80 1.58 0.00 0.00 0.00 3.47
06:00:12 PM 0 36.55 0.00 47.72 0.51 1.52 0.00 0.00 0.00 0.00 13.71
06:00:12 PM 1 27.50 0.00 71.50 0.00 1.00 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 2 17.68 0.00 81.82 0.00 0.51 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 3 9.50 0.00 90.00 0.00 0.50 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 4 15.92 0.00 83.08 0.00 1.00 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 5 13.37 0.00 84.65 0.00 1.49 0.50 0.00 0.00 0.00 0.00
06:00:12 PM 6 8.54 0.00 90.95 0.00 0.50 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 7 15.00 0.00 84.00 0.00 1.00 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 8 12.06 0.00 87.44 0.00 0.50 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 9 2.01 0.00 85.93 0.00 1.01 11.06 0.00 0.00 0.00 0.00
06:00:12 PM 10 22.39 0.00 76.62 0.00 1.00 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 11 8.54 0.00 77.39 0.00 1.01 13.07 0.00 0.00 0.00 0.00
06:00:12 PM 12 21.89 0.00 77.11 0.00 1.00 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 13 0.00 0.00 100.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 14 11.06 0.00 88.44 0.00 0.50 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 15 23.62 0.00 63.82 0.50 1.01 0.50 0.00 0.00 0.00 10.55
06:00:12 PM 16 14.50 0.00 85.00 0.00 0.50 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 17 17.91 0.00 79.10 0.00 1.00 0.00 0.00 0.00 0.00 1.99
06:00:12 PM 18 15.08 0.00 76.88 0.00 1.01 0.00 0.00 0.00 0.00 7.04
06:00:12 PM 19 1.49 0.00 98.01 0.00 0.50 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 20 8.96 0.00 90.55 0.00 0.50 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 21 7.50 0.00 76.50 0.00 1.50 14.50 0.00 0.00 0.00 0.00
06:00:12 PM 22 8.96 0.00 90.05 0.00 1.00 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 23 1.50 0.00 98.00 0.00 0.50 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 24 35.68 0.00 40.70 0.00 1.51 0.00 0.00 0.00 0.00 22.11
06:00:12 PM 25 13.07 0.00 86.43 0.00 0.50 0.00 0.00 0.00 0.00 0.00
06:00:12 PM 26 12.50 0.00 86.00 0.00 0.50 0.00 0.00 0.00 0.00 1.00
06:00:12 PM 27 15.50 0.00 84.00 0.00 0.50 0.00 0.00 0.00 0.00 0.00
3. --top
top - 18:00:11 up 404 days, 10:02, 0 users, load average: 8.00, 5.66, 4.37
Tasks: 3655 total, 257 running, 3398 sleeping, 0 stopped, 0 zombie
%Cpu(s): 14.4 us, 48.1 sy, 0.0 ni, 34.4 id, 0.6 wa, 0.7 hi, 1.9 si, 0.0 st
MiB Mem : 515429.4 total, 6760.2 free, 243086.7 used, 265582.5 buff/cache
MiB Swap: 32768.0 total, 32688.9 free, 79.1 used. 266170.2 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ nMaj nMin WCHAN COMMAND
2016159 postgres 20 0 348812 208628 22964 S 77.4 0.0 47:10.12 184 49k - xxxxxx
2150383 postgres 20 0 245312 169340 12096 R 63.6 0.0 0:01.38 0 39k - xxxxxx
2150384 postgres 20 0 245312 172948 12276 R 63.1 0.0 0:01.37 0 40k - xxxxxx
2150385 postgres 20 0 245312 166596 11992 R 63.1 0.0 0:01.37 0 38k - xxxxxx
2150386 postgres 20 0 245312 171056 12232 R 63.1 0.0 0:01.37 0 39k - xxxxxx
2016418 postgres 20 0 129.1g 28812 11376 R 58.1 0.0 26:16.18 2 338k - postgres: user dbname hostipx
4136689 postgres 20 0 129.1g 79124 12948 R 52.1 0.0 1:40.94 0 72k - postgres: user dbname hostip(47182) idle
1940769 postgres 20 0 129.1g 58444 12884 R 51.2 0.0 0:05.60 0 16k - postgres: user dbname hostip(51662) SELECT
1991976 postgres 20 0 129.1g 28400 12800 R 50.2 0.0 0:02.58 0 10k - postgres: user dbname hostip(38686) INSERT
2150423 postgres 20 0 11708 2104 1984 R 49.8 0.0 0:01.08 0 132 - grep --coluser dbname hostip
3130255 postgres 20 0 129.1g 77600 13012 R 49.8 0.0 2:06.46 0 148k - postgres: user dbname hostip37924) SELECT
1723555 postgres 20 0 129.1g 63160 12884 R 49.3 0.0 0:07.52 0 16k - postgres: user dbname hostip(58118) PARSE
4156794 postgres 20 0 129.1g 69916 12948 R 47.0 0.0 0:43.98 0 71k - postgres: user dbname hostip59524) SELECT
1427436 postgres 20 0 129.1g 78004 13012 R 46.5 0.0 0:22.13 0 32k - postgres: user dbname hostip(56598) idle
1748100 postgres 20 0 129.1g 67268 13012 R 46.5 0.0 0:09.68 0 24k - postgres: user dbname hostip42184) DELETE
2095173 postgres 20 0 129.1g 50952 12720 R 46.5 0.0 0:02.92 0 12k - postgres: user dbname hostip(32772) SELECT
1290342 postgres 20 0 129.1g 70744 12948 R 46.1 0.0 0:23.77 0 53k - postgres: user dbname hostip(60614) idle
1300455 postgres 20 0 129.1g 63676 12948 R 45.2 0.0 0:24.31 0 77k - postgres: user dbname hostip(39736) idle
559010 postgres 20 0 129.1g 69480 13012 R 44.7 0.0 0:33.50 0 54k - postgres: user dbname hostip(58600) SELECT
4. iostat
avg-cpu: %user %nice %system %iowait %steal %idle
15.61 0.00 81.20 0.09 0.00 3.11
Device r/s w/s rkB/s wkB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm %util
sdc 0.00 420.00 0.00 9425.25 0.00 0.00 0.00 0.00 0.00 0.48 0.20 0.00 22.44 1.08 45.35
sdd 0.00 58.50 0.00 336.25 0.00 11.50 0.00 16.43 0.00 0.42 0.02 0.00 5.75 1.34 7.85
sde 0.00 4.00 0.00 22.00 0.00 0.00 0.00 0.00 0.00 0.50 0.00 0.00 5.50 1.00 0.40
sdb 881.00 706.00 11598.00 11008.00 0.00 0.00 0.00 0.00 0.64 0.49 0.91 13.16 15.59 0.40 63.70
sda 0.00 2.00 0.00 14.75 0.00 0.00 0.00 0.00 0.00 0.25 0.00 0.00 7.38 1.00 0.20
scd0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
dm-0 0.00 1.50 0.00 12.75 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 8.50 0.67 0.10
dm-1 0.00 0.50 0.00 2.00 0.00 0.00 0.00 0.00 0.00 1.00 0.00 0.00 4.00 2.00 0.10