Thread
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-07T21:38:51Z
Hi Andres, Searching a bit more, and reading the PostgreSQL wiki pages about debugging, I have now found the 'find-dbgsym-packages' command, part of the 'debian-goodies' Installing and running this against a postgres process ID, returned the following debug symbol packages. Does this list seem about right for you? Marco lib32stdc++6-14-dbg libkrb5-dbg libstdc++6-14-dbg libx32stdc++6-14-dbg postgresql-18-dbgsym
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-07T22:13:34Z
Hi Andres, This looks much better, doesn't it? I hope this helps. Let me know if you need anything else. Marco *** sudo perf top: *** Samples: 2M of event 'cpu-clock:ppp', 4000 Hz, Event count (approx.): 593240647834 lost: 0/0 drop: 0/0 Overhead Shared Object Symbol 24,66% [kernel] [k] pv_native_safe_halt 9,35% postgres [.] LWLockAttemptLock 7,69% postgres [.] heap_hot_search_buffer 6,68% postgres [.] tts_heap_getsomeattrs.lto_priv.0 4,93% postgres [.] LWLockReleaseInternal 4,26% postgres [.] ExecInterpExpr 4,12% postgres [.] hash_search_with_hash_value 3,42% postgres [.] PinBuffer 2,54% postgres [.] heapam_index_fetch_tuple.lto_priv.0 2,46% postgres [.] ReleaseAndReadBuffer 1,72% postgres [.] LWLockAcquire 1,72% postgres [.] HeapTupleSatisfiesVisibility 1,48% postgres [.] index_fetch_heap 1,44% postgres [.] index_getnext_tid 1,40% postgres [.] heap_page_prune_opt 1,28% postgres [.] _bt_readpage 1,28% postgres [.] ExecScan 1,23% postgres [.] LWLockRelease 1,10% postgres [.] IndexNext 1,10% postgres [.] XidInMVCCSnapshot 1,07% postgres [.] _bt_checkkeys 0,98% postgres [.] _bt_next 0,90% postgres [.] UnpinBufferNoOwner.lto_priv.0 0,82% postgres [.] GetPrivateRefCountEntry.lto_priv.0 0,81% postgres [.] StartReadBuffer 0,80% postgres [.] btgettuple 0,69% postgres [.] _bt_check_compare.lto_priv.0 0,67% libxorgxrdp.so [.] crc_process_data 0,56% postgres [.] ExecStoreBufferHeapTuple 0,55% postgres [.] MemoryContextReset 0,50% postgres [.] ExecEvalSysVar 0,50% postgres [.] hash_bytes 0,48% postgres [.] tts_virtual_clear.lto_priv.0 0,48% postgres [.] ExecNestLoop 0,43% postgres [.] ResourceOwnerForget 0,41% postgres [.] GlobalVisTestFor 0,37% postgres [.] HeapTupleIsSurelyDead 0,33% postgres [.] slot_getsomeattrs_int 0,33% postgres [.] PredicateLockTID 0,29% postgres [.] ReadBufferExtended 0,27% postgres [.] _bt_saveitem 0,23% postgres [.] _bt_setuppostingitems 0,22% libc.so.6 [.] __memcmp_sse2 0,21% postgres [.] ExecIndexScan 0,20% postgres [.] ReleaseBuffer 0,19% postgres [.] ResourceOwnerEnlarge *** 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.): 10008250000 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 [.] ServerLoop.isra.0 + 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 [.] exec_simple_query + 100,00% 0,63% postgres postgres [.] ExecNestLoop + 100,00% 0,00% postgres postgres [.] PortalRun + 100,00% 0,00% postgres postgres [.] PortalRunMulti + 100,00% 0,00% postgres postgres [.] ProcessQuery + 100,00% 0,00% postgres postgres [.] standard_ExecutorRun + 100,00% 0,00% postgres postgres [.] ExecModifyTable + 94,63% 1,47% postgres postgres [.] ExecScan + 78,76% 1,49% postgres postgres [.] IndexNext + 66,89% 1,96% postgres postgres [.] index_fetch_heap + 64,35% 3,61% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 21,92% 0,40% postgres postgres [.] ReadBufferExtended + 20,36% 1,19% postgres postgres [.] StartReadBuffer + 16,23% 5,79% postgres postgres [.] ExecInterpExpr + 15,00% 10,70% postgres postgres [.] heap_hot_search_buffer + 12,81% 12,81% postgres postgres [.] LWLockAttemptLock + 10,31% 2,36% postgres postgres [.] index_getnext_tid + 9,69% 0,48% postgres postgres [.] slot_getsomeattrs_int + 9,27% 9,27% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 8,45% 1,85% postgres postgres [.] LWLockRelease + 7,91% 1,08% postgres postgres [.] btgettuple + 6,89% 1,12% postgres postgres [.] _bt_next + 6,77% 6,77% postgres postgres [.] LWLockReleaseInternal + 5,89% 5,89% postgres postgres [.] hash_search_with_hash_value + 5,78% 0,10% postgres postgres [.] _bt_readnextpage + 4,48% 4,14% postgres postgres [.] PinBuffer + 4,41% 1,90% postgres postgres [.] _bt_readpage + 4,09% 3,00% postgres postgres [.] ReleaseAndReadBuffer + 2,99% 2,38% postgres postgres [.] HeapTupleSatisfiesVisibility + 2,58% 0,82% postgres postgres [.] ExecStoreBufferHeapTuple + 2,43% 2,43% postgres postgres [.] LWLockAcquire + 2,28% 1,47% postgres postgres [.] _bt_checkkeys + 1,74% 1,74% postgres postgres [.] heap_page_prune_opt + 1,67% 1,10% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 1,47% 1,47% postgres postgres [.] XidInMVCCSnapshot + 1,18% 1,18% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 + 1,09% 1,09% postgres postgres [.] MemoryContextReset Op 7-10-2025 om 23:38 schreef Marco Boeringa: > Hi Andres, > > Searching a bit more, and reading the PostgreSQL wiki pages about > debugging, I have now found the 'find-dbgsym-packages' command, part > of the 'debian-goodies' > > Installing and running this against a postgres process ID, returned > the following debug symbol packages. Does this list seem about right > for you? > > Marco > > lib32stdc++6-14-dbg > > libkrb5-dbg > > libstdc++6-14-dbg > > libx32stdc++6-14-dbg > > postgresql-18-dbgsym >
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Andres Freund <andres@anarazel.de> — 2025-10-07T23:03:40Z
Hi, On 2025-10-08 00:13:34 +0200, Marco Boeringa wrote: > This looks much better, doesn't it? It indeed does! > I hope this helps. Let me know if you need anything else. > *** sudo perf -p <PID of one stuck postgres backend> -g -d 10 *** > *** sudo perf report -g *** Could you show perf report --no-children? That would show us which individual functions, rather than call-stacks, take the longest. > Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10008250000 > 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 [.] ServerLoop.isra.0 > + 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 [.] exec_simple_query > + 100,00% 0,63% postgres postgres [.] ExecNestLoop > + 100,00% 0,00% postgres postgres [.] PortalRun > + 100,00% 0,00% postgres postgres [.] PortalRunMulti > + 100,00% 0,00% postgres postgres [.] ProcessQuery > + 100,00% 0,00% postgres postgres [.] standard_ExecutorRun > + 100,00% 0,00% postgres postgres [.] ExecModifyTable > + 94,63% 1,47% postgres postgres [.] ExecScan > + 78,76% 1,49% postgres postgres [.] IndexNext > + 66,89% 1,96% postgres postgres [.] index_fetch_heap > + 64,35% 3,61% postgres postgres [.] > heapam_index_fetch_tuple.lto_priv.0 So somehow >60% of the CPU time is spent fetching tuples corresponding to index entries. That seems ... a lot. Is it possible that you have a lot of dead rows in the involved tables? I don't immediately see how this could be related to AIO. Greetings, Andres Freund
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Andres Freund <andres@anarazel.de> — 2025-10-07T23:17:06Z
Hi, On 2025-10-07 19:03:40 -0400, Andres Freund wrote: > On 2025-10-08 00:13:34 +0200, Marco Boeringa wrote: > So somehow >60% of the CPU time is spent fetching tuples corresponding to > index entries. That seems ... a lot. Is it possible that you have a lot of > dead rows in the involved tables? > > I don't immediately see how this could be related to AIO. Can you share the query and explain for it that was running in the "stuck" backend? Greetings, Andres Freund
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-08T07:49:04Z
Hi Andres, > Could you show perf report --no-children? That would show us which individual functions, rather than call-stacks, take the longest. See entirely below! > I don't immediately see how this could be related to AIO. Yes, you could be right this is not related to AIO at all, but another issue introduced in PG18. The only reason I initially thought of AIO was of course that it is one of the main new features of PG18, and I could imagine "workers" getting into some sort of inter-worker locking issues, just like threads can. For sure, I did not see this issue in <= PG17, so some change in PG18 is causing it. Additionally, there is a small chance it might be related to PostGIS, as that was upgraded as well (3.5.2 --> 3.6.0) during the PG upgrade, as PG18 requires PostGIS 3.6.0 minimum. And the query does use PostGIS functions, but none that AFAIK rely on e.g. a spatial index. Functions like ST_Area just process an individual geometry, not the spatial relationship between multiple geometries. As I wrote before, this is a multi-threaded Python application (actually developed in a GIS), that uses Python's 'concurrent.futures' threading framework to create jobs of records to process for each thread, significantly speeding up the processing. The queries are in fact dynamically build by the code, and part of a much larger geoprocessing workflow, so it is hard to run them separately and provide a query plan (although in this case I could by rewriting part of the query below). However, I want to stress that any query plan is unlikely to yield anything. In normal circumstances and in PG17 and below, this code runs fine! And it is only 1 in maybe 4 runs in PG18 that goes berserk and makes a processing step that should takes < 10 seconds, all of a sudden take > 2 hours. UPDATE osm.landcover_scrubs_small_scale_2_ply AS t1 SET area_geo = t2.area_geo, perim_geo = t2.perim_geo, compact_geo = CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END, npoints_geo = t2.npoints_geo, comp_npoints_geo = CASE WHEN t2.npoints_geo > 0 THEN (CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END / t2.npoints_geo) ELSE 0 END, convex_ratio_geo = CASE WHEN ST_Area(ST_ConvexHull(way)::geography,true) > 0 THEN (t2.area_geo / ST_Area(ST_ConvexHull(way)::geography,true)) ELSE 1 END FROM (SELECT objectid,ST_Area(way::geography,true) AS area_geo,ST_Perimeter(way::geography,true) AS perim_geo,ST_NPoints(way) AS npoints_geo FROM osm.landcover_scrubs_small_scale_2_ply) AS t2 WHERE (t2.objectid = t1.objectid) AND t1.objectid IN (SELECT t3.objectid FROM mini_test.osm.osm_tmp_28128_ch5 AS t3) > So somehow >60% of the CPU time is spent fetching tuples corresponding to index entries. That seems ... a lot. Is it possible that you have a lot of dead rows in the involved tables? Yes, that is perfectly possible. However, the particular table is only just over 100k records. It is true that my code is designed to process literally *every* record in a table. However, I specifically set adjusted table storage parameters with much more aggressive vacuum settings (essentially forcing always vacuum after something like 10k dead tuples irrespective of the size of the table). This has worked really well, and I have successfully UPDATEd all of Facebook Daylight size > 1B records tables with the same code, without ever running into this particular issue, nor transaction ID wraparound issues. One particular thing to note as well is that, due to careful design of the jobs taking page locality into account, deliberately setting a low table fill factor, and plenty of RAM, quite a few but not all of the steps in the geoprocessing workflow, manage to run almost completely as PostgreSQL 'HOT' updates, so for all records in the table (even for very large ones). *** sudo perf -p <PID of one stuck postgres backend> -g -d 10 *** *** sudo perf report --no-children *** Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10008250000 Overhead Command Shared Object Symbol + 12,81% postgres postgres [.] LWLockAttemptLock + 10,70% postgres postgres [.] heap_hot_search_buffer + 9,27% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 6,77% postgres postgres [.] LWLockReleaseInternal + 5,89% postgres postgres [.] hash_search_with_hash_value + 5,79% postgres postgres [.] ExecInterpExpr + 4,14% postgres postgres [.] PinBuffer + 3,61% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 3,00% postgres postgres [.] ReleaseAndReadBuffer + 2,43% postgres postgres [.] LWLockAcquire + 2,38% postgres postgres [.] HeapTupleSatisfiesVisibility + 2,36% postgres postgres [.] index_getnext_tid + 1,96% postgres postgres [.] index_fetch_heap + 1,90% postgres postgres [.] _bt_readpage + 1,85% postgres postgres [.] LWLockRelease + 1,74% postgres postgres [.] heap_page_prune_opt + 1,49% postgres postgres [.] IndexNext + 1,47% postgres postgres [.] _bt_checkkeys + 1,47% postgres postgres [.] ExecScan + 1,47% postgres postgres [.] XidInMVCCSnapshot + 1,19% postgres postgres [.] StartReadBuffer + 1,18% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 + 1,12% postgres postgres [.] _bt_next + 1,10% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 1,09% postgres postgres [.] MemoryContextReset + 1,08% postgres postgres [.] btgettuple + 0,91% postgres postgres [.] _bt_check_compare.lto_priv.0 + 0,82% postgres postgres [.] ExecEvalSysVar + 0,82% postgres postgres [.] ExecStoreBufferHeapTuple + 0,71% postgres postgres [.] hash_bytes + 0,65% postgres postgres [.] tts_virtual_clear.lto_priv.0 + 0,63% postgres postgres [.] GlobalVisTestFor + 0,63% postgres postgres [.] ExecNestLoop + 0,55% postgres postgres [.] HeapTupleIsSurelyDead + 0,52% postgres postgres [.] ResourceOwnerForget 0,48% postgres postgres [.] slot_getsomeattrs_int 0,42% postgres postgres [.] PredicateLockTID 0,40% postgres postgres [.] ReadBufferExtended 0,37% postgres postgres [.] _bt_saveitem 0,31% postgres postgres [.] ExecIndexScan 0,30% postgres libc.so.6 [.] __memcmp_sse2 0,28% postgres postgres [.] _bt_setuppostingitems 0,26% postgres postgres [.] ReleaseBuffer 0,23% postgres postgres [.] ResourceOwnerEnlarge 0,23% postgres postgres [.] HeapCheckForSerializableConflictOut 0,22% postgres postgres [.] IncrBufferRefCount 0,18% postgres postgres [.] pgstat_count_io_op -
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-08T10:04:20Z
> Could you show perf report --no-children? That would show us which individual > functions, rather than call-stacks, take the longest. Andres, I now captured a few more 'perf' sessions. Run 1 is the original run I already showed you. For comparison, runs 2-4 are from a different backend captured during a new geoprocessing run, but all refering to same PID. Run 5 is also from the same geoprocessing run, but another backend PID, so another python thread launched from my code. Not much difference between all of these, especially the ordinary "perf report", the "perf report --no children" show a little more variation. "perf report --no children" runs are grouped together at the bottom of the email. Despite the minor differences, maybe seeing different captures of perf is still of some use. Marco *** sudo perf -p <PID of one stuck postgres backend> -g -d 10 *** *** sudo perf report -g *** RUN 1: Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10008250000 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 [.] ServerLoop.isra.0 + 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 [.] exec_simple_query + 100,00% 0,63% postgres postgres [.] ExecNestLoop + 100,00% 0,00% postgres postgres [.] PortalRun + 100,00% 0,00% postgres postgres [.] PortalRunMulti + 100,00% 0,00% postgres postgres [.] ProcessQuery + 100,00% 0,00% postgres postgres [.] standard_ExecutorRun + 100,00% 0,00% postgres postgres [.] ExecModifyTable + 94,63% 1,47% postgres postgres [.] ExecScan + 78,76% 1,49% postgres postgres [.] IndexNext + 66,89% 1,96% postgres postgres [.] index_fetch_heap + 64,35% 3,61% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 21,92% 0,40% postgres postgres [.] ReadBufferExtended + 20,36% 1,19% postgres postgres [.] StartReadBuffer + 16,23% 5,79% postgres postgres [.] ExecInterpExpr + 15,00% 10,70% postgres postgres [.] heap_hot_search_buffer + 12,81% 12,81% postgres postgres [.] LWLockAttemptLock + 10,31% 2,36% postgres postgres [.] index_getnext_tid + 9,69% 0,48% postgres postgres [.] slot_getsomeattrs_int + 9,27% 9,27% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 8,45% 1,85% postgres postgres [.] LWLockRelease + 7,91% 1,08% postgres postgres [.] btgettuple + 6,89% 1,12% postgres postgres [.] _bt_next + 6,77% 6,77% postgres postgres [.] LWLockReleaseInternal + 5,89% 5,89% postgres postgres [.] hash_search_with_hash_value + 5,78% 0,10% postgres postgres [.] _bt_readnextpage + 4,48% 4,14% postgres postgres [.] PinBuffer + 4,41% 1,90% postgres postgres [.] _bt_readpage + 4,09% 3,00% postgres postgres [.] ReleaseAndReadBuffer + 2,99% 2,38% postgres postgres [.] HeapTupleSatisfiesVisibility + 2,58% 0,82% postgres postgres [.] ExecStoreBufferHeapTuple + 2,43% 2,43% postgres postgres [.] LWLockAcquire + 2,28% 1,47% postgres postgres [.] _bt_checkkeys + 1,74% 1,74% postgres postgres [.] heap_page_prune_opt + 1,67% 1,10% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 1,47% 1,47% postgres postgres [.] XidInMVCCSnapshot + 1,18% 1,18% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 + 1,09% 1,09% postgres postgres [.] MemoryContextReset RUN 2: amples: 40K of event 'task-clock:ppp', Event count (approx.): 10020750000 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 [.] ServerLoop.isra.0 + 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 [.] exec_simple_query + 100,00% 0,34% postgres postgres [.] ExecNestLoop + 100,00% 0,00% postgres postgres [.] PortalRun + 100,00% 0,00% postgres postgres [.] PortalRunMulti + 100,00% 0,00% postgres postgres [.] ProcessQuery + 100,00% 0,00% postgres postgres [.] standard_ExecutorRun + 100,00% 0,00% postgres postgres [.] ExecModifyTable + 97,34% 1,13% postgres postgres [.] ExecScan + 88,55% 0,73% postgres postgres [.] IndexNext + 82,41% 1,05% postgres postgres [.] index_fetch_heap + 81,10% 1,78% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 25,70% 25,70% postgres postgres [.] LWLockAttemptLock + 16,67% 0,86% postgres postgres [.] LWLockRelease + 15,91% 15,91% postgres postgres [.] LWLockReleaseInternal + 15,27% 0,22% postgres postgres [.] ReadBufferExtended + 14,41% 1,73% postgres postgres [.] StartReadBuffer + 14,11% 13,01% postgres postgres [.] ReleaseAndReadBuffer + 8,60% 3,08% postgres postgres [.] ExecInterpExpr + 6,27% 3,90% postgres postgres [.] heap_hot_search_buffer + 5,36% 1,11% postgres postgres [.] index_getnext_tid + 5,20% 0,20% postgres postgres [.] slot_getsomeattrs_int + 5,05% 5,05% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 4,74% 4,59% postgres postgres [.] PinBuffer + 4,21% 0,54% postgres postgres [.] btgettuple + 3,75% 0,72% postgres postgres [.] _bt_next + 3,27% 3,27% postgres postgres [.] hash_search_with_hash_value + 3,04% 0,03% postgres postgres [.] _bt_readnextpage + 3,00% 0,44% postgres postgres [.] ExecStoreBufferHeapTuple + 2,43% 2,16% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 2,24% 1,01% postgres postgres [.] _bt_readpage + 1,62% 1,25% postgres postgres [.] HeapTupleSatisfiesVisibility + 1,51% 1,51% postgres postgres [.] LWLockAcquire + 1,18% 1,18% postgres postgres [.] heap_page_prune_opt + 1,07% 0,72% postgres postgres [.] _bt_checkkeys + 0,85% 0,85% postgres postgres [.] XidInMVCCSnapshot + 0,82% 0,74% postgres postgres [.] ReleaseBuffer + 0,56% 0,56% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 0,41% 0,41% postgres postgres [.] _bt_check_compare.lto_priv.0 RUN 3: Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10010750000 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 [.] ServerLoop.isra.0 + 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 [.] exec_simple_query + 100,00% 0,34% postgres postgres [.] ExecNestLoop + 100,00% 0,00% postgres postgres [.] PortalRun + 100,00% 0,00% postgres postgres [.] PortalRunMulti + 100,00% 0,00% postgres postgres [.] ProcessQuery + 100,00% 0,00% postgres postgres [.] standard_ExecutorRun + 100,00% 0,00% postgres postgres [.] ExecModifyTable + 97,43% 1,10% postgres postgres [.] ExecScan + 88,96% 0,79% postgres postgres [.] IndexNext + 82,68% 1,03% postgres postgres [.] index_fetch_heap + 81,42% 1,89% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 25,54% 25,54% postgres postgres [.] LWLockAttemptLock + 17,38% 1,01% postgres postgres [.] LWLockRelease + 16,44% 16,44% postgres postgres [.] LWLockReleaseInternal + 15,39% 0,25% postgres postgres [.] ReadBufferExtended + 14,49% 1,69% postgres postgres [.] StartReadBuffer + 13,77% 12,72% postgres postgres [.] ReleaseAndReadBuffer + 8,28% 2,95% postgres postgres [.] ExecInterpExpr + 6,05% 3,75% postgres postgres [.] heap_hot_search_buffer + 5,39% 1,09% postgres postgres [.] index_getnext_tid + 5,05% 0,21% postgres postgres [.] slot_getsomeattrs_int + 4,88% 4,88% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 4,87% 4,69% postgres postgres [.] PinBuffer + 4,29% 0,61% postgres postgres [.] btgettuple + 3,74% 0,74% postgres postgres [.] _bt_next + 3,47% 3,47% postgres postgres [.] hash_search_with_hash_value + 3,00% 0,05% postgres postgres [.] _bt_readnextpage + 2,99% 0,50% postgres postgres [.] ExecStoreBufferHeapTuple + 2,27% 2,01% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 2,19% 0,99% postgres postgres [.] _bt_readpage + 1,52% 1,14% postgres postgres [.] HeapTupleSatisfiesVisibility + 1,50% 1,50% postgres postgres [.] LWLockAcquire + 1,12% 1,12% postgres postgres [.] heap_page_prune_opt + 1,06% 0,72% postgres postgres [.] _bt_checkkeys + 0,87% 0,87% postgres postgres [.] XidInMVCCSnapshot + 0,87% 0,76% postgres postgres [.] ReleaseBuffer + 0,59% 0,59% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 0,41% 0,41% postgres postgres [.] _bt_check_compare.lto_priv.0 RUN 4: Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10010500000 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 [.] ServerLoop.isra.0 + 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 [.] exec_simple_query + 100,00% 0,32% postgres postgres [.] ExecNestLoop + 100,00% 0,00% postgres postgres [.] PortalRun + 100,00% 0,00% postgres postgres [.] PortalRunMulti + 100,00% 0,00% postgres postgres [.] ProcessQuery + 100,00% 0,00% postgres postgres [.] standard_ExecutorRun + 100,00% 0,00% postgres postgres [.] ExecModifyTable + 97,30% 1,16% postgres postgres [.] ExecScan + 88,81% 0,73% postgres postgres [.] IndexNext + 82,49% 0,99% postgres postgres [.] index_fetch_heap + 81,18% 2,01% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 25,65% 25,65% postgres postgres [.] LWLockAttemptLock + 16,65% 1,01% postgres postgres [.] LWLockRelease + 15,79% 0,26% postgres postgres [.] ReadBufferExtended + 15,76% 15,76% postgres postgres [.] LWLockReleaseInternal + 15,00% 1,65% postgres postgres [.] StartReadBuffer + 13,88% 12,75% postgres postgres [.] ReleaseAndReadBuffer + 8,41% 3,03% postgres postgres [.] ExecInterpExpr + 6,13% 3,82% postgres postgres [.] heap_hot_search_buffer + 5,46% 1,04% postgres postgres [.] index_getnext_tid + 5,02% 0,23% postgres postgres [.] slot_getsomeattrs_int + 4,94% 4,78% postgres postgres [.] PinBuffer + 4,83% 4,83% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 4,40% 0,58% postgres postgres [.] btgettuple + 3,87% 0,79% postgres postgres [.] _bt_next + 3,76% 3,76% postgres postgres [.] hash_search_with_hash_value + 3,09% 0,05% postgres postgres [.] _bt_readnextpage + 2,88% 0,46% postgres postgres [.] ExecStoreBufferHeapTuple + 2,44% 2,11% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 2,26% 1,01% postgres postgres [.] _bt_readpage + 1,53% 1,16% postgres postgres [.] HeapTupleSatisfiesVisibility + 1,45% 1,45% postgres postgres [.] LWLockAcquire + 1,17% 1,17% postgres postgres [.] heap_page_prune_opt + 1,09% 0,72% postgres postgres [.] _bt_checkkeys + 0,82% 0,82% postgres postgres [.] XidInMVCCSnapshot + 0,80% 0,71% postgres postgres [.] ReleaseBuffer + 0,63% 0,63% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 0,44% 0,44% postgres postgres [.] _bt_check_compare.lto_priv.0 RUN 5: Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10003250000 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 [.] ServerLoop.isra.0 + 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 [.] exec_simple_query + 100,00% 0,00% postgres postgres [.] PortalRun + 100,00% 0,00% postgres postgres [.] PortalRunMulti + 100,00% 0,00% postgres postgres [.] ProcessQuery + 100,00% 0,00% postgres postgres [.] standard_ExecutorRun + 100,00% 0,00% postgres postgres [.] ExecModifyTable + 100,00% 0,35% postgres postgres [.] ExecNestLoop + 97,20% 0,90% postgres postgres [.] ExecScan + 89,12% 0,85% postgres postgres [.] IndexNext + 82,86% 1,00% postgres postgres [.] index_fetch_heap + 81,60% 1,92% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 26,49% 26,48% postgres postgres [.] LWLockAttemptLock + 16,53% 0,81% postgres postgres [.] LWLockRelease + 15,81% 15,81% postgres postgres [.] LWLockReleaseInternal + 15,57% 0,22% postgres postgres [.] ReadBufferExtended + 14,68% 1,88% postgres postgres [.] StartReadBuffer + 14,10% 12,88% postgres postgres [.] ReleaseAndReadBuffer + 8,27% 2,97% postgres postgres [.] ExecInterpExpr + 5,87% 3,67% postgres postgres [.] heap_hot_search_buffer + 5,38% 0,92% postgres postgres [.] index_getnext_tid + 5,01% 0,21% postgres postgres [.] slot_getsomeattrs_int + 4,85% 4,84% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 4,81% 4,64% postgres postgres [.] PinBuffer + 4,41% 0,53% postgres postgres [.] btgettuple + 3,96% 0,92% postgres postgres [.] _bt_next + 3,47% 3,47% postgres postgres [.] hash_search_with_hash_value + 3,03% 0,03% postgres postgres [.] _bt_readnextpage + 2,77% 0,40% postgres postgres [.] ExecStoreBufferHeapTuple + 2,41% 2,11% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 2,28% 0,97% postgres postgres [.] _bt_readpage + 1,46% 1,09% postgres postgres [.] HeapTupleSatisfiesVisibility + 1,41% 1,41% postgres postgres [.] LWLockAcquire + 1,14% 0,71% postgres postgres [.] _bt_checkkeys + 1,12% 1,12% postgres postgres [.] heap_page_prune_opt + 0,83% 0,83% postgres postgres [.] XidInMVCCSnapshot + 0,81% 0,69% postgres postgres [.] ReleaseBuffer + 0,57% 0,57% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 0,48% 0,48% postgres postgres [.] _bt_check_compare.lto_priv.0 *** sudo perf -p <PID of one stuck postgres backend> -g -d 10 *** *** sudo perf report --no-children *** RUN 1 - NO CHILDREN: Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10008250000 Overhead Command Shared Object Symbol + 12,81% postgres postgres [.] LWLockAttemptLock + 10,70% postgres postgres [.] heap_hot_search_buffer + 9,27% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 6,77% postgres postgres [.] LWLockReleaseInternal + 5,89% postgres postgres [.] hash_search_with_hash_value + 5,79% postgres postgres [.] ExecInterpExpr + 4,14% postgres postgres [.] PinBuffer + 3,61% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 3,00% postgres postgres [.] ReleaseAndReadBuffer + 2,43% postgres postgres [.] LWLockAcquire + 2,38% postgres postgres [.] HeapTupleSatisfiesVisibility + 2,36% postgres postgres [.] index_getnext_tid + 1,96% postgres postgres [.] index_fetch_heap + 1,90% postgres postgres [.] _bt_readpage + 1,85% postgres postgres [.] LWLockRelease + 1,74% postgres postgres [.] heap_page_prune_opt + 1,49% postgres postgres [.] IndexNext + 1,47% postgres postgres [.] _bt_checkkeys + 1,47% postgres postgres [.] ExecScan + 1,47% postgres postgres [.] XidInMVCCSnapshot + 1,19% postgres postgres [.] StartReadBuffer + 1,18% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 + 1,12% postgres postgres [.] _bt_next + 1,10% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 1,09% postgres postgres [.] MemoryContextReset + 1,08% postgres postgres [.] btgettuple + 0,91% postgres postgres [.] _bt_check_compare.lto_priv.0 + 0,82% postgres postgres [.] ExecEvalSysVar + 0,82% postgres postgres [.] ExecStoreBufferHeapTuple + 0,71% postgres postgres [.] hash_bytes + 0,65% postgres postgres [.] tts_virtual_clear.lto_priv.0 + 0,63% postgres postgres [.] GlobalVisTestFor + 0,63% postgres postgres [.] ExecNestLoop + 0,55% postgres postgres [.] HeapTupleIsSurelyDead + 0,52% postgres postgres [.] ResourceOwnerForget 0,48% postgres postgres [.] slot_getsomeattrs_int 0,42% postgres postgres [.] PredicateLockTID 0,40% postgres postgres [.] ReadBufferExtended 0,37% postgres postgres [.] _bt_saveitem 0,31% postgres postgres [.] ExecIndexScan 0,30% postgres libc.so.6 [.] __memcmp_sse2 0,28% postgres postgres [.] _bt_setuppostingitems 0,26% postgres postgres [.] ReleaseBuffer 0,23% postgres postgres [.] ResourceOwnerEnlarge 0,23% postgres postgres [.] HeapCheckForSerializableConflictOut 0,22% postgres postgres [.] IncrBufferRefCount 0,18% postgres postgres [.] pgstat_count_io_op RUN 2 - NO CHILDREN: Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10020750000 Overhead Command Shared Object Symbol + 25,70% postgres postgres [.] LWLockAttemptLock + 15,91% postgres postgres [.] LWLockReleaseInternal + 13,01% postgres postgres [.] ReleaseAndReadBuffer + 5,05% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 4,59% postgres postgres [.] PinBuffer + 3,90% postgres postgres [.] heap_hot_search_buffer + 3,27% postgres postgres [.] hash_search_with_hash_value + 3,08% postgres postgres [.] ExecInterpExpr + 2,16% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 1,78% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 1,73% postgres postgres [.] StartReadBuffer + 1,51% postgres postgres [.] LWLockAcquire + 1,25% postgres postgres [.] HeapTupleSatisfiesVisibility + 1,18% postgres postgres [.] heap_page_prune_opt + 1,13% postgres postgres [.] ExecScan + 1,11% postgres postgres [.] index_getnext_tid + 1,05% postgres postgres [.] index_fetch_heap + 1,01% postgres postgres [.] _bt_readpage + 0,86% postgres postgres [.] LWLockRelease + 0,85% postgres postgres [.] XidInMVCCSnapshot + 0,74% postgres postgres [.] ReleaseBuffer + 0,73% postgres postgres [.] IndexNext + 0,72% postgres postgres [.] _bt_checkkeys + 0,72% postgres postgres [.] _bt_next + 0,56% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 + 0,54% postgres postgres [.] btgettuple 0,44% postgres postgres [.] ExecStoreBufferHeapTuple 0,41% postgres postgres [.] _bt_check_compare.lto_priv.0 0,41% postgres postgres [.] hash_bytes 0,39% postgres postgres [.] MemoryContextReset 0,34% postgres postgres [.] ExecEvalSysVar 0,34% postgres postgres [.] ExecNestLoop 0,32% postgres postgres [.] tts_virtual_clear.lto_priv.0 0,32% postgres postgres [.] ResourceOwnerForget 0,30% postgres postgres [.] GlobalVisTestFor 0,30% postgres postgres [.] HeapTupleIsSurelyDead 0,26% postgres postgres [.] PredicateLockTID 0,22% postgres postgres [.] ReadBufferExtended 0,20% postgres postgres [.] _bt_setuppostingitems 0,20% postgres postgres [.] ExecIndexScan 0,20% postgres postgres [.] slot_getsomeattrs_int 0,17% postgres libc.so.6 [.] __memcmp_sse2 0,16% postgres postgres [.] _bt_saveitem 0,13% postgres postgres [.] ResourceOwnerEnlarge 0,12% postgres postgres [.] HeapCheckForSerializableConflictOut 0,10% postgres postgres [.] pgstat_count_io_op 0,08% postgres postgres [.] IncrBufferRefCount RUN 3 - NO CHILDREN: Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10010750000 Overhead Command Shared Object Symbol + 25,54% postgres postgres [.] LWLockAttemptLock + 16,44% postgres postgres [.] LWLockReleaseInternal + 12,72% postgres postgres [.] ReleaseAndReadBuffer + 4,88% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 4,69% postgres postgres [.] PinBuffer + 3,75% postgres postgres [.] heap_hot_search_buffer + 3,47% postgres postgres [.] hash_search_with_hash_value + 2,95% postgres postgres [.] ExecInterpExpr + 2,01% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 1,89% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 1,69% postgres postgres [.] StartReadBuffer + 1,50% postgres postgres [.] LWLockAcquire + 1,14% postgres postgres [.] HeapTupleSatisfiesVisibility + 1,12% postgres postgres [.] heap_page_prune_opt + 1,10% postgres postgres [.] ExecScan + 1,09% postgres postgres [.] index_getnext_tid + 1,03% postgres postgres [.] index_fetch_heap + 1,01% postgres postgres [.] LWLockRelease + 0,99% postgres postgres [.] _bt_readpage + 0,87% postgres postgres [.] XidInMVCCSnapshot + 0,79% postgres postgres [.] IndexNext + 0,76% postgres postgres [.] ReleaseBuffer + 0,74% postgres postgres [.] _bt_next + 0,72% postgres postgres [.] _bt_checkkeys + 0,61% postgres postgres [.] btgettuple + 0,59% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 0,50% postgres postgres [.] ExecStoreBufferHeapTuple 0,41% postgres postgres [.] _bt_check_compare.lto_priv.0 0,41% postgres postgres [.] hash_bytes 0,38% postgres postgres [.] MemoryContextReset 0,34% postgres postgres [.] ExecEvalSysVar 0,34% postgres postgres [.] HeapTupleIsSurelyDead 0,34% postgres postgres [.] ExecNestLoop 0,32% postgres postgres [.] ResourceOwnerForget 0,31% postgres postgres [.] GlobalVisTestFor 0,31% postgres postgres [.] tts_virtual_clear.lto_priv.0 0,25% postgres postgres [.] ReadBufferExtended 0,22% postgres postgres [.] PredicateLockTID 0,21% postgres postgres [.] slot_getsomeattrs_int 0,17% postgres postgres [.] ExecIndexScan 0,17% postgres postgres [.] _bt_saveitem 0,16% postgres postgres [.] _bt_setuppostingitems 0,14% postgres postgres [.] HeapCheckForSerializableConflictOut 0,13% postgres libc.so.6 [.] __memcmp_sse2 0,12% postgres postgres [.] ResourceOwnerEnlarge 0,11% postgres postgres [.] IncrBufferRefCount 0,10% postgres postgres [.] pgstat_count_io_op RUN 4 - NO CHILDREN: Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10010500000 Overhead Command Shared Object Symbol + 25,65% postgres postgres [.] LWLockAttemptLock + 15,76% postgres postgres [.] LWLockReleaseInternal + 12,75% postgres postgres [.] ReleaseAndReadBuffer + 4,83% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 4,78% postgres postgres [.] PinBuffer + 3,82% postgres postgres [.] heap_hot_search_buffer + 3,76% postgres postgres [.] hash_search_with_hash_value + 3,03% postgres postgres [.] ExecInterpExpr + 2,11% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 2,01% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 1,65% postgres postgres [.] StartReadBuffer + 1,45% postgres postgres [.] LWLockAcquire + 1,17% postgres postgres [.] heap_page_prune_opt + 1,16% postgres postgres [.] ExecScan + 1,16% postgres postgres [.] HeapTupleSatisfiesVisibility + 1,04% postgres postgres [.] index_getnext_tid + 1,01% postgres postgres [.] LWLockRelease + 1,01% postgres postgres [.] _bt_readpage + 0,99% postgres postgres [.] index_fetch_heap + 0,82% postgres postgres [.] XidInMVCCSnapshot + 0,79% postgres postgres [.] _bt_next + 0,73% postgres postgres [.] IndexNext + 0,72% postgres postgres [.] _bt_checkkeys + 0,71% postgres postgres [.] ReleaseBuffer + 0,63% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 + 0,58% postgres postgres [.] btgettuple 0,46% postgres postgres [.] ExecStoreBufferHeapTuple 0,44% postgres postgres [.] _bt_check_compare.lto_priv.0 0,37% postgres postgres [.] ExecEvalSysVar 0,36% postgres postgres [.] MemoryContextReset 0,34% postgres postgres [.] tts_virtual_clear.lto_priv.0 0,32% postgres postgres [.] ExecNestLoop 0,31% postgres postgres [.] GlobalVisTestFor 0,30% postgres postgres [.] HeapTupleIsSurelyDead 0,30% postgres postgres [.] hash_bytes 0,27% postgres postgres [.] PredicateLockTID 0,26% postgres postgres [.] ResourceOwnerForget 0,26% postgres postgres [.] ReadBufferExtended 0,23% postgres postgres [.] slot_getsomeattrs_int 0,17% postgres postgres [.] _bt_setuppostingitems 0,17% postgres libc.so.6 [.] __memcmp_sse2 0,15% postgres postgres [.] ExecIndexScan 0,14% postgres postgres [.] _bt_saveitem 0,12% postgres postgres [.] int8eq 0,12% postgres postgres [.] ReservePrivateRefCountEntry.lto_priv.0 0,12% postgres postgres [.] ResourceOwnerEnlarge 0,11% postgres postgres [.] HeapCheckForSerializableConflictOut RUN 5 - NO CHILDREN: Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10003250000 Overhead Command Shared Object Symbol + 26,48% postgres postgres [.] LWLockAttemptLock + 15,81% postgres postgres [.] LWLockReleaseInternal + 12,88% postgres postgres [.] ReleaseAndReadBuffer + 4,84% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 + 4,64% postgres postgres [.] PinBuffer + 3,67% postgres postgres [.] heap_hot_search_buffer + 3,47% postgres postgres [.] hash_search_with_hash_value + 2,97% postgres postgres [.] ExecInterpExpr + 2,11% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 + 1,92% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 + 1,88% postgres postgres [.] StartReadBuffer + 1,41% postgres postgres [.] LWLockAcquire + 1,12% postgres postgres [.] heap_page_prune_opt + 1,09% postgres postgres [.] HeapTupleSatisfiesVisibility + 1,00% postgres postgres [.] index_fetch_heap + 0,97% postgres postgres [.] _bt_readpage + 0,92% postgres postgres [.] _bt_next + 0,92% postgres postgres [.] index_getnext_tid + 0,90% postgres postgres [.] ExecScan + 0,85% postgres postgres [.] IndexNext + 0,83% postgres postgres [.] XidInMVCCSnapshot + 0,81% postgres postgres [.] LWLockRelease + 0,71% postgres postgres [.] _bt_checkkeys + 0,69% postgres postgres [.] ReleaseBuffer + 0,57% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 + 0,53% postgres postgres [.] btgettuple 0,48% postgres postgres [.] _bt_check_compare.lto_priv.0 0,46% postgres postgres [.] MemoryContextReset 0,42% postgres postgres [.] hash_bytes 0,40% postgres postgres [.] ExecStoreBufferHeapTuple 0,36% postgres postgres [.] ResourceOwnerForget 0,35% postgres postgres [.] ExecNestLoop 0,33% postgres postgres [.] ExecEvalSysVar 0,32% postgres postgres [.] HeapTupleIsSurelyDead 0,27% postgres postgres [.] GlobalVisTestFor 0,26% postgres postgres [.] PredicateLockTID 0,22% postgres postgres [.] ReadBufferExtended 0,22% postgres postgres [.] tts_virtual_clear.lto_priv.0 0,21% postgres postgres [.] slot_getsomeattrs_int 0,19% postgres postgres [.] _bt_saveitem 0,19% postgres postgres [.] _bt_setuppostingitems 0,18% postgres postgres [.] ResourceOwnerEnlarge 0,17% postgres postgres [.] ExecIndexScan 0,14% postgres libc.so.6 [.] __memcmp_sse2 0,12% postgres postgres [.] pgstat_count_io_op 0,10% postgres postgres [.] int8eq 0,10% postgres postgres [.] HeapCheckForSerializableConflictOut
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Andres Freund <andres@anarazel.de> — 2025-10-08T13:04:03Z
Hi, On 2025-10-08 09:49:04 +0200, Marco Boeringa wrote: > Yes, you could be right this is not related to AIO at all, but another issue > introduced in PG18. Right. > For sure, I did not see this issue in <= PG17, so some change in PG18 is > causing it. Additionally, there is a small chance it might be related to > PostGIS, as that was upgraded as well (3.5.2 --> 3.6.0) during the PG > upgrade, as PG18 requires PostGIS 3.6.0 minimum. And the query does use > PostGIS functions, but none that AFAIK rely on e.g. a spatial > index. Functions like ST_Area just process an individual geometry, not the > spatial relationship between multiple geometries. Can you test this with postgis 3.6 on 17? > As I wrote before, this is a multi-threaded Python application (actually > developed in a GIS), that uses Python's 'concurrent.futures' threading > framework to create jobs of records to process for each thread, > significantly speeding up the processing. The queries are in fact > dynamically build by the code, and part of a much larger geoprocessing > workflow, so it is hard to run them separately and provide a query plan > (although in this case I could by rewriting part of the query below). > > However, I want to stress that any query plan is unlikely to yield > anything. In normal circumstances and in PG17 and below, this code runs > fine! And it is only 1 in maybe 4 runs in PG18 that goes berserk and makes a > processing step that should takes < 10 seconds, all of a sudden take > 2 > hours. The fact that it runs without a problem in 17 means it's actually rather meaningful to look at the query plan. It could have changed. Separately, it might help us to narrow down what changes to look at that could potentially be causing problems. > > So somehow >60% of the CPU time is spent fetching tuples corresponding to > index entries. That seems ... a lot. Is it possible that you have a lot of > dead rows in the involved tables? > > Yes, that is perfectly possible. However, the particular table is only just > over 100k records. > It is true that my code is designed to process literally *every* record in a > table. However, I specifically set adjusted table storage parameters with > much more aggressive vacuum settings (essentially forcing always vacuum > after something like 10k dead tuples irrespective of the size of the > table). This has worked really well, and I have successfully UPDATEd all of > Facebook Daylight size > 1B records tables with the same code, without ever > running into this particular issue, nor transaction ID wraparound issues. Making vacuum more aggressive won't really help much if you have longrunning queries/sessions, since vacuum can't clean up row versions that are still visibile to some of the transactions. > *** sudo perf -p <PID of one stuck postgres backend> -g -d 10 *** > *** sudo perf report --no-children *** > > Samples: 40K of event 'task-clock:ppp', Event count (approx.): 10008250000 > Overhead Command Shared Object Symbol > + 12,81% postgres postgres [.] LWLockAttemptLock > + 10,70% postgres postgres [.] heap_hot_search_buffer > + 9,27% postgres postgres [.] > tts_heap_getsomeattrs.lto_priv.0 > + 6,77% postgres postgres [.] LWLockReleaseInternal > + 5,89% postgres postgres [.] hash_search_with_hash_value > + 5,79% postgres postgres [.] ExecInterpExpr > + 4,14% postgres postgres [.] PinBuffer Could you "unfold" the callstacks for the top entries? And/or attach a perf report --no-children > somefile (when redirecting to a file perf will include much more detail than when using it interactively) Greetings, Andres Freund
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-08T17:46:42Z
Hi Andres, Thanks for all the help and suggestions so far! > Can you test this with postgis 3.6 on 17? If I find time... but looking through the release notes of PostGIS 3.6.0, I doubt the issue is in PostGIS, as there do not appear to be any changes to the specific PostGIS functions I am using. That doesn't exclude it though. > The fact that it runs without a problem in 17 means it's actually rather meaningful to look at the query plan. It could have changed. Separately, it might help us to narrow down what changes to look at that could potentially be causing problems. I would fully understand if this was an "ordinary" issue case with a simple self-contained query and with things going wrong each time in the same way. However, as said, besides the major issue of running the query separately from my geoprocessing workflow which involves many more steps - which would mean that any test outside of it would *not* be very much representative of what is going on inside my tool and geoprocessing workflow - there is the fact that things going wrong is a random anomaly. I cannot stress this enough: about 3-4 in 5 runs are OK, then a random follow up run *with exactly the same input data* turns out bad with the stall. Even if there was an easy way to run the query, I think the chance is highly likely the postgres query planner would come up with a decent plan, as in normal circumstances, there is no issue. > Making vacuum more aggressive won't really help much if you have longrunning queries/sessions, since vacuum can't clean up row versions that are still visibile to some of the transactions. My code batches the updates in sets of 2000 records at a time and then COMMITs, so the transactions themselves are limited in time and size, which should allow vacuum to do its job. > Could you "unfold" the callstacks for the top entries? And/or attach a perf report --no-children > somefile (when redirecting to a file perf will include much more detail than when using it interactively) See below: # Total Lost Samples: 0 # # Samples: 40K of event 'task-clock:ppp' # Event count (approx.): 10003250000 # # Overhead Command Shared Object Symbol # ........ ........ ................. ........................................... # 26.48% postgres postgres [.] LWLockAttemptLock | ---LWLockAttemptLock | |--23.15%--heapam_index_fetch_tuple.lto_priv.0 | index_fetch_heap | IndexNext | ExecScan | ExecNestLoop | ExecNestLoop | ExecModifyTable | standard_ExecutorRun | ProcessQuery | PortalRunMulti | PortalRun | exec_simple_query | PostgresMain | 0x5f3570fb9dbf | postmaster_child_launch | ServerLoop.isra.0 | PostmasterMain | main | __libc_start_call_main | __libc_start_main@@GLIBC_2.34 | _start | --3.30%--StartReadBuffer ReadBufferExtended | --3.25%--heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 15.81% postgres postgres [.] LWLockReleaseInternal | ---LWLockReleaseInternal | --15.71%--LWLockRelease | |--15.03%--heapam_index_fetch_tuple.lto_priv.0 | index_fetch_heap | IndexNext | ExecScan | ExecNestLoop | ExecNestLoop | ExecModifyTable | standard_ExecutorRun | ProcessQuery | PortalRunMulti | PortalRun | exec_simple_query | PostgresMain | 0x5f3570fb9dbf | postmaster_child_launch | ServerLoop.isra.0 | PostmasterMain | main | __libc_start_call_main | __libc_start_main@@GLIBC_2.34 | _start | --0.66%--StartReadBuffer ReadBufferExtended | --0.66%--heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 12.88% postgres postgres [.] ReleaseAndReadBuffer | ---ReleaseAndReadBuffer | --12.78%--heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 4.84% postgres postgres [.] tts_heap_getsomeattrs.lto_priv.0 | ---tts_heap_getsomeattrs.lto_priv.0 | --4.80%--slot_getsomeattrs_int ExecInterpExpr ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 4.64% postgres postgres [.] PinBuffer | ---PinBuffer | --4.64%--StartReadBuffer ReadBufferExtended | --4.57%--heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 3.67% postgres postgres [.] heap_hot_search_buffer | ---heap_hot_search_buffer | --3.61%--heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 3.47% postgres postgres [.] hash_search_with_hash_value | ---hash_search_with_hash_value | --3.45%--StartReadBuffer ReadBufferExtended | --3.35%--heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop | --3.34%--ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 2.97% postgres postgres [.] ExecInterpExpr | ---ExecInterpExpr | |--1.64%--ExecNestLoop | | | --1.60%--ExecNestLoop | ExecModifyTable | standard_ExecutorRun | ProcessQuery | PortalRunMulti | PortalRun | exec_simple_query | PostgresMain | 0x5f3570fb9dbf | postmaster_child_launch | ServerLoop.isra.0 | PostmasterMain | main | __libc_start_call_main | __libc_start_main@@GLIBC_2.34 | _start | --1.33%--ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 2.11% postgres postgres [.] UnpinBufferNoOwner.lto_priv.0 | ---UnpinBufferNoOwner.lto_priv.0 | |--1.24%--ExecStoreBufferHeapTuple | heapam_index_fetch_tuple.lto_priv.0 | index_fetch_heap | IndexNext | ExecScan | ExecNestLoop | ExecNestLoop | ExecModifyTable | standard_ExecutorRun | ProcessQuery | PortalRunMulti | PortalRun | exec_simple_query | PostgresMain | 0x5f3570fb9dbf | postmaster_child_launch | ServerLoop.isra.0 | PostmasterMain | main | __libc_start_call_main | __libc_start_main@@GLIBC_2.34 | _start | --0.81%--ReleaseAndReadBuffer heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 1.92% postgres postgres [.] heapam_index_fetch_tuple.lto_priv.0 | ---heapam_index_fetch_tuple.lto_priv.0 | --1.67%--index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 1.88% postgres postgres [.] StartReadBuffer | ---StartReadBuffer | --1.86%--ReadBufferExtended | --1.83%--heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 1.41% postgres postgres [.] LWLockAcquire | ---LWLockAcquire | --1.15%--heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 1.12% postgres postgres [.] heap_page_prune_opt | ---heap_page_prune_opt | --1.12%--heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 1.09% postgres postgres [.] HeapTupleSatisfiesVisibility | ---HeapTupleSatisfiesVisibility | --1.02%--heap_hot_search_buffer heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 1.00% postgres postgres [.] index_fetch_heap | ---index_fetch_heap | --0.83%--IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 0.97% postgres postgres [.] _bt_readpage | ---_bt_readpage | --0.97%--_bt_readnextpage _bt_next btgettuple index_getnext_tid IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 0.92% postgres postgres [.] _bt_next | ---_bt_next | --0.82%--btgettuple index_getnext_tid IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 0.92% postgres postgres [.] index_getnext_tid | ---index_getnext_tid | --0.82%--IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 0.90% postgres postgres [.] ExecScan | ---ExecScan ExecNestLoop | --0.83%--ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 0.85% postgres postgres [.] IndexNext | ---IndexNext | --0.80%--ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 0.83% postgres postgres [.] XidInMVCCSnapshot | ---XidInMVCCSnapshot 0.81% postgres postgres [.] LWLockRelease | ---LWLockRelease | --0.54%--heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 0.71% postgres postgres [.] _bt_checkkeys | ---_bt_checkkeys | --0.65%--_bt_readpage _bt_readnextpage _bt_next btgettuple index_getnext_tid IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 0.69% postgres postgres [.] ReleaseBuffer | ---ReleaseBuffer | --0.68%--ExecStoreBufferHeapTuple heapam_index_fetch_tuple.lto_priv.0 index_fetch_heap IndexNext ExecScan ExecNestLoop ExecNestLoop ExecModifyTable standard_ExecutorRun ProcessQuery PortalRunMulti PortalRun exec_simple_query PostgresMain 0x5f3570fb9dbf postmaster_child_launch ServerLoop.isra.0 PostmasterMain main __libc_start_call_main __libc_start_main@@GLIBC_2.34 _start 0.57% postgres postgres [.] GetPrivateRefCountEntry.lto_priv.0 | ---GetPrivateRefCountEntry.lto_priv.0 0.53% postgres postgres [.] btgettuple | ---btgettuple 0.48% postgres postgres [.] _bt_check_compare.lto_priv.0 0.46% postgres postgres [.] MemoryContextReset 0.42% postgres postgres [.] hash_bytes 0.40% postgres postgres [.] ExecStoreBufferHeapTuple 0.36% postgres postgres [.] ResourceOwnerForget 0.35% postgres postgres [.] ExecNestLoop 0.33% postgres postgres [.] ExecEvalSysVar 0.32% postgres postgres [.] HeapTupleIsSurelyDead 0.27% postgres postgres [.] GlobalVisTestFor 0.26% postgres postgres [.] PredicateLockTID 0.22% postgres postgres [.] ReadBufferExtended 0.22% postgres postgres [.] tts_virtual_clear.lto_priv.0 0.21% postgres postgres [.] slot_getsomeattrs_int 0.19% postgres postgres [.] _bt_saveitem 0.19% postgres postgres [.] _bt_setuppostingitems 0.18% postgres postgres [.] ResourceOwnerEnlarge 0.17% postgres postgres [.] ExecIndexScan 0.14% postgres libc.so.6 [.] __memcmp_sse2 0.12% postgres postgres [.] pgstat_count_io_op 0.10% postgres postgres [.] int8eq 0.10% postgres postgres [.] HeapCheckForSerializableConflictOut 0.10% postgres postgres [.] ReservePrivateRefCountEntry.lto_priv.0 0.09% postgres postgres [.] IncrBufferRefCount 0.06% postgres postgres [.] _bt_checkpage 0.03% postgres postgres [.] BufferGetLSNAtomic 0.03% postgres postgres [.] tag_hash 0.03% postgres postgres [.] LockBufHdr 0.03% postgres postgres [.] _bt_readnextpage 0.02% postgres postgres [.] tts_buffer_heap_getsomeattrs.lto_priv.0 0.02% postgres [kernel.kallsyms] [k] handle_softirqs 0.01% postgres postgres [.] _bt_steppage 0.01% postgres [kernel.kallsyms] [k] task_mm_cid_work 0.00% postgres [kernel.kallsyms] [k] _raw_spin_unlock_irq 0.00% postgres [kernel.kallsyms] [k] irqentry_exit_to_user_mode 0.00% postgres postgres [.] TransactionIdIsCurrentTransactionId 0.00% postgres postgres [.] index_rescan 0.00% postgres [kernel.kallsyms] [k] _raw_spin_unlock_irqrestore 0.00% postgres postgres [.] AllocSetAlloc 0.00% postgres postgres [.] PredicateLockPage 0.00% postgres postgres [.] _bt_set_startikey
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Andres Freund <andres@anarazel.de> — 2025-10-08T19:08:28Z
Hi, On 2025-10-08 19:46:42 +0200, Marco Boeringa wrote: > > The fact that it runs without a problem in 17 means it's actually rather > meaningful to look at the query plan. It could have changed. Separately, it > might help us to narrow down what changes to look at that could potentially > be causing problems. > > I would fully understand if this was an "ordinary" issue case with a simple > self-contained query and with things going wrong each time in the same way. > However, as said, besides the major issue of running the query separately > from my geoprocessing workflow which involves many more steps - which would > mean that any test outside of it would *not* be very much representative of > what is going on inside my tool and geoprocessing workflow - there is the > fact that things going wrong is a random anomaly. I cannot stress this > enough: about 3-4 in 5 runs are OK, then a random follow up run *with > exactly the same input data* turns out bad with the stall. Even if there was > an easy way to run the query, I think the chance is highly likely the > postgres query planner would come up with a decent plan, as in normal > circumstances, there is no issue. Even just knowing whether the "normal query plan" is the same one as we see in profiles of "stuck" backends is valuable. Even if the query plan is perfectly normal, it *still* is very important to know in which order the joins are evaluated etc. But there also might be changes in the query plan between 17 and 18 that trigger the issue... Without more details about what is expected to be run and what is actually happening, it's just about impossible for us to debug this without a reproducer that we can run and debug ourselves. > > Making vacuum more aggressive won't really help much if you have > longrunning queries/sessions, since vacuum can't clean up row versions that > are still visibile to some of the transactions. > > My code batches the updates in sets of 2000 records at a time and then > COMMITs, so the transactions themselves are limited in time and size, which > should allow vacuum to do its job. Are the "stuck" backends stuck within one 2000 record batch, or are they "just" slower processing each batch? > 26.48% postgres postgres [.] LWLockAttemptLock > | > ---LWLockAttemptLock > | > |--23.15%--heapam_index_fetch_tuple.lto_priv.0 > | index_fetch_heap > | IndexNext > | ExecScan > | ExecNestLoop > | ExecNestLoop > | ExecModifyTable > | standard_ExecutorRun > | ProcessQuery So the query plan we have is a nested loop between at least three tables (there are two joins, c.f. the two ExecNestLoop calls), where there presumably are a lot of row [versions] on the inner side of the innermost join. In [1] you showed a query. Reformated that looks like this: UPDATE osm.landcover_scrubs_small_scale_2_ply AS t1 SET area_geo = t2.area_geo, perim_geo = t2.perim_geo, compact_geo = CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END, npoints_geo = t2.npoints_geo, comp_npoints_geo = CASE WHEN t2.npoints_geo > 0 THEN (CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END / t2.npoints_geo) ELSE 0 END, convex_ratio_geo = CASE WHEN ST_Area(ST_ConvexHull(way)::geography,true) > 0 THEN (t2.area_geo / ST_Area(ST_ConvexHull(way)::geography,true)) ELSE 1 END FROM ( SELECT objectid, ST_Area(way::geography,true) AS area_geo, ST_Perimeter(way::geography,true) AS perim_geo, ST_NPoints(way) AS npoints_geo FROM osm.landcover_scrubs_small_scale_2_ply) AS t2 WHERE (t2.objectid = t1.objectid) AND t1.objectid IN (SELECT t3.objectid FROM mini_test.osm.osm_tmp_28128_ch5 AS t3) Which certainly fits with two nested loops, although I don't think I can infer which order it the joins are in. Is osm.landcover_scrubs_small_scale_2_ply.object_id unique? Can there be multiple rows for one object_id in mini_test.osm.osm_tmp_28128_ch5? Are there indexes on mini_test.osm.osm_tmp_28128_ch5.unique_id and osm.landcover_scrubs_small_scale_2_ply? Greetings, Andres Freund [1] https://www.postgresql.org/message-id/53b44572-0ceb-4149-b361-07da2da91032%40boeringa.demon.nl -
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-08T20:09:04Z
Hi Andres, > Even just knowing whether the "normal query plan" is the same one as we see in > profiles of "stuck" backends is valuable. Even if the query plan is perfectly > normal, it *still* is very important to know in which order the joins are > evaluated etc. But there also might be changes in the query plan between 17 > and 18 that trigger the issue... > > Without more details about what is expected to be run and what is actually > happening, it's just about impossible for us to debug this without a > reproducer that we can run and debug ourselves. I now encountered the auto_explain option in the PostgreSQL help. May sound stupid, but I hadn't been aware of this option. This might help in getting an explain during the actual execution of my tool, if I understand the option properly. This would be far more valuable - as being the "real" thing - than some contrived reproduction case. I will need to investigate this a bit more: https://www.postgresql.org/docs/current/auto-explain.html >>> Making vacuum more aggressive won't really help much if you have >> longrunning queries/sessions, since vacuum can't clean up row versions that >> are still visibile to some of the transactions. >> >> My code batches the updates in sets of 2000 records at a time and then >> COMMITs, so the transactions themselves are limited in time and size, which >> should allow vacuum to do its job. > > Are the "stuck" backends stuck within one 2000 record batch, or are they > "just" slower processing each batch? I can't tell. But to explain: each thread has its own set of jobs assigned, and each job will be batched in sets of 2000 records until COMMIT. So if one job has 100k records to process, 50 commits should occur for that job by one Python thread. I take care to avoid to process records totally randomly, which could cause conflicts and locking issues between threads attempting to access the same locked database page, significantly slowing down the processing. Records are assigned by database page (and depending on some other parameters), which has worked really well so far. Note that this is just a simplified version of the different processing modes I developed for different challenges and geoprocessing steps. >> 26.48% postgres postgres [.] LWLockAttemptLock >> | >> ---LWLockAttemptLock >> | >> |--23.15%--heapam_index_fetch_tuple.lto_priv.0 >> | index_fetch_heap >> | IndexNext >> | ExecScan >> | ExecNestLoop >> | ExecNestLoop >> | ExecModifyTable >> | standard_ExecutorRun >> | ProcessQuery > > So the query plan we have is a nested loop between at least three tables > (there are two joins, c.f. the two ExecNestLoop calls), where there presumably > are a lot of row [versions] on the inner side of the innermost join. > > In [1] you showed a query. Reformated that looks like this: > > UPDATE osm.landcover_scrubs_small_scale_2_ply AS t1 > SET area_geo = t2.area_geo, > perim_geo = t2.perim_geo, > compact_geo = CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END, > npoints_geo = t2.npoints_geo, > comp_npoints_geo = CASE WHEN t2.npoints_geo > 0 THEN (CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END / t2.npoints_geo) ELSE 0 END, > convex_ratio_geo = CASE WHEN ST_Area(ST_ConvexHull(way)::geography,true) > 0 THEN (t2.area_geo / ST_Area(ST_ConvexHull(way)::geography,true)) ELSE 1 END > FROM ( > SELECT > objectid, > ST_Area(way::geography,true) AS area_geo, > ST_Perimeter(way::geography,true) AS perim_geo, > ST_NPoints(way) AS npoints_geo > FROM osm.landcover_scrubs_small_scale_2_ply) AS t2 > WHERE (t2.objectid = t1.objectid) > AND t1.objectid IN (SELECT t3.objectid FROM mini_test.osm.osm_tmp_28128_ch5 AS t3) > > > Which certainly fits with two nested loops, although I don't think I can infer > which order it the joins are in. > > > Is osm.landcover_scrubs_small_scale_2_ply.object_id unique? Yes. > Can there be multiple rows for one object_id in > mini_test.osm.osm_tmp_28128_ch5? No. This table contains the records to process, which are unique. It is the job. It is a one-to-one join. > Are there indexes on mini_test.osm.osm_tmp_28128_ch5.unique_id and > osm.landcover_scrubs_small_scale_2_ply? Yes, the unique ids / objectid fields are indexed to allow an efficient join.
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-08T20:22:48Z
I noticed the formatting of the last email was totally screwed when displayed on postgresql.org's mail archive making it hard to read there, so a re-post of the last email, hopefully it will be better this time. Answers are intermingled with all the quotes, read carefully. Op 8-10-2025 om 22:09 schreef Marco Boeringa: > > Hi Andres, > Even just knowing whether the "normal query plan" is the > same one as we see in > profiles of "stuck" backends is valuable. Even > if the query plan is perfectly > normal, it *still* is very important > to know in which order the joins are > evaluated etc. But there also > might be changes in the query plan between 17 > and 18 that trigger > the issue... > > Without more details about what is expected to be run > and what is actually > happening, it's just about impossible for us to > debug this without a > reproducer that we can run and debug ourselves. > I now encountered the auto_explain option in the PostgreSQL help. May > sound stupid, but I hadn't been aware of this option. This might help > in getting an explain during the actual execution of my tool, if I > understand the option properly. This would be far more valuable - as > being the "real" thing - than some contrived reproduction case. I will > need to investigate this a bit more: > https://www.postgresql.org/docs/current/auto-explain.html >>> Making > vacuum more aggressive won't really help much if you have >> > longrunning queries/sessions, since vacuum can't clean up row versions > that >> are still visibile to some of the transactions. >> >> My code > batches the updates in sets of 2000 records at a time and then >> > COMMITs, so the transactions themselves are limited in time and size, > which >> should allow vacuum to do its job. > > Are the "stuck" > backends stuck within one 2000 record batch, or are they > "just" > slower processing each batch? I can't tell. But to explain: each > thread has its own set of jobs assigned, and each job will be batched > in sets of 2000 records until COMMIT. So if one job has 100k records > to process, 50 commits should occur for that job by one Python thread. > I take care to avoid to process records totally randomly, which could > cause conflicts and locking issues between threads attempting to > access the same locked database page, significantly slowing down the > processing. Records are assigned by database page (and depending on > some other parameters), which has worked really well so far. Note that > this is just a simplified version of the different processing modes I > developed for different challenges and geoprocessing steps. >> 26.48% > postgres postgres [.] LWLockAttemptLock >> | >> ---LWLockAttemptLock > >> | >> |--23.15%--heapam_index_fetch_tuple.lto_priv.0 >> | > index_fetch_heap >> | IndexNext >> | ExecScan >> | ExecNestLoop >> | > ExecNestLoop >> | ExecModifyTable >> | standard_ExecutorRun >> | > ProcessQuery > > So the query plan we have is a nested loop between at > least three tables > (there are two joins, c.f. the two ExecNestLoop > calls), where there presumably > are a lot of row [versions] on the > inner side of the innermost join. > > In [1] you showed a query. > Reformated that looks like this: > > UPDATE > osm.landcover_scrubs_small_scale_2_ply AS t1 > SET area_geo = > t2.area_geo, > perim_geo = t2.perim_geo, > compact_geo = CASE WHEN > t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * > pi())) ELSE 0 END, > npoints_geo = t2.npoints_geo, > comp_npoints_geo > = CASE WHEN t2.npoints_geo > 0 THEN (CASE WHEN t2.area_geo > 0 THEN > ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END / > t2.npoints_geo) ELSE 0 END, > convex_ratio_geo = CASE WHEN > ST_Area(ST_ConvexHull(way)::geography,true) > 0 THEN (t2.area_geo / > ST_Area(ST_ConvexHull(way)::geography,true)) ELSE 1 END > FROM ( > > SELECT > objectid, > ST_Area(way::geography,true) AS area_geo, > > ST_Perimeter(way::geography,true) AS perim_geo, > ST_NPoints(way) AS > npoints_geo > FROM osm.landcover_scrubs_small_scale_2_ply) AS t2 > > WHERE (t2.objectid = t1.objectid) > AND t1.objectid IN (SELECT > t3.objectid FROM mini_test.osm.osm_tmp_28128_ch5 AS t3) > > > Which > certainly fits with two nested loops, although I don't think I can > infer > which order it the joins are in. > > > Is > osm.landcover_scrubs_small_scale_2_ply.object_id unique? Yes. > Can > there be multiple rows for one object_id in > > mini_test.osm.osm_tmp_28128_ch5? No. This table contains the records > to process, which are unique. It is the job. > > It is a one-to-one join. > > > Are there indexes on mini_test.osm.osm_tmp_28128_ch5.unique_id and > osm.landcover_scrubs_small_scale_2_ply? Yes, the unique ids / > objectid fields are indexed to allow an efficient join. >
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-09T07:40:03Z
Last attempt to get the mail out in a proper format. I hate it when software gets "smart" with formatting... ;-( I added one minor detail to the last question of Andres at the entire bottom, see below. > Even just knowing whether the "normal query plan" is the same one as we see in > profiles of "stuck" backends is valuable. Even if the query plan is perfectly > normal, it *still* is very important to know in which order the joins are > evaluated etc. But there also might be changes in the query plan between 17 > and 18 that trigger the issue... > > Without more details about what is expected to be run and what is actually > happening, it's just about impossible for us to debug this without a > reproducer that we can run and debug ourselves. I now encountered the auto_explain option in the PostgreSQL help. May sound stupid, but I hadn't been aware of this option. This might help in getting an explain during the actual execution of my tool, if I understand the option properly. This would be far more valuable - as being the "real" thing - than some contrived reproduction case. I will need to investigate this a bit more: https://www.postgresql.org/docs/current/auto-explain.html >>> Making vacuum more aggressive won't really help much if you have >> longrunning queries/sessions, since vacuum can't clean up row versions that >> are still visibile to some of the transactions. >> >> My code batches the updates in sets of 2000 records at a time and then >> COMMITs, so the transactions themselves are limited in time and size, which >> should allow vacuum to do its job. > Are the "stuck" backends stuck within one 2000 record batch, or are they > "just" slower processing each batch? I can't tell. But to explain: each thread has its own set of jobs assigned, and each job will be batched in sets of 2000 records until COMMIT. So if one job has 100k records to process, 50 commits should occur for that job by one Python thread. I take care to avoid to process records totally randomly, which could cause conflicts and locking issues between threads attempting to access the same locked database page, significantly slowing down the processing. Records are assigned by database page (and depending on some other parameters), which has worked really well so far. Note that this is just a simplified version of the different processing modes I developed for different challenges and geoprocessing steps. >> 26.48% postgres postgres [.] LWLockAttemptLock >> | >> ---LWLockAttemptLock >> | >> |--23.15%--heapam_index_fetch_tuple.lto_priv.0 >> | index_fetch_heap >> | IndexNext >> | ExecScan >> | ExecNestLoop >> | ExecNestLoop >> | ExecModifyTable >> | standard_ExecutorRun >> | ProcessQuery > So the query plan we have is a nested loop between at least three tables > (there are two joins, c.f. the two ExecNestLoop calls), where there presumably > are a lot of row [versions] on the inner side of the innermost join. > > In [1] you showed a query. Reformated that looks like this: > > UPDATE osm.landcover_scrubs_small_scale_2_ply AS t1 > SET area_geo = t2.area_geo, > perim_geo = t2.perim_geo, > compact_geo = CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END, > npoints_geo = t2.npoints_geo, > comp_npoints_geo = CASE WHEN t2.npoints_geo > 0 THEN (CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END / t2.npoints_geo) ELSE 0 END, > convex_ratio_geo = CASE WHEN ST_Area(ST_ConvexHull(way)::geography,true) > 0 THEN (t2.area_geo / ST_Area(ST_ConvexHull(way)::geography,true)) ELSE 1 END > FROM ( > SELECT > objectid, > ST_Area(way::geography,true) AS area_geo, > ST_Perimeter(way::geography,true) AS perim_geo, > ST_NPoints(way) AS npoints_geo > FROM osm.landcover_scrubs_small_scale_2_ply) AS t2 > WHERE (t2.objectid = t1.objectid) > AND t1.objectid IN (SELECT t3.objectid FROM mini_test.osm.osm_tmp_28128_ch5 AS t3) > > > Which certainly fits with two nested loops, although I don't think I can infer > which order it the joins are in. > > > Is osm.landcover_scrubs_small_scale_2_ply.object_id unique? Yes. > Can there be multiple rows for one object_id in > mini_test.osm.osm_tmp_28128_ch5? No. This table contains the records to process, which are unique. It is the job. It is a one-to-one join. > Are there indexes on mini_test.osm.osm_tmp_28128_ch5.unique_id and > osm.landcover_scrubs_small_scale_2_ply? Yes, the unique ids / objectid fields are indexed to allow an efficient join. Actually, the "*_ch<number>" database object that represents the records to process for one job, references a database view. Each thread gets its own view. All views reference the same secondary table that has an index on the objectid.
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-10T10:03:02Z
Op 8-10-2025 om 21:08 schreef Andres Freund: > Even just knowing whether the "normal query plan" is the same one as we see in > profiles of "stuck" backends is valuable. Even if the query plan is perfectly > normal, it *still* is very important to know in which order the joins are > evaluated etc. But there also might be changes in the query plan between 17 > and 18 that trigger the issue... > > Without more details about what is expected to be run and what is actually > happening, it's just about impossible for us to debug this without a > reproducer that we can run and debug ourselves. > > Hi Andres, I have tried to get the auto_explain stuff to run, but that has not succeeded not yet. However, I realized that due to the extreme long "stall", it should be possible to simply copy out the visible SQL statement from pgAdmin and run it in a separate window, as the required (temporary) tables and views to run the SQL statement would be there at that point all the while the processing appears stuck, and run Explain simply from pgAdmin. This resulted in the plan I pasted below in JSON format. Any insights you gain from this in combination with the other stuff I shared and the answers I gave to your last questions? Marco "[ { ""Plan"": { ""Node Type"": ""ModifyTable"", ""Operation"": ""Update"", ""Parallel Aware"": false, ""Async Capable"": false, ""Relation Name"": ""landcover_grassy_small_scale_2_ply"", ""Schema"": ""osm"", ""Alias"": ""t1"", ""Startup Cost"": 1.14, ""Total Cost"": 9129.99, ""Plan Rows"": 0, ""Plan Width"": 0, ""Disabled"": false, ""Plans"": [ { ""Node Type"": ""Nested Loop"", ""Parent Relationship"": ""Outer"", ""Parallel Aware"": false, ""Async Capable"": false, ""Join Type"": ""Inner"", ""Startup Cost"": 1.14, ""Total Cost"": 9129.99, ""Plan Rows"": 70, ""Plan Width"": 62, ""Disabled"": false, ""Output"": [""st_area((landcover_grassy_small_scale_2_ply.way)::geography, true)"", ""st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, true)"", ""CASE WHEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, true) > '0'::double precision) THEN ((power(st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, true), '2'::double precision) / st_area((landcover_grassy_small_scale_2_ply.way)::geography, true)) / '12.566370614359172'::double precision) ELSE '0'::double precision END"", ""st_npoints(landcover_grassy_small_scale_2_ply.way)"", ""CASE WHEN (st_npoints(landcover_grassy_small_scale_2_ply.way) > 0) THEN (CASE WHEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, true) > '0'::double precision) THEN ((power(st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, true), '2'::double precision) / st_area((landcover_grassy_small_scale_2_ply.way)::geography, true)) / '12.566370614359172'::double precision) ELSE '0'::double precision END / (st_npoints(landcover_grassy_small_scale_2_ply.way))::double precision) ELSE '0'::double precision END"", ""CASE WHEN (st_area((st_convexhull(t1.way))::geography, true) > '0'::double precision) THEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, true) / st_area((st_convexhull(t1.way))::geography, true)) ELSE '1'::double precision END"", ""t1.ctid"", ""landcover_grassy_small_scale_2_ply.ctid"", ""landcover_grassy_small_scale_2_ply_pg.ctid""], ""Inner Unique"": true, ""Plans"": [ { ""Node Type"": ""Nested Loop"", ""Parent Relationship"": ""Outer"", ""Parallel Aware"": false, ""Async Capable"": false, ""Join Type"": ""Inner"", ""Startup Cost"": 0.72, ""Total Cost"": 173.50, ""Plan Rows"": 70, ""Plan Width"": 828, ""Disabled"": false, ""Output"": [""t1.way"", ""t1.ctid"", ""t1.objectid"", ""landcover_grassy_small_scale_2_ply_pg.ctid"", ""landcover_grassy_small_scale_2_ply_pg.objectid""], ""Inner Unique"": true, ""Plans"": [ { ""Node Type"": ""Index Scan"", ""Parent Relationship"": ""Outer"", ""Parallel Aware"": false, ""Async Capable"": false, ""Scan Direction"": ""Forward"", ""Index Name"": ""idx_osm_35"", ""Relation Name"": ""landcover_grassy_small_scale_2_ply_pg"", ""Schema"": ""osm"", ""Alias"": ""landcover_grassy_small_scale_2_ply_pg"", ""Startup Cost"": 0.29, ""Total Cost"": 3.70, ""Plan Rows"": 70, ""Plan Width"": 14, ""Disabled"": false, ""Output"": [""landcover_grassy_small_scale_2_ply_pg.ctid"", ""landcover_grassy_small_scale_2_ply_pg.objectid""], ""Index Cond"": ""((landcover_grassy_small_scale_2_ply_pg.page_number >= 28873) AND (landcover_grassy_small_scale_2_ply_pg.page_number < 29373))"" }, { ""Node Type"": ""Index Scan"", ""Parent Relationship"": ""Inner"", ""Parallel Aware"": false, ""Async Capable"": false, ""Scan Direction"": ""Forward"", ""Index Name"": ""landcover_grassy_small_scale_2_ply_pkey"", ""Relation Name"": ""landcover_grassy_small_scale_2_ply"", ""Schema"": ""osm"", ""Alias"": ""t1"", ""Startup Cost"": 0.42, ""Total Cost"": 2.43, ""Plan Rows"": 1, ""Plan Width"": 814, ""Disabled"": false, ""Output"": [""t1.way"", ""t1.ctid"", ""t1.objectid""], ""Index Cond"": ""(t1.objectid = landcover_grassy_small_scale_2_ply_pg.objectid)"" } ] }, { ""Node Type"": ""Index Scan"", ""Parent Relationship"": ""Inner"", ""Parallel Aware"": false, ""Async Capable"": false, ""Scan Direction"": ""Forward"", ""Index Name"": ""landcover_grassy_small_scale_2_ply_pkey"", ""Relation Name"": ""landcover_grassy_small_scale_2_ply"", ""Schema"": ""osm"", ""Alias"": ""landcover_grassy_small_scale_2_ply"", ""Startup Cost"": 0.42, ""Total Cost"": 0.64, ""Plan Rows"": 1, ""Plan Width"": 814, ""Disabled"": false, ""Output"": [""landcover_grassy_small_scale_2_ply.way"", ""landcover_grassy_small_scale_2_ply.ctid"", ""landcover_grassy_small_scale_2_ply.objectid""], ""Index Cond"": ""(landcover_grassy_small_scale_2_ply.objectid = t1.objectid)"" } ] } ] } } ]" -
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-12T08:24:51Z
Hi Andres, I have been doing a bit more investigation. As I explained before, the problematic multi-threaded geoprocessing step is not some stand-alone query that can be easily reduced to small easily portable reproducible case with attached data. In fact, this geoprocessing step is part of a large custom build Python geoprocessing workflow, with total code probably in the 25k code lines range. However, based on the apparent poor query plan in PG18 / PostGIS 3.6.0, I now reviewed the exact code once more. I noticed that just before entering the multi-threaded code that emits the queries as seen below, I am actually adding the primary key field 'objectid' as "GENERATED BY DEFAULT AS IDENTITY" to the 'osm.landcover_scrubs_small_scale_2_ply' table. Now I also noticed I did not run ANALYZE after that against the same table. I have now added this to the code. Although it is still preliminary, first tests seem to indicate that this resolves the issue, and prevents the stalls or better said apparent hugely inefficient query plan (remember: a < 10 sec process was turned into multi-hour). I still need to do more thorough testing to be sure though. However, this raises a couple of question: - While ANALYZE is of course hugely important for proper statistics and query planning, I have wondered if PostgreSQL shouldn't automatically have updated the statistics for the addition of the primary key with IDENTITY? It seems to me that based on the definition of the primary key column and IDENTITY and table size, the actual distribution of values is essentially already known even before any sampling of ANALYZE to update statistics? - Am I right to assume that only the statistics on the objectid field play any role in this issue? As you can see, the WHERE clause does not involve any other fields than the two objectid fields of the main table and the chunk table specifying the job. All other values computed are just derived straight from the geometry column. - Were there any hints in the all the other data I supplied as to where PG18's query planning without the updated statistics of the new ANALYZE step added, is going wrong? And why this was never an issue in <= PG17? I also did some preliminary test with the old PG17.6 / PostgGIS 3.6.0 cluster with the same Italy extract data. I still need to do more thorough testing, both with and without the extra ANALYZE step, to fully exclude that there isn't something related to the upgrade to PostGIS 3.6.0, but first indications are as I already saw with the PG17.6 / PostgGIS 3.5.3, that there are no issue with <= PG17 / PostGIS combination as regards this apparent planner issue. Marco Op 8-10-2025 om 21:08 schreef Andres Freund: > In [1] you showed a query. Reformated that looks like this: > > UPDATE osm.landcover_scrubs_small_scale_2_ply AS t1 > SET area_geo = t2.area_geo, > perim_geo = t2.perim_geo, > compact_geo = CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END, > npoints_geo = t2.npoints_geo, > comp_npoints_geo = CASE WHEN t2.npoints_geo > 0 THEN (CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END / t2.npoints_geo) ELSE 0 END, > convex_ratio_geo = CASE WHEN ST_Area(ST_ConvexHull(way)::geography,true) > 0 THEN (t2.area_geo / ST_Area(ST_ConvexHull(way)::geography,true)) ELSE 1 END > FROM ( > SELECT > objectid, > ST_Area(way::geography,true) AS area_geo, > ST_Perimeter(way::geography,true) AS perim_geo, > ST_NPoints(way) AS npoints_geo > FROM osm.landcover_scrubs_small_scale_2_ply) AS t2 > WHERE (t2.objectid = t1.objectid) > AND t1.objectid IN (SELECT t3.objectid FROM mini_test.osm.osm_tmp_28128_ch5 AS t3) > > > Which certainly fits with two nested loops, although I don't think I can infer > which order it the joins are in.
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-19T20:37:08Z
Hi Andres, I have now been able to capture an actual bad plan using PostgreSQL's 'auto_explain' option, so this the bad plan that makes a process and job that should take just a few seconds, cost more than 7 hours to execute. And this is of course without updating the tables statistics with ANALYZE after adding the primary key objectid, as that solved the issue in PG18. It is now clear where PostgreSQL spends all of its time when the bad plan is generated, see the loop number of the second index scan. I am not sure why in this nested loop, two index scans on essentially the same key and table are executed. You can compare this bad plan with the one below it, that was generated with EXPLAIN in pgAdmin, not from actual auto_explain output, but shows a different query execution plan. Note again: - I did not see the bad plan in PG<=17, even without the now added ANALYZE step that solves the issue in PG18. - The two tables involved ('landcover_grassy_small_scale_2_ply' and 'landcover_grassy_small_scale_2_ply_pg') both have primary keys and unique objectid indexes. - The join is one-to-one. 'landcover_grassy_small_scale_2_ply_pg' has unique values for objectids, so only record per corresponding record in 'landcover_grassy_small_scale_2_ply' - The 'osm_tmp_28232_ch3' references a database view and represents the chunk / multi-threaded job that needs to be executed from my Python code, and references a selection of the 'landcover_grassy_small_scale_2_ply_pg' table's records, which is the filter in the last index scan in the bad plan below. Marco *** ACTUAL BAD PLAN AS CAPTURED BY auto_explain ***: 2025-10-17 23:32:17.375 CEST [242803] osm@mini_test LOG: duration: 27133980.536 ms plan: Query Text: UPDATE osm.landcover_grassy_small_scale_2_ply AS t1 SET area_geo = t2.area_geo, perim_geo = t2.perim_geo, compact_geo = CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END, npoints_geo = t2.npoints_geo, comp_npoints_geo = CASE WHEN t2.npoints_geo > 0 THEN (CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END / t2.npoints_geo) ELSE 0 END, convex_ratio_geo = CASE WHEN ST_Area(ST_ConvexHull(way)::geography,true) > 0 THEN (t2.area_geo / ST_Area(ST_ConvexHull(way)::geography,true)) ELSE 1 END FROM (SELECT objectid,ST_Area(way::geography,true) AS area_geo,ST_Perimeter(way::geography,true) AS perim_geo,ST_NPoints(way) AS npoints_geo FROM osm.landcover_grassy_small_scale_2_ply) AS t2 WHERE (t2.objectid = t1.objectid) AND t1.objectid IN (SELECT t3.objectid FROM mini_test.osm.osm_tmp_28232_ch3 AS t3) Update on osm.landcover_grassy_small_scale_2_ply t1 (cost=1.17..134.56 rows=0 width=0) (actual time=27133980.532..27133980.534 rows=0.00 loops=1) Buffers: shared hit=7585627828 -> Nested Loop (cost=1.17..134.56 rows=1 width=62) (actual time=225948.297..27133979.894 rows=8.00 loops=1) Output: st_area((landcover_grassy_small_scale_2_ply.way)::geography, true), st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, true), CASE WHEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, true) > '0'::double precision) THEN ((power(st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, true), '2'::double precision) / st_area((landcover_grassy_small_scale_2_ply.way)::geography, true)) / '12.566370614359172'::double precision) ELSE '0'::double precision END, st_npoints(landcover_grassy_small_scale_2_ply.way), CASE WHEN (st_npoints(landcover_grassy_small_scale_2_ply.way) > 0) THEN (CASE WHEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, true) > '0'::double precision) THEN ((power(st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, true), '2'::double precision) / st_area((landcover_grassy_small_scale_2_ply.way)::geography, true)) / '12.566370614359172'::double precision) ELSE '0'::double precision END / (st_npoints(landcover_grassy_small_scale_2_ply.way))::double precision) ELSE '0'::double precision END, CASE WHEN (st_area((st_convexhull(t1.way))::geography, true) > '0'::double precision) THEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, true) / st_area((st_convexhull(t1.way))::geography, true)) ELSE '1'::double precision END, t1.ctid, landcover_grassy_small_scale_2_ply.ctid, landcover_grassy_small_scale_2_ply_pg.ctid Inner Unique: true Join Filter: (landcover_grassy_small_scale_2_ply.objectid = landcover_grassy_small_scale_2_ply_pg.objectid) Buffers: shared hit=7585627705 -> Nested Loop (cost=0.75..4.79 rows=1 width=620) (actual time=5.784..27131099.372 rows=222396.00 loops=1) Output: t1.way, t1.ctid, t1.objectid, landcover_grassy_small_scale_2_ply.way, landcover_grassy_small_scale_2_ply.ctid, landcover_grassy_small_scale_2_ply.objectid Inner Unique: true Join Filter: (t1.objectid = landcover_grassy_small_scale_2_ply.objectid) Rows Removed by Join Filter: 24729879210 Buffers: shared hit=7584737792 -> Index Scan using landcover_grassy_small_scale_2_ply_pkey on osm.landcover_grassy_small_scale_2_ply t1 (cost=0.38..2.39 rows=1 width=310) (actual time=5.176..462.613 rows=222396.00 loops=1) Output: t1.way, t1.ctid, t1.objectid Index Searches: 1 Buffers: shared hit=66411 -> Index Scan using landcover_grassy_small_scale_2_ply_pkey on osm.landcover_grassy_small_scale_2_ply (cost=0.38..2.39 rows=1 width=310) (actual time=0.035..114.709 rows=111198.50 loops=222396) Output: landcover_grassy_small_scale_2_ply.way, landcover_grassy_small_scale_2_ply.ctid, landcover_grassy_small_scale_2_ply.objectid Index Searches: 222396 Buffers: shared hit=7584671381 -> Index Scan using idx_osm_41 on osm.landcover_grassy_small_scale_2_ply_pg (cost=0.42..2.44 rows=1 width=14) (actual time=0.009..0.009 rows=0.00 loops=222396) Output: landcover_grassy_small_scale_2_ply_pg.ctid, landcover_grassy_small_scale_2_ply_pg.objectid Index Cond: (landcover_grassy_small_scale_2_ply_pg.objectid = t1.objectid) Filter: ((landcover_grassy_small_scale_2_ply_pg.page_number >= 31276) AND (landcover_grassy_small_scale_2_ply_pg.page_number < 31766)) Rows Removed by Filter: 1 Index Searches: 222396 Buffers: shared hit=889584 *** LIKELY GOOD PLAN AS GENERATED BY CAPTURING THE SQL AND RUNNING 'EXPLAIN' IN pgAdmin ***: "[ { ""Plan"": { ""Node Type"": ""ModifyTable"", ""Operation"": ""Update"", ""Parallel Aware"": false, ""Async Capable"": false, ""Relation Name"": ""landcover_grassy_small_scale_2_ply"", ""Schema"": ""osm"", ""Alias"": ""t1"", ""Startup Cost"": 1.14, ""Total Cost"": 9129.99, ""Plan Rows"": 0, ""Plan Width"": 0, ""Disabled"": false, ""Plans"": [ { ""Node Type"": ""Nested Loop"", ""Parent Relationship"": ""Outer"", ""Parallel Aware"": false, ""Async Capable"": false, ""Join Type"": ""Inner"", ""Startup Cost"": 1.14, ""Total Cost"": 9129.99, ""Plan Rows"": 70, ""Plan Width"": 62, ""Disabled"": false, ""Output"": [""st_area((landcover_grassy_small_scale_2_ply.way)::geography, true)"", ""st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, true)"", ""CASE WHEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, true) > '0'::double precision) THEN ((power(st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, true), '2'::double precision) / st_area((landcover_grassy_small_scale_2_ply.way)::geography, true)) / '12.566370614359172'::double precision) ELSE '0'::double precision END"", ""st_npoints(landcover_grassy_small_scale_2_ply.way)"", ""CASE WHEN (st_npoints(landcover_grassy_small_scale_2_ply.way) > 0) THEN (CASE WHEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, true) > '0'::double precision) THEN ((power(st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, true), '2'::double precision) / st_area((landcover_grassy_small_scale_2_ply.way)::geography, true)) / '12.566370614359172'::double precision) ELSE '0'::double precision END / (st_npoints(landcover_grassy_small_scale_2_ply.way))::double precision) ELSE '0'::double precision END"", ""CASE WHEN (st_area((st_convexhull(t1.way))::geography, true) > '0'::double precision) THEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, true) / st_area((st_convexhull(t1.way))::geography, true)) ELSE '1'::double precision END"", ""t1.ctid"", ""landcover_grassy_small_scale_2_ply.ctid"", ""landcover_grassy_small_scale_2_ply_pg.ctid""], ""Inner Unique"": true, ""Plans"": [ { ""Node Type"": ""Nested Loop"", ""Parent Relationship"": ""Outer"", ""Parallel Aware"": false, ""Async Capable"": false, ""Join Type"": ""Inner"", ""Startup Cost"": 0.72, ""Total Cost"": 173.50, ""Plan Rows"": 70, ""Plan Width"": 828, ""Disabled"": false, ""Output"": [""t1.way"", ""t1.ctid"", ""t1.objectid"", ""landcover_grassy_small_scale_2_ply_pg.ctid"", ""landcover_grassy_small_scale_2_ply_pg.objectid""], ""Inner Unique"": true, ""Plans"": [ { ""Node Type"": ""Index Scan"", ""Parent Relationship"": ""Outer"", ""Parallel Aware"": false, ""Async Capable"": false, ""Scan Direction"": ""Forward"", ""Index Name"": ""idx_osm_35"", ""Relation Name"": ""landcover_grassy_small_scale_2_ply_pg"", ""Schema"": ""osm"", ""Alias"": ""landcover_grassy_small_scale_2_ply_pg"", ""Startup Cost"": 0.29, ""Total Cost"": 3.70, ""Plan Rows"": 70, ""Plan Width"": 14, ""Disabled"": false, ""Output"": [""landcover_grassy_small_scale_2_ply_pg.ctid"", ""landcover_grassy_small_scale_2_ply_pg.objectid""], ""Index Cond"": ""((landcover_grassy_small_scale_2_ply_pg.page_number >= 28873) AND (landcover_grassy_small_scale_2_ply_pg.page_number < 29373))"" }, { ""Node Type"": ""Index Scan"", ""Parent Relationship"": ""Inner"", ""Parallel Aware"": false, ""Async Capable"": false, ""Scan Direction"": ""Forward"", ""Index Name"": ""landcover_grassy_small_scale_2_ply_pkey"", ""Relation Name"": ""landcover_grassy_small_scale_2_ply"", ""Schema"": ""osm"", ""Alias"": ""t1"", ""Startup Cost"": 0.42, ""Total Cost"": 2.43, ""Plan Rows"": 1, ""Plan Width"": 814, ""Disabled"": false, ""Output"": [""t1.way"", ""t1.ctid"", ""t1.objectid""], ""Index Cond"": ""(t1.objectid = landcover_grassy_small_scale_2_ply_pg.objectid)"" } ] }, { ""Node Type"": ""Index Scan"", ""Parent Relationship"": ""Inner"", ""Parallel Aware"": false, ""Async Capable"": false, ""Scan Direction"": ""Forward"", ""Index Name"": ""landcover_grassy_small_scale_2_ply_pkey"", ""Relation Name"": ""landcover_grassy_small_scale_2_ply"", ""Schema"": ""osm"", ""Alias"": ""landcover_grassy_small_scale_2_ply"", ""Startup Cost"": 0.42, ""Total Cost"": 0.64, ""Plan Rows"": 1, ""Plan Width"": 814, ""Disabled"": false, ""Output"": [""landcover_grassy_small_scale_2_ply.way"", ""landcover_grassy_small_scale_2_ply.ctid"", ""landcover_grassy_small_scale_2_ply.objectid""], ""Index Cond"": ""(landcover_grassy_small_scale_2_ply.objectid = t1.objectid)"" } ] } ] } } ]" Op 12-10-2025 om 10:24 schreef Marco Boeringa: > Hi Andres, > > I have been doing a bit more investigation. As I explained before, the > problematic multi-threaded geoprocessing step is not some stand-alone > query that can be easily reduced to small easily portable reproducible > case with attached data. In fact, this geoprocessing step is part of a > large custom build Python geoprocessing workflow, with total code > probably in the 25k code lines range. > > However, based on the apparent poor query plan in PG18 / PostGIS > 3.6.0, I now reviewed the exact code once more. I noticed that just > before entering the multi-threaded code that emits the queries as seen > below, I am actually adding the primary key field 'objectid' as > "GENERATED BY DEFAULT AS IDENTITY" to the > 'osm.landcover_scrubs_small_scale_2_ply' table. > > Now I also noticed I did not run ANALYZE after that against the same > table. I have now added this to the code. Although it is still > preliminary, first tests seem to indicate that this resolves the > issue, and prevents the stalls or better said apparent hugely > inefficient query plan (remember: a < 10 sec process was turned into > multi-hour). I still need to do more thorough testing to be sure though. > > However, this raises a couple of question: > > - While ANALYZE is of course hugely important for proper statistics > and query planning, I have wondered if PostgreSQL shouldn't > automatically have updated the statistics for the addition of the > primary key with IDENTITY? It seems to me that based on the definition > of the primary key column and IDENTITY and table size, the actual > distribution of values is essentially already known even before any > sampling of ANALYZE to update statistics? > > - Am I right to assume that only the statistics on the objectid field > play any role in this issue? As you can see, the WHERE clause does not > involve any other fields than the two objectid fields of the main > table and the chunk table specifying the job. All other values > computed are just derived straight from the geometry column. > > - Were there any hints in the all the other data I supplied as to > where PG18's query planning without the updated statistics of the new > ANALYZE step added, is going wrong? And why this was never an issue in > <= PG17? > > I also did some preliminary test with the old PG17.6 / PostgGIS 3.6.0 > cluster with the same Italy extract data. I still need to do more > thorough testing, both with and without the extra ANALYZE step, to > fully exclude that there isn't something related to the upgrade to > PostGIS 3.6.0, but first indications are as I already saw with > the PG17.6 / PostgGIS 3.5.3, that there are no issue with <= PG17 / > PostGIS combination as regards this apparent planner issue. > > Marco > > Op 8-10-2025 om 21:08 schreef Andres Freund: >> In [1] you showed a query. Reformated that looks like this: >> >> UPDATE osm.landcover_scrubs_small_scale_2_ply AS t1 >> SET area_geo = t2.area_geo, >> perim_geo = t2.perim_geo, >> compact_geo = CASE WHEN t2.area_geo > 0 THEN >> ((power(t2.perim_geo,2) / t2.area_geo) / (4 * pi())) ELSE 0 END, >> npoints_geo = t2.npoints_geo, >> comp_npoints_geo = CASE WHEN t2.npoints_geo > 0 THEN (CASE WHEN >> t2.area_geo > 0 THEN ((power(t2.perim_geo,2) / t2.area_geo) / (4 * >> pi())) ELSE 0 END / t2.npoints_geo) ELSE 0 END, >> convex_ratio_geo = CASE WHEN >> ST_Area(ST_ConvexHull(way)::geography,true) > 0 THEN (t2.area_geo / >> ST_Area(ST_ConvexHull(way)::geography,true)) ELSE 1 END >> FROM ( >> SELECT >> objectid, >> ST_Area(way::geography,true) AS area_geo, >> ST_Perimeter(way::geography,true) AS perim_geo, >> ST_NPoints(way) AS npoints_geo >> FROM osm.landcover_scrubs_small_scale_2_ply) AS t2 >> WHERE (t2.objectid = t1.objectid) >> AND t1.objectid IN (SELECT t3.objectid FROM >> mini_test.osm.osm_tmp_28128_ch5 AS t3) >> >> >> Which certainly fits with two nested loops, although I don't think I >> can infer >> which order it the joins are in. -
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
David Rowley <dgrowleyml@gmail.com> — 2025-10-20T01:33:35Z
On Mon, 20 Oct 2025 at 09:37, Marco Boeringa <marco@boeringa.demon.nl> wrote: > I am not sure why in this nested loop, two index scans on essentially > the same key and table are executed. You can compare this bad plan with The query contains a self-join, so that's why you're seeing the index scanned twice in the query plan. If that's not needed, then you should remove it from the query. If objectid is unique for this table then I don't see why you need to join the table again to access the very same row that you're updating. Just put those function calls in the UPDATE's SET clause. (We do have self join elimination in v18, but I see that it's a bit overly strict in what it removes around looking for duplicate relations when one of them is the query's result relation. Likely that can be made better so it still looks for duplicate relations including the result relation, but just never considers removing that one, only the other duplicate(s).) > *** ACTUAL BAD PLAN AS CAPTURED BY auto_explain ***: > -> Index Scan using > landcover_grassy_small_scale_2_ply_pkey on > osm.landcover_grassy_small_scale_2_ply t1 (cost=0.38..2.39 rows=1 > width=310) (actual time=5.176..462.613 rows=222396.00 loops=1) > Output: t1.way, t1.ctid, t1.objectid > Index Searches: 1 > Buffers: shared hit=66411 This table must have been VACUUMed or ANALYZEd either when it was empty or when it contained 1 row. There's no predicate here, so that estimate, aside from clamping to 1, comes directly from pg_class.reltuples. A new table or truncated table would never estimate 1 row as the planner always plays it safe when there are no statistics generated yet and assumes 10 pages worth of rows. I can't think of any specific reason why v18 behaves differently from v17 on this... Maybe you've gotten unlikely with an autovacuum timing thing and it's running at a slightly different time than in v17, perhaps because it completed the autovacuum of another table slightly quicker than v17 did. v18 can perform asynchronous reads for vacuum, maybe that could mean more vacuum_cost_page_hits and less vacuum_cost_page_misses when calculating vacuum_cost_limit. Or, perhaps you're doing something like performing a manual VACUUM after the tables have had all of their rows deleted? David
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-20T09:34:19Z
Hi David, To be honest I am not a SQL wizard like some of you here on the list, but part of the reason I setup the query as it currently is, is that the PostGIS function calls like ST_Area and ST_Perimeter can be very expensive depending on the complexity and size of the geometry, and I thus want to avoid at all cost to have to unnecessarily recalculate them multiple times in the same query. Maybe I am misunderstanding how PostgreSQL processes such queries, but I need the values multiple times to calculate some other parameters. So unless PostgreSQL is smart enough to cache the result and not execute ST_Area multiple times if it is used multiple times in the same query, I thought it wise to separate out the calculation and use the SELECT's results as input for the calculation of the other parameters. Maybe that isn't actually needed, but I think I remember seeing performance gains from the current setup when I initially wrote it this way, but I am not entirely sure at this point in time, it is a while ago. I know far to little about the internals of PostgreSQL and its exact query processing to say anything really sensible about this. A couple of things that still strike me: - As I wrote in a previous post, just before entering the Python multi-threaded processing that generates the jobs, I am adding a primary key column with unique objectids (GENERATED BY DEFAULT AS IDENTITY), that is subsequently used in the join. I realize this actually an enhancement request, but I am wondering why, if PostgreSQL already needs to dig through the entire table to add a new column with unique objectid values, it doesn't automatically update the statistics of the newly added column and write out the proper number of records of the table, that must be known by the end of the addition of the column, to the 'pg_class.reltuples' table you refer to? It seems to me it would save the need of the ANALYZE here, and at least ensure that there is some useful statistics available on the vital primary key column and about the relation size? - As I wrote in a previous post, the multi-threaded Python code creates multiple jobs (dozens). What I am seeing is that only part of the jobs is failing, and with some runs, none. E.g. I can run my tool 3 times without issues, than the fourth run some of the jobs get the bad plan (I only see this behavior in PG18, I never saw it in <= PG17). In all of these cases, the input data is *exactly* the same. The planning behavior therefor appears non-deterministic. As I understood it, PostgreSQL may indeed have non-deterministic behavior if it switches to the genetic algorithm on complex queries with many joins, but I have the feeling that my query doesn't quite satisfy that level of complexity? Or am I wrong here, and do you consider it likely it went through the genetic algorithm? It would actually be desirable if EXPLAIN (especially 'auto_explain') output always showed whether the genetic algorithm was activated, so one could judge if non-deterministic behavior of the planner is expected. - Lastly, did you notice the likely "good" plan I posted below the "bad" one. I generated that one by simply copy the visible query to pgAdmin and hitting EXPLAIN, so it's not the real thing as from 'auto_explain', but it does show some marked differences between the plan. Do you have any comments to add as to the differences? Marco Op 20-10-2025 om 03:33 schreef David Rowley: > On Mon, 20 Oct 2025 at 09:37, Marco Boeringa <marco@boeringa.demon.nl> wrote: >> I am not sure why in this nested loop, two index scans on essentially >> the same key and table are executed. You can compare this bad plan with > The query contains a self-join, so that's why you're seeing the index > scanned twice in the query plan. If that's not needed, then you should > remove it from the query. If objectid is unique for this table then I > don't see why you need to join the table again to access the very same > row that you're updating. Just put those function calls in the > UPDATE's SET clause. > > (We do have self join elimination in v18, but I see that it's a bit > overly strict in what it removes around looking for duplicate > relations when one of them is the query's result relation. Likely that > can be made better so it still looks for duplicate relations including > the result relation, but just never considers removing that one, only > the other duplicate(s).) > >> *** ACTUAL BAD PLAN AS CAPTURED BY auto_explain ***: >> -> Index Scan using >> landcover_grassy_small_scale_2_ply_pkey on >> osm.landcover_grassy_small_scale_2_ply t1 (cost=0.38..2.39 rows=1 >> width=310) (actual time=5.176..462.613 rows=222396.00 loops=1) >> Output: t1.way, t1.ctid, t1.objectid >> Index Searches: 1 >> Buffers: shared hit=66411 > This table must have been VACUUMed or ANALYZEd either when it was > empty or when it contained 1 row. There's no predicate here, so that > estimate, aside from clamping to 1, comes directly from > pg_class.reltuples. A new table or truncated table would never > estimate 1 row as the planner always plays it safe when there are no > statistics generated yet and assumes 10 pages worth of rows. I can't > think of any specific reason why v18 behaves differently from v17 on > this... Maybe you've gotten unlikely with an autovacuum timing thing > and it's running at a slightly different time than in v17, perhaps > because it completed the autovacuum of another table slightly quicker > than v17 did. v18 can perform asynchronous reads for vacuum, maybe > that could mean more vacuum_cost_page_hits and less > vacuum_cost_page_misses when calculating vacuum_cost_limit. > > Or, perhaps you're doing something like performing a manual VACUUM > after the tables have had all of their rows deleted? > > David
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-20T11:22:45Z
Hi David, I wrote in my last post somewhere: "In all of these cases, the input data is *exactly* the same." I think I need to correct this. Although the input base table 'landcover_grassy_small_scale_2_ply' is the same and the number of records it has as well for each run, the actual contents of the database views that represent the multi-threading jobs (in the example below 'osm_tmp_28232_ch3'), and the number of records they refer to, *can* vary in a non-deterministic way, anywhere from 0 to about 5000 records. Most jobs have several thousands, close to the limit of 5000, but some can have considerably less. Actually, it appears that most of jobs getting the bad plan have the lower number of records (dozens to a few hundreds, instead of a few thousands), at least that is what I saw with the last run, but I would need to do further testing to confirm. That said, they are implemented as non-materialized ordinary database views, so don't have their own statistics and such (the underlying table the views refer to is a secondary table called ' landcover_grassy_small_scale_2_ply_pg' derived from 'landcover_grassy_small_scale_2_ply' that was visible in the 'auto_explain' output)? So this shouldn't actually be that relevant? Marco See query below for reference: UPDATE osm.landcover_grassy_small_scale_2_ply AS t1 SET area_geo = t2.area_geo, perim_geo = t2.perim_geo, compact_geo = CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo, 2) / t2.area_geo) / (4 * pi())) ELSE 0 END, npoints_geo = t2.npoints_geo, comp_npoints_geo = CASE WHEN t2.npoints_geo > 0 THEN (CASE WHEN t2.area_geo > 0 THEN ((power(t2.perim_geo, 2) / t2.area_geo) / (4 * pi())) ELSE 0 END / t2.npoints_geo) ELSE 0 END, convex_ratio_geo = CASE WHEN ST_Area(ST_ConvexHull(way)::geography, TRUE) > 0 THEN (t2.area_geo / ST_Area(ST_ConvexHull(way)::geography, TRUE)) ELSE 1 END FROM ( SELECT objectid, ST_Area(way::geography, TRUE) AS area_geo, ST_Perimeter(way::geography, TRUE) AS perim_geo, ST_NPoints(way) AS npoints_geo FROM osm.landcover_grassy_small_scale_2_ply) AS t2 WHERE (t2.objectid = t1.objectid) AND t1.objectid IN ( SELECT t3.objectid FROM mini_test.osm.osm_tmp_28232_ch3 AS t3) Op 20-10-2025 om 11:34 schreef Marco Boeringa: > Hi David, > > To be honest I am not a SQL wizard like some of you here on the list, > but part of the reason I setup the query as it currently is, is that > the PostGIS function calls like ST_Area and ST_Perimeter can be very > expensive depending on the complexity and size of the geometry, and I > thus want to avoid at all cost to have to unnecessarily recalculate > them multiple times in the same query. Maybe I am misunderstanding how > PostgreSQL processes such queries, but I need the values multiple > times to calculate some other parameters. So unless PostgreSQL is > smart enough to cache the result and not execute ST_Area multiple > times if it is used multiple times in the same query, I thought it > wise to separate out the calculation and use the SELECT's results as > input for the calculation of the other parameters. Maybe that isn't > actually needed, but I think I remember seeing performance gains from > the current setup when I initially wrote it this way, but I am not > entirely sure at this point in time, it is a while ago. I know far to > little about the internals of PostgreSQL and its exact query > processing to say anything really sensible about this. > > A couple of things that still strike me: > > - As I wrote in a previous post, just before entering the Python > multi-threaded processing that generates the jobs, I am adding a > primary key column with unique objectids (GENERATED BY DEFAULT AS > IDENTITY), that is subsequently used in the join. I realize this > actually an enhancement request, but I am wondering why, if PostgreSQL > already needs to dig through the entire table to add a new column with > unique objectid values, it doesn't automatically update the statistics > of the newly added column and write out the proper number of records > of the table, that must be known by the end of the addition of the > column, to the 'pg_class.reltuples' table you refer to? It seems to me > it would save the need of the ANALYZE here, and at least ensure that > there is some useful statistics available on the vital primary key > column and about the relation size? > > - As I wrote in a previous post, the multi-threaded Python code > creates multiple jobs (dozens). What I am seeing is that only part of > the jobs is failing, and with some runs, none. E.g. I can run my tool > 3 times without issues, than the fourth run some of the jobs get the > bad plan (I only see this behavior in PG18, I never saw it in <= > PG17). In all of these cases, the input data is *exactly* the same. > The planning behavior therefor appears non-deterministic. As I > understood it, PostgreSQL may indeed have non-deterministic behavior > if it switches to the genetic algorithm on complex queries with many > joins, but I have the feeling that my query doesn't quite satisfy that > level of complexity? Or am I wrong here, and do you consider it likely > it went through the genetic algorithm? It would actually be desirable > if EXPLAIN (especially 'auto_explain') output always showed whether > the genetic algorithm was activated, so one could judge if > non-deterministic behavior of the planner is expected. > > - Lastly, did you notice the likely "good" plan I posted below the > "bad" one. I generated that one by simply copy the visible query to > pgAdmin and hitting EXPLAIN, so it's not the real thing as from > 'auto_explain', but it does show some marked differences between the > plan. Do you have any comments to add as to the differences? > > Marco > > Op 20-10-2025 om 03:33 schreef David Rowley: >> On Mon, 20 Oct 2025 at 09:37, Marco Boeringa >> <marco@boeringa.demon.nl> wrote: >>> I am not sure why in this nested loop, two index scans on essentially >>> the same key and table are executed. You can compare this bad plan with >> The query contains a self-join, so that's why you're seeing the index >> scanned twice in the query plan. If that's not needed, then you should >> remove it from the query. If objectid is unique for this table then I >> don't see why you need to join the table again to access the very same >> row that you're updating. Just put those function calls in the >> UPDATE's SET clause. >> >> (We do have self join elimination in v18, but I see that it's a bit >> overly strict in what it removes around looking for duplicate >> relations when one of them is the query's result relation. Likely that >> can be made better so it still looks for duplicate relations including >> the result relation, but just never considers removing that one, only >> the other duplicate(s).) >> >>> *** ACTUAL BAD PLAN AS CAPTURED BY auto_explain ***: >>> -> Index Scan using >>> landcover_grassy_small_scale_2_ply_pkey on >>> osm.landcover_grassy_small_scale_2_ply t1 (cost=0.38..2.39 rows=1 >>> width=310) (actual time=5.176..462.613 rows=222396.00 loops=1) >>> Output: t1.way, t1.ctid, t1.objectid >>> Index Searches: 1 >>> Buffers: shared hit=66411 >> This table must have been VACUUMed or ANALYZEd either when it was >> empty or when it contained 1 row. There's no predicate here, so that >> estimate, aside from clamping to 1, comes directly from >> pg_class.reltuples. A new table or truncated table would never >> estimate 1 row as the planner always plays it safe when there are no >> statistics generated yet and assumes 10 pages worth of rows. I can't >> think of any specific reason why v18 behaves differently from v17 on >> this... Maybe you've gotten unlikely with an autovacuum timing thing >> and it's running at a slightly different time than in v17, perhaps >> because it completed the autovacuum of another table slightly quicker >> than v17 did. v18 can perform asynchronous reads for vacuum, maybe >> that could mean more vacuum_cost_page_hits and less >> vacuum_cost_page_misses when calculating vacuum_cost_limit. >> >> Or, perhaps you're doing something like performing a manual VACUUM >> after the tables have had all of their rows deleted? >> >> David
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-20T14:42:32Z
Op 20-10-2025 om 11:34 schreef Marco Boeringa: > Hi David, > > To be honest I am not a SQL wizard like some of you here on the list, > but part of the reason I setup the query as it currently is, is that > the PostGIS function calls like ST_Area and ST_Perimeter can be very > expensive depending on the complexity and size of the geometry, and I > thus want to avoid at all cost to have to unnecessarily recalculate > them multiple times in the same query. Maybe I am misunderstanding how > PostgreSQL processes such queries, but I need the values multiple > times to calculate some other parameters. So unless PostgreSQL is > smart enough to cache the result and not execute ST_Area multiple > times if it is used multiple times in the same query, I thought it > wise to separate out the calculation and use the SELECT's results as > input for the calculation of the other parameters. Maybe that isn't > actually needed, but I think I remember seeing performance gains from > the current setup when I initially wrote it this way, but I am not > entirely sure at this point in time, it is a while ago. I know far to > little about the internals of PostgreSQL and its exact query > processing to say anything really sensible about this. > Hi David, Looking through the 'auto_explain' output of the bad query plan, I noticed the below included clause as generated by the planner. In the context of what I actually wrote above about the desire to not run expensive function calls like ST_Area multiple times, do I understand it correctly from the 'auto_explain' output excerpt that PostgreSQL, by removing the self join, actually *does* run the ST_Area and ST_Perimeter multiple times? Is this how I need to interpret this part of the 'auto_explain' output? If there is no caching of the function result, this could be expensive as well. Marco *** 'auto_explain' output excerpt ***: st_area((landcover_grassy_small_scale_2_ply.way)::geography, TRUE), st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, TRUE), CASE WHEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, TRUE) > '0'::double PRECISION) THEN ((power(st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, TRUE), '2'::double PRECISION) / st_area((landcover_grassy_small_scale_2_ply.way)::geography, TRUE)) / '12.566370614359172'::double PRECISION) ELSE '0'::double PRECISION END, st_npoints(landcover_grassy_small_scale_2_ply.way), CASE WHEN (st_npoints(landcover_grassy_small_scale_2_ply.way) > 0) THEN (CASE WHEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, TRUE) > '0'::double PRECISION) THEN ((power(st_perimeter((landcover_grassy_small_scale_2_ply.way)::geography, TRUE), '2'::double PRECISION) / st_area((landcover_grassy_small_scale_2_ply.way)::geography, TRUE)) / '12.566370614359172'::double PRECISION) ELSE '0'::double PRECISION END / (st_npoints(landcover_grassy_small_scale_2_ply.way))::double PRECISION) ELSE '0'::double PRECISION END, CASE WHEN (st_area((st_convexhull(t1.way))::geography, TRUE) > '0'::double PRECISION) THEN (st_area((landcover_grassy_small_scale_2_ply.way)::geography, TRUE) / st_area((st_convexhull(t1.way))::geography, TRUE)) ELSE '1'::double PRECISION END, t1.ctid, landcover_grassy_small_scale_2_ply.ctid, landcover_grassy_small_scale_2_ply_pg.ctid
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
David Rowley <dgrowleyml@gmail.com> — 2025-10-20T19:09:30Z
On Tue, 21 Oct 2025 at 03:42, Marco Boeringa <marco@boeringa.demon.nl> wrote: > Looking through the 'auto_explain' output of the bad query plan, I > noticed the below included clause as generated by the planner. In the > context of what I actually wrote above about the desire to not run > expensive function calls like ST_Area multiple times, do I understand it > correctly from the 'auto_explain' output excerpt that PostgreSQL, by > removing the self join, actually *does* run the ST_Area and ST_Perimeter > multiple times? Is this how I need to interpret this part of the > 'auto_explain' output? If there is no caching of the function result, > this could be expensive as well. So you basically have something like: UPDATE t t1 SET col1 = t2.a1, col2 = t2.a2 FROM (SELECT unique_col, f1(col3) as a1, f2(col4) as a2 FROM t) AS t2 WHERE t1.unique_col = t2.unique_col AND <other filter clauses> Assuming here that unique_col has a UNIQUE or PK constraint. The self join basically amounts to wasted effort. There is no function result caching anywhere. Looking at the EXPLAIN output, it seems those functions are executed once per row that's output from the join and just below the "Update" node and they're executed 8 times. That won't change if you get rid of the self join. David
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-20T20:02:35Z
Hi David, Thanks for the explanation. Back when I developed this, I am pretty sure I tried to find out the answer to this, but was left somewhat confused as to the results of subqueries in relation to this aspect of avoiding doing unnecessary work related to costly functions. E.g. this very old StackOverflow post of Erwin Brandstetter, who's name I have seen come up in that discussion forum a lot with what suggests based on his answers a pretty thorough knowledge of PostgreSQL and databases in general, at least suggested a subquery could work: https://stackoverflow.com/questions/20718499/does-postgresql-cache-function-calls#comment31095072_20718499 And in relation to that post and thread, and the suggestion of WITH / CTE clause, would that be a suitable substitute and avoid the recalling of the functions? I assume with the MATERIALIZED option, it should, that is what the MATERIALIZED option is for, isn't it? Marco Op 20-10-2025 om 21:09 schreef David Rowley: > On Tue, 21 Oct 2025 at 03:42, Marco Boeringa <marco@boeringa.demon.nl> wrote: >> Looking through the 'auto_explain' output of the bad query plan, I >> noticed the below included clause as generated by the planner. In the >> context of what I actually wrote above about the desire to not run >> expensive function calls like ST_Area multiple times, do I understand it >> correctly from the 'auto_explain' output excerpt that PostgreSQL, by >> removing the self join, actually *does* run the ST_Area and ST_Perimeter >> multiple times? Is this how I need to interpret this part of the >> 'auto_explain' output? If there is no caching of the function result, >> this could be expensive as well. > So you basically have something like: > > UPDATE t t1 SET col1 = t2.a1, col2 = t2.a2 > FROM (SELECT unique_col, f1(col3) as a1, f2(col4) as a2 FROM t) AS t2 > WHERE t1.unique_col = t2.unique_col > AND <other filter clauses> > > Assuming here that unique_col has a UNIQUE or PK constraint. The self > join basically amounts to wasted effort. There is no function result > caching anywhere. Looking at the EXPLAIN output, it seems those > functions are executed once per row that's output from the join and > just below the "Update" node and they're executed 8 times. That won't > change if you get rid of the self join. > > David
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
David Rowley <dgrowleyml@gmail.com> — 2025-10-20T21:06:51Z
On Tue, 21 Oct 2025 at 09:02, Marco Boeringa <marco@boeringa.demon.nl> wrote: > https://stackoverflow.com/questions/20718499/does-postgresql-cache-function-calls#comment31095072_20718499 > > And in relation to that post and thread, and the suggestion of WITH / > CTE clause, would that be a suitable substitute and avoid the recalling > of the functions? I assume with the MATERIALIZED option, it should, that > is what the MATERIALIZED option is for, isn't it? That article states "this function is invoked multiple times with the same parameter", so doesn't sound very applicable for your case since your function parameter changes with every row. I don't see how WITH MATERIALIZED could help you here as that's not a parameterized cache. I suppose we could adjust the planner to consider something similar to Memoize for caching results for expensive stable functions. We'd have to put a lot of trust into n_distinct estimates and the function(s) COST setting, however. I suspect you're trying to optimise for something that's not an actual problem. David
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-20T21:57:54Z
Hi David, PostGIS functions can be very expensive, especially in the context of the fact that Polygon and Line geometries can vary vastly in size in terms of the number of vertices that constitute them, which has a profound impact on some PostGIS function calls, merely due to the enormous complexity of some shapes. But of course you're right that any change will need some thorough testing before assuming it will actually benefit the queries. Marco Op 20-10-2025 om 23:06 schreef David Rowley: > On Tue, 21 Oct 2025 at 09:02, Marco Boeringa <marco@boeringa.demon.nl> wrote: >> https://stackoverflow.com/questions/20718499/does-postgresql-cache-function-calls#comment31095072_20718499 >> >> And in relation to that post and thread, and the suggestion of WITH / >> CTE clause, would that be a suitable substitute and avoid the recalling >> of the functions? I assume with the MATERIALIZED option, it should, that >> is what the MATERIALIZED option is for, isn't it? > That article states "this function is invoked multiple times with the > same parameter", so doesn't sound very applicable for your case since > your function parameter changes with every row. > > I don't see how WITH MATERIALIZED could help you here as that's not a > parameterized cache. I suppose we could adjust the planner to consider > something similar to Memoize for caching results for expensive stable > functions. We'd have to put a lot of trust into n_distinct estimates > and the function(s) COST setting, however. > > I suspect you're trying to optimise for something that's not an actual problem. > > David
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
David Rowley <dgrowleyml@gmail.com> — 2025-10-20T22:16:13Z
On Tue, 21 Oct 2025 at 10:57, Marco Boeringa <marco@boeringa.demon.nl> wrote: > PostGIS functions can be very expensive, especially in the context of > the fact that Polygon and Line geometries can vary vastly in size in > terms of the number of vertices that constitute them, which has a > profound impact on some PostGIS function calls, merely due to the > enormous complexity of some shapes. How expensive the function call is is irrelevant as there simply is no function result caching going on and there's nothing wired up in any released version of PostgreSQL which gives you this with the query you've written. You still seem to be under the illusion that the self-join is giving you some sort of caching. If you remain content in not trusting me on that, by all means, create a plpgsql function with a RAISE NOTICE and try it out for yourself. > But of course you're right that any change will need some thorough > testing before assuming it will actually benefit the queries. I don't recall talking about testing... (It may help if you quote things you're replying to. This conversation will be quite hard to follow with your top post replies.) This whole conversation has drifted well off what the original report was about, so I think it's better if you need more help on this to use pgsql-performance@lists.postgresql.org David
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
Marco Boeringa <marco@boeringa.demon.nl> — 2025-10-20T22:46:40Z
Hi David, I totally understood your remarks about no caching going on, and don't intend to keep the query as-is with self join if I decide to make and benchmark any changes. Any changes will certainly either involve a WITH / CTE materialized, or first writing out some temporary table with the results of the expensive function calls to be able to re-use them from there. Whether any of that will result in any measurable change and benefits, will require thorough testing. Yes, you are right this has drifted. I don't need any more help and this issue can essentially be closed, I just wanted to report the fact that an application and workflow that has run for years without issues, was heavily affected by the (planner) changes for PG18. I have submitted all data I can on this, and the culprit is now clear, also thanks to Andres's useful (debugging) suggestions. It is also clear what the solution in my case is, the extra ANALYZE run I added to my code. So, as said, I don't need more help, although answers to some of unanswered questions regarding specific observations I made (e.g. PG18 versus PG17 and lower) would still be welcome, e.g. to repeat from previous posts.: - As I wrote in a previous post, just before entering the Python multi-threaded processing that generates the jobs, I am adding a primary key column with unique objectids (GENERATED BY DEFAULT AS IDENTITY), that is subsequently used in the join. I realize this actually an enhancement request, but I am wondering why, if PostgreSQL already needs to dig through the entire table to add a new column with unique objectid values, it doesn't automatically update the statistics of the newly added column and write out the proper number of records of the table, that must be known by the end of the addition of the column, to the 'pg_class.reltuples' table you refer to? It seems to me it would save the need of the ANALYZE here, and at least ensure that there is some useful statistics available on the vital primary key column and about the relation size? - As I wrote in a previous post, the multi-threaded Python code creates multiple jobs (dozens). What I am seeing is that only part of the jobs is failing, and with some runs, none. E.g. I can run my tool 3 times without issues, than the fourth run some of the jobs get the bad plan (I only see this behavior in PG18, I never saw it in <= PG17). In all of these cases, the input data is *exactly* the same. The planning behavior therefor appears non-deterministic. As I understood it, PostgreSQL may indeed have non-deterministic behavior if it switches to the genetic algorithm on complex queries with many joins, but I have the feeling that my query doesn't quite satisfy that level of complexity? Or am I wrong here, and do you consider it likely it went through the genetic algorithm? It would actually be desirable if EXPLAIN (especially 'auto_explain') output always showed whether the genetic algorithm was activated, so one could judge if non-deterministic behavior of the planner is expected. But having no answers to these questions is not a major issue, it is just my curiosity. Thanks for your answers and contributions so far, Marco Op 21-10-2025 om 00:16 schreef David Rowley: > On Tue, 21 Oct 2025 at 10:57, Marco Boeringa <marco@boeringa.demon.nl> wrote: >> PostGIS functions can be very expensive, especially in the context of >> the fact that Polygon and Line geometries can vary vastly in size in >> terms of the number of vertices that constitute them, which has a >> profound impact on some PostGIS function calls, merely due to the >> enormous complexity of some shapes. > How expensive the function call is is irrelevant as there simply is no > function result caching going on and there's nothing wired up in any > released version of PostgreSQL which gives you this with the query > you've written. > > You still seem to be under the illusion that the self-join is giving > you some sort of caching. If you remain content in not trusting me on > that, by all means, create a plpgsql function with a RAISE NOTICE and > try it out for yourself. > >> But of course you're right that any change will need some thorough >> testing before assuming it will actually benefit the queries. > I don't recall talking about testing... (It may help if you quote > things you're replying to. This conversation will be quite hard to > follow with your top post replies.) > > This whole conversation has drifted well off what the original report > was about, so I think it's better if you need more help on this to use > pgsql-performance@lists.postgresql.org > > David
-
Re: Potential "AIO / io workers" inter-worker locking issue in PG18?
David Rowley <dgrowleyml@gmail.com> — 2025-10-21T00:44:52Z
On Tue, 21 Oct 2025 at 11:46, Marco Boeringa <marco@boeringa.demon.nl> wrote: > I totally understood your remarks about no caching going on, and don't > intend to keep the query as-is with self join if I decide to make and > benchmark any changes. Any changes will certainly either involve a WITH > / CTE materialized, or first writing out some temporary table with the > results of the expensive function calls to be able to re-use them from > there. To get what you want, you'd need to do something like add OFFSET 0 to the subquery. That would prevent the planner from pulling it up into the main query. However, if you do that, it'll mean running those PostGIS functions on every row in the landcover_grassy_small_scale_2_ply table. You could get around that by either moving or duplicating the "t1.objectid IN (SELECT t3.objectid FROM mini_test.osm.osm_tmp_28232_ch3 AS t3)" and putting it in the WHERE clause of the subquery. David