Re: Potential "AIO / io workers" inter-worker locking issue in PG18?

Hi Andres,

I have now been able to successfully run 'perf' after a VM restart and 
booting with the linux 6.8 kernel.

I have copied in two results for 'perf top' and a recording of one of 
the about 10 stuck processes by supplying a specific pid of the postgres 
backend.

Let me know if this is of any use. Of course, the recordings themselves 
are much bigger, I just copied the top part as displayed by the 'perf' 
report option. If you need the actual underlying files, let me know.

Also, if you have specific suggestions for 'perf' command options you 
would like to see run, please post them in your response and I will try 
if I can run them.

Andres: I posted separately to you I had a suspicion a recent linux 
kernel update (6.8 --> 6.14) might be involved that coincided with the 
PG18/PostGIS 3.6.0 upgrade when I initially had multiple successful runs 
of my tool without the temporary stalling / delay in returning of 
postgres after booting to the older 6.8 kernel. This has now proven 
wrong: these results are of the 6.8 kernel runs, so the kernel is not 
involved, and I also see the issue with the older kernel.

*** sudo perf top: ***

Samples: 1M of event 'cpu-clock:ppp', 4000 Hz, Event count (approx.): 
346785156250 lost: 0/0 drop: 0/0
Overhead  Shared Object                          Symbol
   17,33%  postgres                               [.] 0x0000000000584216
   12,21%  postgres                               [.] 0x000000000058737a
   11,80%  [kernel]                               [k] pv_native_safe_halt
   10,24%  postgres                               [.] ReleaseAndReadBuffer
    4,92%  postgres                               [.] heap_hot_search_buffer
    3,63%  postgres                               [.] 
hash_search_with_hash_value
    2,36%  postgres                               [.] 0x00000000005841f3
    1,85%  postgres                               [.] 0x0000000000554edd
    1,61%  postgres                               [.] 0x0000000000554e1f
    1,40%  postgres                               [.] 0x00000000005567f9
    1,32%  postgres                               [.] StartReadBuffer
    1,24%  postgres                               [.] heap_page_prune_opt
    1,23%  postgres                               [.] LWLockAcquire
    1,14%  postgres                               [.] 
HeapTupleSatisfiesVisibility
    1,10%  postgres                               [.] 0x00000000003977dd
    0,92%  postgres                               [.] index_getnext_tid
    0,87%  postgres                               [.] index_fetch_heap
    0,83%  postgres                               [.] ExecScan
    0,82%  postgres                               [.] ReleaseBuffer
    0,81%  postgres                               [.] LWLockRelease
    0,71%  postgres                               [.] XidInMVCCSnapshot
    0,66%  postgres                               [.] _bt_checkkeys
    0,66%  postgres                               [.] _bt_next
    0,55%  libxorgxrdp.so                         [.] crc_process_data
    0,51%  postgres                               [.] btgettuple
    0,41%  postgres                               [.] 0x00000000005567c6
    0,40%  postgres                               [.] 0x00000000003975d0
    0,35%  postgres                               [.] 
ExecStoreBufferHeapTuple
    0,34%  postgres                               [.] hash_bytes
    0,33%  postgres                               [.] MemoryContextReset
    0,33%  postgres                               [.] 0x00000000003975d3
    0,32%  postgres                               [.] ExecEvalSysVar
    0,28%  postgres                               [.] 0x00000000003975e3
    0,27%  postgres                               [.] ResourceOwnerForget
    0,27%  postgres                               [.] GlobalVisTestFor
    0,26%  postgres                               [.] 0x00000000003975b6
    0,26%  postgres                               [.] HeapTupleIsSurelyDead
    0,23%  postgres                               [.] 0x00000000003975c3
    0,23%  postgres                               [.] 0x00000000001ff80a
    0,22%  postgres                               [.] PredicateLockTID
    0,21%  postgres                               [.] slot_getsomeattrs_int
    0,20%  postgres                               [.] 0x000000000058421d
    0,19%  postgres                               [.] ReadBufferExtended
    0,16%  libc.so.6                              [.] __memcmp_sse2
    0,15%  postgres                               [.] 0x0000000000382e9e

