FW: Query execution failure

Resending this with all the text in the body of the email rather than as a Word attachment.

PostgreSQL Bug Report

Overview
When trying to run a complex join of eight tables - including 6 foreign tables - the query runs for a few seconds and then terminates with an error message
This occurs ONLY in the Dev environment; the query executes successfully in our Production environment, although it returns zero rows.
The query
Here is the query that is causing the problem:
SELECT
dk.deployment_id,
dk.deployment_key_txt,
dp.name as deployment_nm,
dp.tenant as deployment_tenant_nm,
infc.name as deployment_cluster_nm,
icv.description as cluster_kubernetes_version_id,
infc.nodes as cluster_node_no,
infc.ram as cluster_ram_no,
infc.cpu as cluster_cpu_no,
infc.disk as cluster_disk_no,
dp.deploy_description as infrastructure_desc,
CASE
WHEN infrq.multi_master = 1 THEN 'Y'
else 'N'
END
AS HA_multi_master_flg,
infrq.cluster_label as cluster_environment_desc,
dl.deploy_time as deployment_deploy_tm,
dl.order_number as order_no_id,
ob.order_id as order_id,
dp.server as deployment_host_nm,
to_timestamp(CAST(dl."timestamp" AS double precision)) as deployment_created_dttm,
dl.promotion_stage as promotion_stage_cd,
se.ship_event_nm as ship_event_nm,
'UDANEXT' as source_system_cd
FROM foreign_udanext.deployments dp
LEFT OUTER JOIN foreign_udanext.deployment_log dl ON (dl.deploy_id = dp.id)
LEFT OUTER JOIN foreign_udanext.infrastructure_tenant inft ON (inft.name=dp.tenant)
JOIN cqm_meta.deployment_key dk ON (concat_ws('|',dl.deploy_id, dl.task_id,'UDANEXT') = dk.deployment_key_txt)
-- JOIN sel_meta_key dk ON concat_ws('|',dl.deploy_id, dl.task_id,'UDANEXT') = dk.deployment_key_txt
LEFT OUTER JOIN foreign_udanext.infrastructure_cluster infc ON (infc.tenant_id=inft.id)
LEFT OUTER JOIN foreign_udanext.infrastructure_cluster_request infrq ON (infrq.id=infc.request_id)
LEFT OUTER JOIN foreign_udanext.infrastructure_cluster_version icv ON (infc.k8s_version_id=icv.id)
LEFT OUTER JOIN main.ship_event se ON (se.ship_event_nm = substring(dp.shipevent from 6 for 5))
inner join main.order_base ob on ob.order_no = dl.order_number
WHERE dk.deployment_key_txt NOT IN
(SELECT source_system_deployment_id
FROM main.deployment_base db)

The intent is to use this SELECT within an INSERT statement that will add the result data into a table, but first we have to have the SELECT work appropriately.

The error
ERROR: mergejoin input data is out of order
SQL state: XX000
This error message is not documented anywhere that I can find, and it only occurs in Dev, not Prod.
Suspected issue
We believe that this error is caused by one of two conditions:

1. Postgres is assuming an incorrect sort order on data returned from a substring function; and/or
2. The number of joins is causing intermediate data to be cached, and available cache memory is being exhausted.

Reasons for error suspicions
For (1), the error is suspected because if the line containing the substring is commented out, along with it's associated join, the query runs successfully.
Substring:
LEFT OUTER JOIN main.ship_event se ON (se.ship_event_nm = substring(dp.shipevent from 6 for 5))
Query parameter (part of select):
se.ship_event_nm as ship_event_nm,
The reason we suspect this is first, because the query runs if this join and column selected is commented out of the query. Second, the error message, "mergejoin input data is out of order", leads us to suspect that it is expecting the shipevent data to be in a particular order, and it is not because it is a substring that begins with the 6th character of the string in the column.
What argues against this being the issue is that fact that the query executes properly in Prod, which is running on the same version of Postgres as Dev.
For error (2), the suspicion is based on the log output. The full log will be attached to this bug report, but here's the relevant subset of the log:

