Possible hang in 10.1 with JSON query over partially indexedpartitions - Mailing list pgsql-general

From Paul Jones
Subject Possible hang in 10.1 with JSON query over partially indexedpartitions
Date
Msg-id 852006162.725231.1516302046887@mail.yahoo.com
Whole thread Raw
Responses Re: Possible hang in 10.1 with JSON query over partially indexed partitions
List pgsql-general
Version   10.1, Community version from PGDG repo
OS        RHEL 7.3

I may have discovered a situation in 10.1 where EXECUTEing a PREPARED
statement acting on JSON data in partitioned tables hangs in an
infinite loop for a particular set of data.  Unfortunately, the data is
proprietary, so I did the best I could below to describe what happened.

    1) Partitioning is done with an (I hope) IMMUTABLE FUNC
    2) Each partition has a partial index on IP address
    3) The query looks for logins within a certain small time frame
       from the same IP

I compiled a debug version and took 3 backtraces.  When I first discovered
this, I allowed it to sit for 10-15 minutes before interrupting it.
Similar queries for different addresses return within seconds.

------------ Setup --------------

CREATE FUNCTION sesstime(tin JSONB)
RETURNS DATE
AS $$
    SELECT (substring(tin->>'timestamp' from 1 for 8))::DATE;
$$ LANGUAGE SQL IMMUTABLE;

DROP TABLE sessparts;
CREATE TABLE sessparts
(
    session        JSONB
) PARTITION BY RANGE (sesstime(session));

CREATE TABLE sessparts_20171116
    PARTITION OF sessparts
FOR VALUES FROM ('2017-11-16') TO ('2017-11-17');

CREATE TABLE sessparts_20171117
    PARTITION OF sessparts
FOR VALUES FROM ('2017-11-17') TO ('2017-11-18');

--------------------------------------------
.....OTHER PARTITIONS ELIDED FOR BREVITY.....
--------------------------------------------

CREATE INDEX ON sessparts_20171116 (CAST(session->>'requestIP' AS INET))
    WHERE session->>'requestIP' != ''
    AND session->>'requestIP' != '0';

CREATE INDEX ON sessparts_20171117 (CAST(session->>'requestIP' AS INET))
    WHERE session->>'requestIP' != ''
    AND session->>'requestIP' != '0';

--------------------------------------------
.....OTHER PARTITIONS ELIDED FOR BREVITY.....
--------------------------------------------

PREPARE fanalq1(INET, TIMESTAMPTZ, INTERVAL) AS
SELECT inetad, aid, count(aid), stddev(td)
FROM (
    SELECT $1, aid,
        lid,
        tstmp,
        EXTRACT(EPOCH FROM (tstmp - lag(tstmp) OVER (ORDER BY tstmp)))
    FROM (
        SELECT session->>'authID' AUTHID,
            session->>'loginID' LOGINID,
            to_timestamp(session->>'timestamp', 'YYYYMMDDHH24MISS') tt
        FROM sessparts
            WHERE sesstime(session) >= ($2 - $3)::DATE
            AND sesstime(session) <= $2::DATE
            AND to_timestamp(session->>'timestamp', 'YYYYMMDDHH24MISS')
                            <@ tstzrange($2 - $3, $2)
            AND session->>'requestIP' != ''
            AND session->>'requestIP' != '0'
            AND (session->>'requestIP')::INET = $1
            AND session->>'isAuthenticationSuccessful' = 'false'
        ) attempts(aid, lid, tstmp)
) tdiffs(inetad, aid, lid, ts, td)
GROUP BY aid, 1;

------------ Query --------------

sessions=# explain EXECUTE fanalq1('206.108.41.102', '2017-11-17 16:23:31-05', '60 seconds');


                      QUERY PLAN
                                                                                                                  
 