*** sudo perf -p <PID of one stuck postgres backend> -g -d 10 ***
*** sudo perf report -g ***

Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10018000000
   Children      Self  Command   Shared Object      Symbol
+  100,00%     0,00%  postgres  postgres           [.] _start
+  100,00%     0,00%  postgres  libc.so.6          [.] 
__libc_start_main@@GLIBC_2.34
+  100,00%     0,00%  postgres  libc.so.6          [.] 
__libc_start_call_main
+  100,00%     0,00%  postgres  postgres           [.] main
+  100,00%     0,00%  postgres  postgres           [.] PostmasterMain
+  100,00%     0,00%  postgres  postgres           [.] 0x00005f35711b913e
+  100,00%     0,00%  postgres  postgres           [.] 
postmaster_child_launch
+  100,00%     0,00%  postgres  postgres           [.] 0x00005f3570fb9dbf
+  100,00%     0,00%  postgres  postgres           [.] PostgresMain
+  100,00%     0,00%  postgres  postgres           [.] 0x00005f3570fb6cb9
+  100,00%     0,00%  postgres  postgres           [.] PortalRun
+  100,00%     0,00%  postgres  postgres           [.] 0x00005f3570fbeca3
+  100,00%     0,00%  postgres  postgres           [.] 0x00005f3570fbcf85
+  100,00%     0,00%  postgres  postgres           [.] standard_ExecutorRun
+  100,00%     0,00%  postgres  postgres           [.] 0x00005f3570de682b
+  100,00%     0,00%  postgres  postgres           [.] 0x00005f3570de966d
+   97,51%     0,00%  postgres  postgres           [.] 0x00005f3570de959d
+   97,17%     0,95%  postgres  postgres           [.] ExecScan
+   82,75%     0,00%  postgres  postgres           [.] 0x00005f3570dda135
+   82,35%     1,04%  postgres  postgres           [.] index_fetch_heap
+   28,80%     0,00%  postgres  postgres           [.] 0x00005f3570bf3f87
+   23,67%     0,00%  postgres  postgres           [.] 0x00005f3570bf3ee8
+   22,19%     0,00%  postgres  postgres           [.] 0x00005f3570fa1216
+   22,18%    22,18%  postgres  postgres           [.] 0x0000000000584216
+   17,06%     0,89%  postgres  postgres           [.] LWLockRelease
+   16,18%     0,00%  postgres  postgres           [.] 0x00005f3570bf3f4f
+   15,59%     0,00%  postgres  postgres           [.] 0x00005f3570fa437a
+   15,57%    15,57%  postgres  postgres           [.] 0x000000000058737a
+   14,90%     0,22%  postgres  postgres           [.] ReadBufferExtended
+   14,18%    13,05%  postgres  postgres           [.] ReleaseAndReadBuffer
+   14,00%     1,82%  postgres  postgres           [.] StartReadBuffer
+    6,59%     0,00%  postgres  postgres           [.] 0x00005f3570bf3f18
+    5,97%     3,78%  postgres  postgres           [.] 
heap_hot_search_buffer
+    5,23%     0,00%  postgres  postgres           [.] 0x00005f3570da0613
+    5,20%     0,00%  postgres  postgres           [.] 0x00005f3570dda121
+    5,19%     0,22%  postgres  postgres           [.] slot_getsomeattrs_int
+    5,18%     0,68%  postgres  postgres           [.] index_getnext_tid
+    4,52%     0,65%  postgres  postgres           [.] btgettuple
+    3,92%     0,99%  postgres  postgres           [.] _bt_next
+    3,28%     3,28%  postgres  postgres           [.] 
hash_search_with_hash_value
+    2,96%     0,38%  postgres  postgres           [.] 
ExecStoreBufferHeapTuple
+    2,93%     0,00%  postgres  postgres           [.] 0x00005f3570bf3fe0