SELECT
dk.deployment_id,
dk.deployment_key_txt,
dp.name as deployment_nm,
dp.tenant as deployment_tenant_nm,
infc.name as deployment_cluster_nm,
icv.description as cluster_kubernetes_version_id,
infc.nodes as cluster_node_no,
infc.ram as cluster_ram_no,
infc.cpu as cluster_cpu_no,
infc.disk as cluster_disk_no,
dp.deploy_description as infrastructure_desc,
CASE
WHEN infrq.multi_master = 1 THEN 'Y'
else 'N'
END
AS HA_multi_master_flg,
infrq.cluster_label as cluster_environment_desc,
dl.deploy_time as deployment_deploy_tm,
dl.order_number as order_no_id,
ob.order_id as order_id,
dp.server as deployment_host_nm,
to_timestamp(CAST(dl."timestamp" AS double precision)) as deployment_created_dttm,
dl.promotion_stage as promotion_stage_cd,
se.ship_event_nm as ship_event_nm,
'UDANEXT' as source_system_cd
FROM foreign_udanext.deployments dp
LEFT OUTER JOIN foreign_udanext.deployment_log dl ON (dl.deploy_id = dp.id)
LEFT OUTER JOIN foreign_udanext.infrastructure_tenant inft ON (inft.name=dp.tenant)
JOIN cqm_meta.deployment_key dk ON (concat_ws('|',dl.deploy_id, dl.task_id,'UDANEXT') = dk.deployment_key_txt)
-- JOIN sel_meta_key dk ON concat_ws('|',dl.deploy_id, dl.task_id,'UDANEXT') = dk.deployment_key_txt
LEFT OUTER JOIN foreign_udanext.infrastructure_cluster infc ON (infc.tenant_id=inft.id)
LEFT OUTER JOIN foreign_udanext.infrastructure_cluster_request infrq ON (infrq.id=infc.request_id)
LEFT OUTER JOIN foreign_udanext.infrastructure_cluster_version icv ON (infc.k8s_version_id=icv.id)
LEFT OUTER JOIN main.ship_event se ON (se.ship_event_nm = substring(dp.shipevent from 6 for 5))
inner join main.order_base ob on ob.order_no = dl.order_number
WHERE dk.deployment_key_txt NOT IN
(SELECT source_system_deployment_id
FROM main.deployment_base db)

2023-01-25 09:08:46 EST [354873]: user=pestor,db=cqm_dev,app=pgAdmin 4 - CONN:5168871,client=172.16.47.57 LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp354873.0", size 24272896
2023-01-25 09:08:46 EST [354873]: user=pestor,db=cqm_dev,app=pgAdmin 4 - CONN:5168871,client=172.16.47.57 LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp354873.5", size 0
2023-01-25 09:08:46 EST [354873]: user=pestor,db=cqm_dev,app=pgAdmin 4 - CONN:5168871,client=172.16.47.57 LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp354873.4", size 0
2023-01-25 09:08:46 EST [354873]: user=pestor,db=cqm_dev,app=pgAdmin 4 - CONN:5168871,client=172.16.47.57 LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp354873.3", size 0
2023-01-25 09:08:46 EST [354873]: user=pestor,db=cqm_dev,app=pgAdmin 4 - CONN:5168871,client=172.16.47.57 LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp354873.2", size 24231936
2023-01-25 09:08:46 EST [354873]: user=pestor,db=cqm_dev,app=pgAdmin 4 - CONN:5168871,client=172.16.47.57 LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp354873.1", size 24305664
2023-01-25 09:08:55 EST [354911]: user=,db=,app=,client= LOG: automatic vacuum of table "cqm_metabase.public.qrtz_scheduler_state": index scans: 0
pages: 0 removed, 1 remain, 0 skipped due to pins, 0 skipped frozen
tuples: 56 removed, 1 remain, 0 are dead but not yet removable, oldest xmin: 53130667
index scan not needed: 0 pages from table (0.00% of total) had 0 dead item identifiers removed
avg read rate: 0.000 MB/s, avg write rate: 18.382 MB/s
buffer usage: 52 hits, 0 misses, 1 dirtied
WAL usage: 3 records, 1 full page images, 8671 bytes
system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s