-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 GroupAggregate  (cost=1175004.52..1175004.72 rows=8 width=80)
   Group Key: tdiffs.aid, tdiffs.inetad
   ->  Sort  (cost=1175004.52..1175004.54 rows=8 width=72)
         Sort Key: tdiffs.aid, tdiffs.inetad
         ->  Subquery Scan on tdiffs  (cost=1175004.00..1175004.40 rows=8 width=72)
               ->  WindowAgg  (cost=1175004.00..1175004.32 rows=8 width=112)
                     ->  Sort  (cost=1175004.00..1175004.02 rows=8 width=1400)
                           Sort Key: (to_timestamp((sessparts_20171110.session ->> 'timestamp'::text),
'YYYYMMDDHH24MISS'::text))
                           ->  Result  (cost=74.23..1175003.88 rows=8 width=1400)
                                 ->  Append  (cost=74.23..1175003.76 rows=8 width=1392)
                                       ->  Bitmap Heap Scan on sessparts_20171110  (cost=74.23..16077.23 rows=1
width=1380)
                                             Recheck Cond: ((((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)AND ((session ->> 'requestIP'::text) <> ''::text) AND ((session ->> 'requestIP'::text) <>
'0'::text))
                                             Filter: (((session ->> 'isAuthenticationSuccessful'::text) =
'false'::text)AND (to_timestamp((session ->> 'timestamp'::text), 'YYYYMMDDHH24MISS'::text) <@ tstzrange(('2017-11-17
16:23:31-05'::timestampwith time zone - '00:01:00'::interval), '2017-11-17 16:23:31-05'::timestamp with time zone)) AND
(sesstime(session)<= ('2017-11-17 16:23:31-05'::timestamp with time zone)::date) AND (sesstime(session) >=
(('2017-11-1716:23:31-05'::timestamp with time zone - '00:01:00'::interval))::date))
 
                                             ->  Bitmap Index Scan on sessparts_20171110_inet_idx  (cost=0.00..74.23
rows=3974width=0)
 
                                                   Index Cond: (((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)
                                       ->  Bitmap Heap Scan on sessparts_20171111  (cost=261.04..56514.03 rows=1
width=1420)
                                             Recheck Cond: ((((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)AND ((session ->> 'requestIP'::text) <> ''::text) AND ((session ->> 'requestIP'::text) <>
'0'::text))
                                             Filter: (((session ->> 'isAuthenticationSuccessful'::text) =
'false'::text)AND (to_timestamp((session ->> 'timestamp'::text), 'YYYYMMDDHH24MISS'::text) <@ tstzrange(('2017-11-17
16:23:31-05'::timestampwith time zone - '00:01:00'::interval), '2017-11-17 16:23:31-05'::timestamp with time zone)) AND
(sesstime(session)<= ('2017-11-17 16:23:31-05'::timestamp with time zone)::date) AND (sesstime(session) >=
(('2017-11-1716:23:31-05'::timestamp with time zone - '00:01:00'::interval))::date))
 
                                             ->  Bitmap Index Scan on sessparts_20171111_inet_idx  (cost=0.00..261.04
rows=13948width=0)
 
                                                   Index Cond: (((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)
                                       ->  Bitmap Heap Scan on sessparts_20171112  (cost=274.18..59053.83 rows=1
width=1342)
                                             Recheck Cond: ((((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)AND ((session ->> 'requestIP'::text) <> ''::text) AND ((session ->> 'requestIP'::text) <>
'0'::text))
                                             Filter: (((session ->> 'isAuthenticationSuccessful'::text) =
'false'::text)AND (to_timestamp((session ->> 'timestamp'::text), 'YYYYMMDDHH24MISS'::text) <@ tstzrange(('2017-11-17
16:23:31-05'::timestampwith time zone - '00:01:00'::interval), '2017-11-17 16:23:31-05'::timestamp with time zone)) AND
(sesstime(session)<= ('2017-11-17 16:23:31-05'::timestamp with time zone)::date) AND (sesstime(session) >=
(('2017-11-1716:23:31-05'::timestamp with time zone - '00:01:00'::interval))::date))
 
                                             ->  Bitmap Index Scan on sessparts_20171112_inet_idx  (cost=0.00..274.18
rows=14633width=0)
 
                                                   Index Cond: (((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)
                                       ->  Bitmap Heap Scan on sessparts_20171113  (cost=981.22..214235.52 rows=1
width=1395)
                                             Recheck Cond: ((((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)AND ((session ->> 'requestIP'::text) <> ''::text) AND ((session ->> 'requestIP'::text) <>
'0'::text))
                                             Filter: (((session ->> 'isAuthenticationSuccessful'::text) =
'false'::text)AND (to_timestamp((session ->> 'timestamp'::text), 'YYYYMMDDHH24MISS'::text) <@ tstzrange(('2017-11-17
16:23:31-05'::timestampwith time zone - '00:01:00'::interval), '2017-11-17 16:23:31-05'::timestamp with time zone)) AND
(sesstime(session)<= ('2017-11-17 16:23:31-05'::timestamp with time zone)::date) AND (sesstime(session) >=
(('2017-11-1716:23:31-05'::timestamp with time zone - '00:01:00'::interval))::date))
 
                                             ->  Bitmap Index Scan on sessparts_20171113_inet_idx  (cost=0.00..981.21
rows=52904width=0)
 
                                                   Index Cond: (((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)
                                       ->  Bitmap Heap Scan on sessparts_20171114  (cost=989.38..216526.98 rows=1
width=1397)
                                             Recheck Cond: ((((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)AND ((session ->> 'requestIP'::text) <> ''::text) AND ((session ->> 'requestIP'::text) <>
'0'::text))
                                             Filter: (((session ->> 'isAuthenticationSuccessful'::text) =
'false'::text)AND (to_timestamp((session ->> 'timestamp'::text), 'YYYYMMDDHH24MISS'::text) <@ tstzrange(('2017-11-17
16:23:31-05'::timestampwith time zone - '00:01:00'::interval), '2017-11-17 16:23:31-05'::timestamp with time zone)) AND
(sesstime(session)<= ('2017-11-17 16:23:31-05'::timestamp with time zone)::date) AND (sesstime(session) >=
(('2017-11-1716:23:31-05'::timestamp with time zone - '00:01:00'::interval))::date))
 
                                             ->  Bitmap Index Scan on sessparts_20171114_inet_idx  (cost=0.00..989.38
rows=53459width=0)
 
                                                   Index Cond: (((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)
                                       ->  Bitmap Heap Scan on sessparts_20171115  (cost=975.53..213392.42 rows=1
width=1401)
                                             Recheck Cond: ((((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)AND ((session ->> 'requestIP'::text) <> ''::text) AND ((session ->> 'requestIP'::text) <>
'0'::text))
                                             Filter: (((session ->> 'isAuthenticationSuccessful'::text) =
'false'::text)AND (to_timestamp((session ->> 'timestamp'::text), 'YYYYMMDDHH24MISS'::text) <@ tstzrange(('2017-11-17
16:23:31-05'::timestampwith time zone - '00:01:00'::interval), '2017-11-17 16:23:31-05'::timestamp with time zone)) AND
(sesstime(session)<= ('2017-11-17 16:23:31-05'::timestamp with time zone)::date) AND (sesstime(session) >=
(('2017-11-1716:23:31-05'::timestamp with time zone - '00:01:00'::interval))::date))
 
                                             ->  Bitmap Index Scan on sessparts_20171115_inet_idx  (cost=0.00..975.53
rows=52679width=0)
 
                                                   Index Cond: (((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)
                                       ->  Bitmap Heap Scan on sessparts_20171116  (cost=1042.06..227732.56 rows=1
width=1400)
                                             Recheck Cond: ((((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)AND ((session ->> 'requestIP'::text) <> ''::text) AND ((session ->> 'requestIP'::text) <>
'0'::text))
                                             Filter: (((session ->> 'isAuthenticationSuccessful'::text) =
'false'::text)AND (to_timestamp((session ->> 'timestamp'::text), 'YYYYMMDDHH24MISS'::text) <@ tstzrange(('2017-11-17
16:23:31-05'::timestampwith time zone - '00:01:00'::interval), '2017-11-17 16:23:31-05'::timestamp with time zone)) AND
(sesstime(session)<= ('2017-11-17 16:23:31-05'::timestamp with time zone)::date) AND (sesstime(session) >=
(('2017-11-1716:23:31-05'::timestamp with time zone - '00:01:00'::interval))::date))
 
                                             ->  Bitmap Index Scan on sessparts_20171116_inet_idx  (cost=0.00..1042.06
rows=56217width=0)
 
                                                   Index Cond: (((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)
                                       ->  Bitmap Heap Scan on sessparts_20171117  (cost=785.91..171471.19 rows=1
width=1401)
                                             Recheck Cond: ((((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)AND ((session ->> 'requestIP'::text) <> ''::text) AND ((session ->> 'requestIP'::text) <>
'0'::text))
                                             Filter: (((session ->> 'isAuthenticationSuccessful'::text) =
'false'::text)AND (to_timestamp((session ->> 'timestamp'::text), 'YYYYMMDDHH24MISS'::text) <@ tstzrange(('2017-11-17
16:23:31-05'::timestampwith time zone - '00:01:00'::interval), '2017-11-17 16:23:31-05'::timestamp with time zone)) AND
(sesstime(session)<= ('2017-11-17 16:23:31-05'::timestamp with time zone)::date) AND (sesstime(session) >=
(('2017-11-1716:23:31-05'::timestamp with time zone - '00:01:00'::interval))::date))
 
                                             ->  Bitmap Index Scan on sessparts_20171117_inet_idx  (cost=0.00..785.91
rows=42330width=0)
 
                                                   Index Cond: (((session ->> 'requestIP'::text))::inet =
'206.108.41.102'::inet)
(50 rows)

--------- Backtrace #1 ----------

(gdb) bt
#0  0x00007fc326cae480 in __read_nocancel () from /lib64/libpthread.so.0
#1  0x00000000006ec65e in read (__nbytes=8192, __buf=0x7fbf1a41f800, __fd=<optimized out>) at
/usr/include/bits/unistd.h:44
#2  FileRead (file=<optimized out>, buffer=buffer@entry=0x7fbf1a41f800 "#", amount=amount@entry=8192,
wait_event_info=wait_event_info@entry=167772173)at fd.c:1665
 
#3  0x000000000070f036 in mdread (reln=<optimized out>, forknum=<optimized out>, blocknum=175416, buffer=0x7fbf1a41f800
"#")at md.c:757
 
#4  0x00000000006e8af8 in ReadBuffer_common (smgr=0x15408f8, relpersistence=<optimized out>,
forkNum=forkNum@entry=MAIN_FORKNUM,blockNum=blockNum@entry=175416,
 
    mode=RBM_NORMAL, strategy=0x0, hit=hit@entry=0x7ffe3a6e14e7 "") at bufmgr.c:890
#5  0x00000000006e9600 in ReadBufferExtended (reln=0x7fc32709d880, forkNum=forkNum@entry=MAIN_FORKNUM, blockNum=175416,
mode=mode@entry=RBM_NORMAL,
    strategy=strategy@entry=0x0) at bufmgr.c:664
#6  0x00000000006e971b in ReadBuffer (blockNum=<optimized out>, reln=<optimized out>) at bufmgr.c:596
#7  ReleaseAndReadBuffer (buffer=<optimized out>, relation=<optimized out>, blockNum=blockNum@entry=175416) at
bufmgr.c:1545
#8  0x00000000005fdd94 in bitgetpage (tbmres=0x16c6e0c, scan=0x1683bc8) at nodeBitmapHeapscan.c:364
#9  BitmapHeapNext (node=node@entry=0x1676b08) at nodeBitmapHeapscan.c:230
#10 0x00000000005f3254 in ExecScanFetch (recheckMtd=0x5fdb30 <BitmapHeapRecheck>, accessMtd=0x5fdbc0 <BitmapHeapNext>,
node=0x1676b08)at execScan.c:97
 
#11 ExecScan (node=0x1676b08, accessMtd=0x5fdbc0 <BitmapHeapNext>, recheckMtd=0x5fdb30 <BitmapHeapRecheck>) at
execScan.c:164
#12 0x00000000005f8c02 in ExecProcNode (node=0x1676b08) at ../../../src/include/executor/executor.h:250
#13 ExecAppend (pstate=0x1672800) at nodeAppend.c:222
#14 0x000000000060ce79 in ExecProcNode (node=0x1672800) at ../../../src/include/executor/executor.h:250
#15 ExecResult (pstate=0x1672590) at nodeResult.c:115
#16 0x000000000060e5c6 in ExecProcNode (node=0x1672590) at ../../../src/include/executor/executor.h:250
#17 ExecSort (pstate=0x1672320) at nodeSort.c:106
#18 0x000000000061264c in ExecProcNode (node=0x1672320) at ../../../src/include/executor/executor.h:250
#19 begin_partition (winstate=winstate@entry=0x1671b90) at nodeWindowAgg.c:1082
#20 0x0000000000614f64 in ExecWindowAgg (pstate=0x1671b90) at nodeWindowAgg.c:1671
#21 0x00000000005f3254 in ExecScanFetch (recheckMtd=0x611290 <SubqueryRecheck>, accessMtd=0x6112b0 <SubqueryNext>,
node=0x1671870)at execScan.c:97
 
#22 ExecScan (node=0x1671870, accessMtd=0x6112b0 <SubqueryNext>, recheckMtd=0x611290 <SubqueryRecheck>) at
execScan.c:164
#23 0x000000000060e5c6 in ExecProcNode (node=0x1671870) at ../../../src/include/executor/executor.h:250
#24 ExecSort (pstate=0x1671600) at nodeSort.c:106
#25 0x00000000005f8f49 in ExecProcNode (node=0x1671600) at ../../../src/include/executor/executor.h:250
#26 fetch_input_tuple (aggstate=aggstate@entry=0x1670f58) at nodeAgg.c:695
#27 0x00000000005fb0c7 in agg_retrieve_direct (aggstate=0x1670f58) at nodeAgg.c:2336
#28 ExecAgg (pstate=0x1670f58) at nodeAgg.c:2147
#29 0x00000000005ed7e2 in ExecProcNode (node=0x1670f58) at ../../../src/include/executor/executor.h:250
#30 ExecutePlan (execute_once=<optimized out>, dest=0x15f5f10, direction=<optimized out>, numberTuples=0, sendTuples=1
'\001',operation=CMD_SELECT,
 
    use_parallel_mode=<optimized out>, planstate=0x1670f58, estate=0x1670d48) at execMain.c:1722
#31 standard_ExecutorRun (queryDesc=0x14d9b08, direction=<optimized out>, count=0, execute_once=<optimized out>) at
execMain.c:363
#32 0x00000000007167db in PortalRunSelect (portal=portal@entry=0x152cdc8, forward=forward@entry=1 '\001', count=0,
count@entry=9223372036854775807,
    dest=dest@entry=0x15f5f10) at pquery.c:932
#33 0x0000000000717b7f in PortalRun (portal=portal@entry=0x152cdc8, count=count@entry=9223372036854775807,
isTopLevel=isTopLevel@entry=0'\000',
 
    run_once=run_once@entry=1 '\001', dest=dest@entry=0x15f5f10, altdest=altdest@entry=0x15f5f10,
completionTag=completionTag@entry=0x7ffe3a6e1c40"") at pquery.c:773
 
#34 0x00000000005abd3e in ExecuteQuery (stmt=<optimized out>, intoClause=0x0, queryString=<optimized out>,
params=<optimizedout>, dest=0x15f5f10,
 
    completionTag=0x7ffe3a6e1c40 "") at prepare.c:304
#35 0x0000000000718cfa in standard_ProcessUtility (pstmt=0x1532b28,
    queryString=0x1531bf8 "EXECUTE fanalq1('206.108.41.102', '2017-11-17 16:23:31-05', '60 seconds');",
context=PROCESS_UTILITY_TOPLEVEL,params=0x0, queryEnv=0x0,
 
    dest=0x15f5f10, completionTag=0x7ffe3a6e1c40 "") at utility.c:576
#36 0x0000000000716458 in PortalRunUtility (portal=0x152ccb8, pstmt=0x1532b28, isTopLevel=<optimized out>,
setHoldSnapshot=<optimizedout>, dest=0x15f5f10,
 
    completionTag=0x7ffe3a6e1c40 "") at pquery.c:1178
#37 0x0000000000717172 in FillPortalStore (portal=portal@entry=0x152ccb8, isTopLevel=isTopLevel@entry=1 '\001') at
pquery.c:1038
#38 0x0000000000717bff in PortalRun (portal=portal@entry=0x152ccb8, count=count@entry=9223372036854775807,
isTopLevel=isTopLevel@entry=1'\001',
 
    run_once=run_once@entry=1 '\001', dest=dest@entry=0x1532c08, altdest=altdest@entry=0x1532c08,
completionTag=completionTag@entry=0x7ffe3a6e1e60"") at pquery.c:768
 
#39 0x0000000000713b03 in exec_simple_query (query_string=0x1531bf8 "EXECUTE fanalq1('206.108.41.102', '2017-11-17
16:23:31-05','60 seconds');") at postgres.c:1099
 
#40 0x0000000000714dfc in PostgresMain (argc=<optimized out>, argv=argv@entry=0x14dc860, dbname=0x14dc758 "sessions",
username=<optimizedout>) at postgres.c:4088
 
#41 0x0000000000479b4c in BackendRun (port=0x14d2d80) at postmaster.c:4357
#42 BackendStartup (port=0x14d2d80) at postmaster.c:4029
#43 ServerLoop () at postmaster.c:1753
#44 0x00000000006ac63f in PostmasterMain (argc=argc@entry=13, argv=argv@entry=0x14ac250) at postmaster.c:1361
#45 0x000000000047a97f in main (argc=13, argv=0x14ac250) at main.c:228

--------- Backtrace #2 ----------

(gdb) bt
#0  0x00007fc326cae480 in __read_nocancel () from /lib64/libpthread.so.0
#1  0x00000000006ec65e in read (__nbytes=8192, __buf=0x7fbf1c33b800, __fd=<optimized out>) at
/usr/include/bits/unistd.h:44
#2  FileRead (file=<optimized out>, buffer=buffer@entry=0x7fbf1c33b800 "#", amount=amount@entry=8192,
wait_event_info=wait_event_info@entry=167772173)at fd.c:1665
 
#3  0x000000000070f036 in mdread (reln=<optimized out>, forknum=<optimized out>, blocknum=272410, buffer=0x7fbf1c33b800
"#")at md.c:757
 
#4  0x00000000006e8af8 in ReadBuffer_common (smgr=0x15408f8, relpersistence=<optimized out>,
forkNum=forkNum@entry=MAIN_FORKNUM,blockNum=blockNum@entry=272410,
 
    mode=RBM_NORMAL, strategy=0x0, hit=hit@entry=0x7ffe3a6e14e7 "") at bufmgr.c:890
#5  0x00000000006e9600 in ReadBufferExtended (reln=0x7fc32709d880, forkNum=forkNum@entry=MAIN_FORKNUM, blockNum=272410,
mode=mode@entry=RBM_NORMAL,
    strategy=strategy@entry=0x0) at bufmgr.c:664
#6  0x00000000006e971b in ReadBuffer (blockNum=<optimized out>, reln=<optimized out>) at bufmgr.c:596
#7  ReleaseAndReadBuffer (buffer=<optimized out>, relation=<optimized out>, blockNum=blockNum@entry=272410) at
bufmgr.c:1545
#8  0x00000000005fdd94 in bitgetpage (tbmres=0x16c6e0c, scan=0x1683bc8) at nodeBitmapHeapscan.c:364
#9  BitmapHeapNext (node=node@entry=0x1676b08) at nodeBitmapHeapscan.c:230
#10 0x00000000005f3254 in ExecScanFetch (recheckMtd=0x5fdb30 <BitmapHeapRecheck>, accessMtd=0x5fdbc0 <BitmapHeapNext>,
node=0x1676b08)at execScan.c:97
 
#11 ExecScan (node=0x1676b08, accessMtd=0x5fdbc0 <BitmapHeapNext>, recheckMtd=0x5fdb30 <BitmapHeapRecheck>) at
execScan.c:164
#12 0x00000000005f8c02 in ExecProcNode (node=0x1676b08) at ../../../src/include/executor/executor.h:250
#13 ExecAppend (pstate=0x1672800) at nodeAppend.c:222
#14 0x000000000060ce79 in ExecProcNode (node=0x1672800) at ../../../src/include/executor/executor.h:250
#15 ExecResult (pstate=0x1672590) at nodeResult.c:115
#16 0x000000000060e5c6 in ExecProcNode (node=0x1672590) at ../../../src/include/executor/executor.h:250
#17 ExecSort (pstate=0x1672320) at nodeSort.c:106
#18 0x000000000061264c in ExecProcNode (node=0x1672320) at ../../../src/include/executor/executor.h:250
#19 begin_partition (winstate=winstate@entry=0x1671b90) at nodeWindowAgg.c:1082
#20 0x0000000000614f64 in ExecWindowAgg (pstate=0x1671b90) at nodeWindowAgg.c:1671
#21 0x00000000005f3254 in ExecScanFetch (recheckMtd=0x611290 <SubqueryRecheck>, accessMtd=0x6112b0 <SubqueryNext>,
node=0x1671870)at execScan.c:97
 
#22 ExecScan (node=0x1671870, accessMtd=0x6112b0 <SubqueryNext>, recheckMtd=0x611290 <SubqueryRecheck>) at
execScan.c:164
#23 0x000000000060e5c6 in ExecProcNode (node=0x1671870) at ../../../src/include/executor/executor.h:250
#24 ExecSort (pstate=0x1671600) at nodeSort.c:106
#25 0x00000000005f8f49 in ExecProcNode (node=0x1671600) at ../../../src/include/executor/executor.h:250
#26 fetch_input_tuple (aggstate=aggstate@entry=0x1670f58) at nodeAgg.c:695
#27 0x00000000005fb0c7 in agg_retrieve_direct (aggstate=0x1670f58) at nodeAgg.c:2336
#28 ExecAgg (pstate=0x1670f58) at nodeAgg.c:2147
#29 0x00000000005ed7e2 in ExecProcNode (node=0x1670f58) at ../../../src/include/executor/executor.h:250
#30 ExecutePlan (execute_once=<optimized out>, dest=0x15f5f10, direction=<optimized out>, numberTuples=0, sendTuples=1
'\001',operation=CMD_SELECT,
 
    use_parallel_mode=<optimized out>, planstate=0x1670f58, estate=0x1670d48) at execMain.c:1722
#31 standard_ExecutorRun (queryDesc=0x14d9b08, direction=<optimized out>, count=0, execute_once=<optimized out>) at
execMain.c:363
#32 0x00000000007167db in PortalRunSelect (portal=portal@entry=0x152cdc8, forward=forward@entry=1 '\001', count=0,
count@entry=9223372036854775807,
    dest=dest@entry=0x15f5f10) at pquery.c:932
#33 0x0000000000717b7f in PortalRun (portal=portal@entry=0x152cdc8, count=count@entry=9223372036854775807,
isTopLevel=isTopLevel@entry=0'\000',
 
    run_once=run_once@entry=1 '\001', dest=dest@entry=0x15f5f10, altdest=altdest@entry=0x15f5f10,
completionTag=completionTag@entry=0x7ffe3a6e1c40"") at pquery.c:773
 
#34 0x00000000005abd3e in ExecuteQuery (stmt=<optimized out>, intoClause=0x0, queryString=<optimized out>,
params=<optimizedout>, dest=0x15f5f10,
 
    completionTag=0x7ffe3a6e1c40 "") at prepare.c:304
#35 0x0000000000718cfa in standard_ProcessUtility (pstmt=0x1532b28,
    queryString=0x1531bf8 "EXECUTE fanalq1('206.108.41.102', '2017-11-17 16:23:31-05', '60 seconds');",
context=PROCESS_UTILITY_TOPLEVEL,params=0x0, queryEnv=0x0, 
    dest=0x15f5f10, completionTag=0x7ffe3a6e1c40 "") at utility.c:576
#36 0x0000000000716458 in PortalRunUtility (portal=0x152ccb8, pstmt=0x1532b28, isTopLevel=<optimized out>,
setHoldSnapshot=<optimizedout>, dest=0x15f5f10,
 
    completionTag=0x7ffe3a6e1c40 "") at pquery.c:1178
#37 0x0000000000717172 in FillPortalStore (portal=portal@entry=0x152ccb8, isTopLevel=isTopLevel@entry=1 '\001') at
pquery.c:1038
#38 0x0000000000717bff in PortalRun (portal=portal@entry=0x152ccb8, count=count@entry=9223372036854775807,
isTopLevel=isTopLevel@entry=1'\001',
 
    run_once=run_once@entry=1 '\001', dest=dest@entry=0x1532c08, altdest=altdest@entry=0x1532c08,
completionTag=completionTag@entry=0x7ffe3a6e1e60"") at pquery.c:768
 
#39 0x0000000000713b03 in exec_simple_query (query_string=0x1531bf8 "EXECUTE fanalq1('206.108.41.102', '2017-11-17
16:23:31-05','60 seconds');") at postgres.c:1099
 
#40 0x0000000000714dfc in PostgresMain (argc=<optimized out>, argv=argv@entry=0x14dc860, dbname=0x14dc758 "sessions",
username=<optimizedout>) at postgres.c:4088
 
#41 0x0000000000479b4c in BackendRun (port=0x14d2d80) at postmaster.c:4357
#42 BackendStartup (port=0x14d2d80) at postmaster.c:4029
#43 ServerLoop () at postmaster.c:1753
#44 0x00000000006ac63f in PostmasterMain (argc=argc@entry=13, argv=argv@entry=0x14ac250) at postmaster.c:1361
#45 0x000000000047a97f in main (argc=13, argv=0x14ac250) at main.c:228

--------- Backtrace #3 ----------

(gdb) bt
#0  0x00007fc326cae480 in __read_nocancel () from /lib64/libpthread.so.0
#1  0x00000000006ec65e in read (__nbytes=8192, __buf=0x7fbf1cc33800, __fd=<optimized out>) at
/usr/include/bits/unistd.h:44
#2  FileRead (file=<optimized out>, buffer=buffer@entry=0x7fbf1cc33800 "#", amount=amount@entry=8192,
wait_event_info=wait_event_info@entry=167772173)at fd.c:1665
 
#3  0x000000000070f036 in mdread (reln=<optimized out>, forknum=<optimized out>, blocknum=303087, buffer=0x7fbf1cc33800
"#")at md.c:757
 
#4  0x00000000006e8af8 in ReadBuffer_common (smgr=0x15408f8, relpersistence=<optimized out>,
forkNum=forkNum@entry=MAIN_FORKNUM,blockNum=blockNum@entry=303087,
 
    mode=RBM_NORMAL, strategy=0x0, hit=hit@entry=0x7ffe3a6e14e7 "") at bufmgr.c:890
#5  0x00000000006e9600 in ReadBufferExtended (reln=0x7fc32709d880, forkNum=forkNum@entry=MAIN_FORKNUM, blockNum=303087,
mode=mode@entry=RBM_NORMAL,
    strategy=strategy@entry=0x0) at bufmgr.c:664
#6  0x00000000006e971b in ReadBuffer (blockNum=<optimized out>, reln=<optimized out>) at bufmgr.c:596
#7  ReleaseAndReadBuffer (buffer=<optimized out>, relation=<optimized out>, blockNum=blockNum@entry=303087) at
bufmgr.c:1545
#8  0x00000000005fdd94 in bitgetpage (tbmres=0x16c6e0c, scan=0x1683bc8) at nodeBitmapHeapscan.c:364
#9  BitmapHeapNext (node=node@entry=0x1676b08) at nodeBitmapHeapscan.c:230
#10 0x00000000005f3254 in ExecScanFetch (recheckMtd=0x5fdb30 <BitmapHeapRecheck>, accessMtd=0x5fdbc0 <BitmapHeapNext>,
node=0x1676b08)at execScan.c:97
 
#11 ExecScan (node=0x1676b08, accessMtd=0x5fdbc0 <BitmapHeapNext>, recheckMtd=0x5fdb30 <BitmapHeapRecheck>) at
execScan.c:164
#12 0x00000000005f8c02 in ExecProcNode (node=0x1676b08) at ../../../src/include/executor/executor.h:250
#13 ExecAppend (pstate=0x1672800) at nodeAppend.c:222
#14 0x000000000060ce79 in ExecProcNode (node=0x1672800) at ../../../src/include/executor/executor.h:250
#15 ExecResult (pstate=0x1672590) at nodeResult.c:115
#16 0x000000000060e5c6 in ExecProcNode (node=0x1672590) at ../../../src/include/executor/executor.h:250
#17 ExecSort (pstate=0x1672320) at nodeSort.c:106
#18 0x000000000061264c in ExecProcNode (node=0x1672320) at ../../../src/include/executor/executor.h:250
#19 begin_partition (winstate=winstate@entry=0x1671b90) at nodeWindowAgg.c:1082
#20 0x0000000000614f64 in ExecWindowAgg (pstate=0x1671b90) at nodeWindowAgg.c:1671
#21 0x00000000005f3254 in ExecScanFetch (recheckMtd=0x611290 <SubqueryRecheck>, accessMtd=0x6112b0 <SubqueryNext>,
node=0x1671870)at execScan.c:97
 
#22 ExecScan (node=0x1671870, accessMtd=0x6112b0 <SubqueryNext>, recheckMtd=0x611290 <SubqueryRecheck>) at
execScan.c:164
#23 0x000000000060e5c6 in ExecProcNode (node=0x1671870) at ../../../src/include/executor/executor.h:250
#24 ExecSort (pstate=0x1671600) at nodeSort.c:106
#25 0x00000000005f8f49 in ExecProcNode (node=0x1671600) at ../../../src/include/executor/executor.h:250
#26 fetch_input_tuple (aggstate=aggstate@entry=0x1670f58) at nodeAgg.c:695
#27 0x00000000005fb0c7 in agg_retrieve_direct (aggstate=0x1670f58) at nodeAgg.c:2336
#28 ExecAgg (pstate=0x1670f58) at nodeAgg.c:2147
#29 0x00000000005ed7e2 in ExecProcNode (node=0x1670f58) at ../../../src/include/executor/executor.h:250
#30 ExecutePlan (execute_once=<optimized out>, dest=0x15f5f10, direction=<optimized out>, numberTuples=0, sendTuples=1
'\001',operation=CMD_SELECT,
 
    use_parallel_mode=<optimized out>, planstate=0x1670f58, estate=0x1670d48) at execMain.c:1722
#31 standard_ExecutorRun (queryDesc=0x14d9b08, direction=<optimized out>, count=0, execute_once=<optimized out>) at
execMain.c:363
#32 0x00000000007167db in PortalRunSelect (portal=portal@entry=0x152cdc8, forward=forward@entry=1 '\001', count=0,
count@entry=9223372036854775807,
    dest=dest@entry=0x15f5f10) at pquery.c:932
#33 0x0000000000717b7f in PortalRun (portal=portal@entry=0x152cdc8, count=count@entry=9223372036854775807,
isTopLevel=isTopLevel@entry=0'\000',
 
    run_once=run_once@entry=1 '\001', dest=dest@entry=0x15f5f10, altdest=altdest@entry=0x15f5f10,
completionTag=completionTag@entry=0x7ffe3a6e1c40"") at pquery.c:773
 
#34 0x00000000005abd3e in ExecuteQuery (stmt=<optimized out>, intoClause=0x0, queryString=<optimized out>,
params=<optimizedout>, dest=0x15f5f10,
 
    completionTag=0x7ffe3a6e1c40 "") at prepare.c:304
#35 0x0000000000718cfa in standard_ProcessUtility (pstmt=0x1532b28,
    queryString=0x1531bf8 "EXECUTE fanalq1('206.108.41.102', '2017-11-17 16:23:31-05', '60 seconds');",
context=PROCESS_UTILITY_TOPLEVEL,params=0x0, queryEnv=0x0,
 
    dest=0x15f5f10, completionTag=0x7ffe3a6e1c40 "") at utility.c:576
#36 0x0000000000716458 in PortalRunUtility (portal=0x152ccb8, pstmt=0x1532b28, isTopLevel=<optimized out>,
setHoldSnapshot=<optimizedout>, dest=0x15f5f10,
 
    completionTag=0x7ffe3a6e1c40 "") at pquery.c:1178
#37 0x0000000000717172 in FillPortalStore (portal=portal@entry=0x152ccb8, isTopLevel=isTopLevel@entry=1 '\001') at
pquery.c:1038
#38 0x0000000000717bff in PortalRun (portal=portal@entry=0x152ccb8, count=count@entry=9223372036854775807,
isTopLevel=isTopLevel@entry=1'\001',
 
    run_once=run_once@entry=1 '\001', dest=dest@entry=0x1532c08, altdest=altdest@entry=0x1532c08,
completionTag=completionTag@entry=0x7ffe3a6e1e60"") at pquery.c:768
 
#39 0x0000000000713b03 in exec_simple_query (query_string=0x1531bf8 "EXECUTE fanalq1('206.108.41.102', '2017-11-17
16:23:31-05','60 seconds');") at postgres.c:1099
 
#40 0x0000000000714dfc in PostgresMain (argc=<optimized out>, argv=argv@entry=0x14dc860, dbname=0x14dc758 "sessions",
username=<optimizedout>) at postgres.c:4088
 
#41 0x0000000000479b4c in BackendRun (port=0x14d2d80) at postmaster.c:4357
#42 BackendStartup (port=0x14d2d80) at postmaster.c:4029
#43 ServerLoop () at postmaster.c:1753
#44 0x00000000006ac63f in PostmasterMain (argc=argc@entry=13, argv=argv@entry=0x14ac250) at postmaster.c:1361
#45 0x000000000047a97f in main (argc=13, argv=0x14ac250) at main.c:228


pgsql-general by date:

Previous
From: Enrico Pirozzi
Date:
Subject: Re: Connection type
Next
From: Seamus Abshere
Date:
Subject: warning for subquery that references a table but not its columns