FW: Query execution failure - Mailing list pgsql-bugs

From Pete Storer
Subject FW: Query execution failure
Date
Msg-id BL0PR05MB66283C57D72E321591AE4EB1F3CE9@BL0PR05MB6628.namprd05.prod.outlook.com
Whole thread Raw
In response to Query execution failure  (Pete Storer <Pete.Storer@sas.com>)
Responses Re: FW: Query execution failure  (Tom Lane <tgl@sss.pgh.pa.us>)
List pgsql-bugs

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@lists.postgresql.org' <pgsql-bugs@lists.postgresql.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

 

DID YOU KNOW?
SAS IS THE NO. 1 AI AND ADVANCED ANALYTICS SOFTWARE PLATFORM.

 

 

Attachment

pgsql-bugs by date:

Previous
From: Christophe Pettus
Date:
Subject: Re: Query execution failure
Next
From: Kyotaro Horiguchi
Date:
Subject: Re: Minor difference in behavior between +/-