What is significant here is that a number of temp files are created with intermediate results. Three temp files of none-zero size are noted, each of which is slightly over 24 MB in size. It could be that, as a result of all this caching, we are running out of cache/swap space on the server which is causing the failure (albeit with an EXTREMELY misleading error message). As you can see below, the two environments are very similar in architecture except for number of CPUs.
Below are the stats for the two machines, dev and prod.
Dev environment
$ df
Filesystem 1K-blocks Used Available Use% Mounted on
devtmpfs 32810860 0 32810860 0% /dev
tmpfs 32829716 1308 32828408 1% /dev/shm
tmpfs 32829716 1016 32828700 1% /run
tmpfs 32829716 0 32829716 0% /sys/fs/cgroup
/dev/mapper/vg_default-lv_root 69094696 18072504 47830792 28% /
/dev/sda1 499656 347104 115856 75% /boot
/dev/mapper/vg_default-lv_var 16382844 1684248 13843352 11% /var
/dev/mapper/vg_default-lv_tmp 5095040 23452 4793060 1% /tmp
/dev/mapper/vg_data-lv_data 2604006408 1295117116 1308872908 50% /var/lib/pgsql
regxbc02.unx.sas.com:/opt/sysadm 206288896 91794432 103992320 47% /opt/sysadm
isilon03nfs.unx.sas.com:/ifs/nosnaps/cqm_backups 1468006400 1182180864 285825536 81% /var/cqm_backups
isilon03.unx.sas.com:/ifs/data/cqmtest_backups 1073741824 1073741824 0 100% /var/cqmtest_backups
tmpfs 6565940 0 6565940 0% /run/user/3595
tmpfs 6565940 0 6565940 0% /run/user/10639

cat /proc/meminfo
MemTotal: 65659436 kB
MemFree: 17569556 kB
MemAvailable: 47897876 kB
Buffers: 248268 kB
Cached: 45506792 kB
SwapCached: 14000 kB
Active: 28747392 kB
Inactive: 17297648 kB
Active(anon): 16033288 kB
Inactive(anon): 266548 kB
Active(file): 12714104 kB
Inactive(file): 17031100 kB
Unevictable: 0 kB
Mlocked: 0 kB
SwapTotal: 4194300 kB
SwapFree: 3939324 kB
Dirty: 52 kB
Writeback: 0 kB
AnonPages: 280560 kB
Mapped: 16046604 kB
Shmem: 16009848 kB
KReclaimable: 1309076 kB
Slab: 1543072 kB
SReclaimable: 1309076 kB
SUnreclaim: 233996 kB
KernelStack: 6432 kB
PageTables: 225972 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
WritebackTmp: 0 kB
CommitLimit: 37024016 kB
Committed_AS: 17046424 kB
VmallocTotal: 34359738367 kB
VmallocUsed: 0 kB
VmallocChunk: 0 kB
Percpu: 107008 kB
HardwareCorrupted: 0 kB
AnonHugePages: 159744 kB
ShmemHugePages: 0 kB
ShmemPmdMapped: 0 kB
FileHugePages: 0 kB
FilePmdMapped: 0 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
HugePages_Surp: 0
Hugepagesize: 2048 kB
Hugetlb: 0 kB
DirectMap4k: 542528 kB
DirectMap2M: 50837504 kB
DirectMap1G: 17825792 kB

$ lscpu | egrep 'Model name|Socket|Thread|NUMA|CPU\(s\)'
CPU(s): 4
On-line CPU(s) list: 0-3
Thread(s) per core: 1
Socket(s): 4
NUMA node(s): 1
Model name: Intel(R) Xeon(R) Gold 6148 CPU @ 2.40GHz
NUMA node0 CPU(s): 0-3

select version()
PostgreSQL 14.3 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 8.5.0 20210514 (Red Hat 8.5.0-10), 64-bit

Prod environment
$ df
Filesystem 1K-blocks Used Available Use% Mounted on
devtmpfs 65840984 0 65840984 0% /dev
tmpfs 65859840 58564 65801276 1% /dev/shm
tmpfs 65859840 1132 65858708 1% /run
tmpfs 65859840 0 65859840 0% /sys/fs/cgroup
/dev/mapper/vg_default-lv_root 69094696 4753588 61149708 8% /
/dev/sda1 499656 347064 115896 75% /boot
/dev/mapper/vg_default-lv_var 16382844 3419088 12108512 23% /var
/dev/mapper/vg_default-lv_tmp 5095040 20492 4796020 1% /tmp
regxbc02.unx.sas.com:/opt/sysadm 206288896 91794432 103992320 47% /opt/sysadm
tmpfs 13171968 0 13171968 0% /run/user/0
isilon03nfs.unx.sas.com:/ifs/nosnaps/cqm_backups 1468006400 1182180864 285825536 81% /var/cqm_backups
/dev/drbd0 1878122868 901901912 976204572 49% /var/lib/pgsql
tmpfs 13171968 0 13171968 0% /run/user/3595
tmpfs 13171968 0 13171968 0% /run/user/10639

$ cat /proc/meminfo
MemTotal: 131719684 kB
MemFree: 1893884 kB
MemAvailable: 96026960 kB
Buffers: 55028 kB
Cached: 125785868 kB
SwapCached: 20956 kB
Active: 62095452 kB
Inactive: 64324096 kB
Active(anon): 32042800 kB
Inactive(anon): 565988 kB
Active(file): 30052652 kB
Inactive(file): 63758108 kB
Unevictable: 165980 kB
Mlocked: 165980 kB
SwapTotal: 4194300 kB
SwapFree: 3481264 kB
Dirty: 2056 kB
Writeback: 0 kB
AnonPages: 734624 kB
Mapped: 31501228 kB
Shmem: 32014476 kB
KReclaimable: 1574668 kB
Slab: 1860200 kB
SReclaimable: 1574668 kB
SUnreclaim: 285532 kB
KernelStack: 9168 kB
PageTables: 738928 kB
NFS_Unstable: 0 kB
Bounce: 0 kB
WritebackTmp: 0 kB
CommitLimit: 70054140 kB
Committed_AS: 34301304 kB
VmallocTotal: 34359738367 kB
VmallocUsed: 0 kB
VmallocChunk: 0 kB
Percpu: 158208 kB
HardwareCorrupted: 0 kB
AnonHugePages: 376832 kB
ShmemHugePages: 0 kB
ShmemPmdMapped: 0 kB
FileHugePages: 0 kB
FilePmdMapped: 0 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
HugePages_Surp: 0
Hugepagesize: 2048 kB
Hugetlb: 0 kB
DirectMap4k: 2967360 kB
DirectMap2M: 92452864 kB
DirectMap1G: 40894464 kB

$ lscpu | egrep 'Model name|Socket|Thread|NUMA|CPU\(s\)'
CPU(s): 16
On-line CPU(s) list: 0-15
Thread(s) per core: 1
Socket(s): 16
NUMA node(s): 1
Model name: Intel(R) Xeon(R) Gold 6148 CPU @ 2.40GHz
NUMA node0 CPU(s): 0-15

Select version()
PostgreSQL 14.3 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 8.5.0 20210514 (Red Hat 8.5.0-10), 64-bit

From: Pete Storer
Sent: Wednesday, January 25, 2023 2:59 PM
To: 'pgsql-bugs(at)lists(dot)postgresql(dot)org' <pgsql-bugs(at)lists(dot)postgresql(dot)org>
Subject: Query execution failure

I am encountering a strange error when trying to execute a complex SELECT query in Postgres. All of the details of this error are documented in the attachment.

I hope you can help me to resolve this error.

Thanks very much.

Pete Storer
Sr Data Architect
Enterprise Performance and Data Architecture - EPD
Tel: + 1 919 531 5745
SAS | 100 Campus Drive | Cary, NC 27513

[cid:image001(dot)gif(at)01D930CD(dot)801E7950]
DID YOU KNOW?
SAS IS THE NO. 1 AI AND ADVANCED ANALYTICS SOFTWARE PLATFORM.<https://www.sas.com/gms/redirect.jsp?detail=GMS114829_158201>