Обсуждение: BUG #17406: Segmentation fault on GiST index after 14.2 upgrade

The following bug has been logged on the website:

Bug reference:      17406
Logged by:          Victor Yegorov
Email address:      vyegorov@gmail.com
PostgreSQL version: 14.2
Operating system:   Ubuntu 18.04.6 LTS (bionic)
Description:

KVM guest, on Intel(R) Xeon(R) CPU E5-2697 v2.

PostgreSQL 12.9 had been upgraded to 14.2 using

pg_upgradecluster -k  -m link 12 main /mnt/postgres/14/

After that, one of the queries is crashing with Segmentation Fault.
However, after REINDEX problem will be fixed. I thought I should report
still.

explain
SELECT r.id, r.name, r.map_center_y, r.map_center_x,
       COALESCE ((SELECT string_agg(id::TEXT, ',') FROM v3_region AS r2
WHERE r2.id != r.id AND r2.ltree_path <@ r.ltree_path), '') AS children
  FROM v3_region AS r;
                                                 QUERY PLAN
-------------------------------------------------------------------------------------------------------------
 Seq Scan on v3_region r  (cost=0.00..3207.31 rows=349 width=580)
   SubPlan 1
     ->  Aggregate  (cost=8.17..8.18 rows=1 width=32)
           ->  Index Scan using region_ltree_path_idx_gist on v3_region r2
(cost=0.14..8.16 rows=1 width=4)
                 Index Cond: (ltree_path <@ r.ltree_path)
                 Filter: (id <> r.id)
(6 rows)

Here is backtrace:
#0  __memmove_sse2_unaligned_erms () at
../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:435
#1  0x00007f129244c266 in memcpy (__len=<optimized out>,
__src=0x55bbbd430f4a, __dest=<optimized out>) at
/usr/include/x86_64-linux-gnu/bits/string_fortified.h:34
#2  copy_ltree (src=0x55bbbd430f4a) at
./build/../contrib/ltree/ltree_gist.c:446
#3  0x00007f129244db51 in gist_ischild (siglen=28, query=0x55bbbd410cb8,
key=0x55bbbd430f18) at ./build/../contrib/ltree/ltree_gist.c:454
#4  ltree_consistent (fcinfo=0x7ffdac2e3e20) at
./build/../contrib/ltree/ltree_gist.c:674
#5  0x000055bbbb944a5d in FunctionCall5Coll
(flinfo=flinfo@entry=0x55bbbd416b20, collation=<optimized out>,
arg1=arg1@entry=140727492165472, arg2=<optimized out>, arg3=<optimized out>,
arg4=<optimized out>, arg5=140727492165471)
    at ./build/../src/backend/utils/fmgr/fmgr.c:1241
#6  0x000055bbbb4db72d in gistindex_keytest (recheck_distances_p=<synthetic
pointer>, recheck_p=<synthetic pointer>, offset=4, page=0x7f1293a45180
"K\313\003", tuple=0x7f1293a47058, scan=0x55bbbd4196c8)
    at ./build/../src/backend/access/gist/gistget.c:222
#7  gistScanPage (scan=scan@entry=0x55bbbd4196c8,
pageItem=pageItem@entry=0x7ffdac2e3fe0, myDistances=myDistances@entry=0x0,
tbm=tbm@entry=0x0, ntids=ntids@entry=0x0) at
./build/../src/backend/access/gist/gistget.c:438
#8  0x000055bbbb4dbf43 in gistgettuple (scan=0x55bbbd4196c8, dir=<optimized
out>) at ./build/../src/backend/access/gist/gistget.c:639
#9  0x000055bbbb50cb05 in index_getnext_tid (scan=0x55bbbd4196c8,
direction=<optimized out>) at
./build/../src/backend/access/index/indexam.c:533
#10 0x000055bbbb50ccbd in index_getnext_slot
(scan=scan@entry=0x55bbbd4196c8,
direction=direction@entry=ForwardScanDirection,
slot=slot@entry=0x55bbbd4057a0) at
./build/../src/backend/access/index/indexam.c:625
#11 0x000055bbbb6a3042 in IndexNext (node=node@entry=0x55bbbd405500) at
./build/../src/backend/executor/nodeIndexscan.c:133
#12 0x000055bbbb688281 in ExecScanFetch (recheckMtd=0x55bbbb6a38a0
<IndexRecheck>, accessMtd=0x55bbbb6a2fd0 <IndexNext>, node=0x55bbbd405500)
at ./build/../src/backend/executor/execScan.c:133
#13 ExecScan (node=0x55bbbd405500, accessMtd=0x55bbbb6a2fd0 <IndexNext>,
recheckMtd=0x55bbbb6a38a0 <IndexRecheck>) at
./build/../src/backend/executor/execScan.c:199
#14 0x000055bbbb685349 in ExecProcNodeInstr (node=0x55bbbd405500) at
./build/../src/backend/executor/execProcnode.c:479
#15 0x000055bbbb68fb9c in ExecProcNode (node=0x55bbbd405500) at
./build/../src/include/executor/executor.h:257
#16 fetch_input_tuple (aggstate=aggstate@entry=0x55bbbd404ed8) at
./build/../src/backend/executor/nodeAgg.c:581
#17 0x000055bbbb692c19 in agg_retrieve_direct (aggstate=0x55bbbd404ed8) at
./build/../src/backend/executor/nodeAgg.c:2364
#18 ExecAgg (pstate=0x55bbbd404ed8) at
./build/../src/backend/executor/nodeAgg.c:2179
#19 0x000055bbbb685349 in ExecProcNodeInstr (node=0x55bbbd404ed8) at
./build/../src/backend/executor/execProcnode.c:479
#20 0x000055bbbb6b14a1 in ExecProcNode (node=0x55bbbd404ed8) at
./build/../src/include/executor/executor.h:257
#21 ExecScanSubPlan (isNull=0x55bbbd4153dd, econtext=0x55bbbd414c00,
node=0x55bbbd415c70) at ./build/../src/backend/executor/nodeSubplan.c:323
#22 ExecSubPlan (node=node@entry=0x55bbbd415c70,
econtext=econtext@entry=0x55bbbd414c00, isNull=0x55bbbd4153dd) at
./build/../src/backend/executor/nodeSubplan.c:89
#23 0x000055bbbb678ebd in ExecEvalSubPlan (state=state@entry=0x55bbbd4153d8,
op=op@entry=0x55bbbd415618, econtext=econtext@entry=0x55bbbd414c00) at
./build/../src/backend/executor/execExprInterp.c:3932
#24 0x000055bbbb679b42 in ExecInterpExpr (state=0x55bbbd4153d8,
econtext=0x55bbbd414c00, isnull=<optimized out>) at
./build/../src/backend/executor/execExprInterp.c:1564
#25 0x000055bbbb6883d2 in ExecEvalExprSwitchContext (isNull=0x7ffdac2e4457,
econtext=0x55bbbd414c00, state=0x55bbbd4153d8) at
./build/../src/include/executor/executor.h:339
#26 ExecProject (projInfo=0x55bbbd4153d0) at
./build/../src/include/executor/executor.h:373
#27 ExecScan (node=<optimized out>, accessMtd=0x55bbbb6afe20 <SeqNext>,
recheckMtd=0x55bbbb6afdf0 <SeqRecheck>) at
./build/../src/backend/executor/execScan.c:238
#28 0x000055bbbb685349 in ExecProcNodeInstr (node=0x55bbbd414af0) at
./build/../src/backend/executor/execProcnode.c:479
#29 0x000055bbbb67e34d in ExecProcNode (node=0x55bbbd414af0) at
./build/../src/include/executor/executor.h:257
#30 ExecutePlan (execute_once=<optimized out>, dest=0x55bbbbdbf260
<donothingDR>, direction=<optimized out>, numberTuples=0,
sendTuples=<optimized out>, operation=CMD_SELECT,
use_parallel_mode=<optimized out>, planstate=0x55bbbd414af0,
    estate=0x55bbbd404c58) at
./build/../src/backend/executor/execMain.c:1551
#31 standard_ExecutorRun (queryDesc=0x55bbbd4037c8, direction=<optimized
out>, count=0, execute_once=<optimized out>) at
./build/../src/backend/executor/execMain.c:361
#32 0x00007f13269e0595 in pgss_ExecutorRun (queryDesc=0x55bbbd4037c8,
direction=ForwardScanDirection, count=0, execute_once=<optimized out>) at
./build/../contrib/pg_stat_statements/pg_stat_statements.c:1003
#33 0x000055bbbb60c3e8 in ExplainOnePlan
(plannedstmt=plannedstmt@entry=0x55bbbd402018, into=into@entry=0x0,
es=es@entry=0x55bbbd2e0f78,
    queryString=queryString@entry=0x55bbbd289148 "explain (analyze, buffers)
SELECT\n", ' ' <repeats 24 times>, "r.id,\n", ' ' <repeats 24 times>,
"r.name,\n", ' ' <repeats 24 times>, "r.map_center_y,\n", ' ' <repeats 24
times>, "r.map_center_x,\n", ' '
<repeats 24 times>..., params=params@entry=0x0, queryEnv=<optimized out>,
planduration=0x7ffdac2e4700, bufusage=0x7ffdac2e4780) at
./build/../src/backend/commands/explain.c:593
#34 0x000055bbbb60c7da in ExplainOneQuery (query=<optimized out>,
cursorOptions=<optimized out>, into=0x0, es=0x55bbbd2e0f78,
    queryString=0x55bbbd289148 "explain (analyze, buffers) SELECT\n", ' '
<repeats 24 times>, "r.id,\n", ' ' <repeats 24 times>, "r.name,\n", ' '
<repeats 24 times>, "r.map_center_y,\n", ' ' <repeats 24 times>,
"r.map_center_x,\n", ' ' <repeats 24 times>..., params=0x0, queryEnv=0x0) at
./build/../src/backend/commands/explain.c:410
#35 0x000055bbbb60ce7d in ExplainQuery (pstate=pstate@entry=0x55bbbd3a0230,
stmt=stmt@entry=0x55bbbd3b7840, params=params@entry=0x0,
dest=dest@entry=0x55bbbd3a01a0) at
./build/../src/backend/commands/explain.c:281
#36 0x000055bbbb806783 in standard_ProcessUtility
(pstmt=pstmt@entry=0x55bbbd3b7fa8,
    queryString=queryString@entry=0x55bbbd289148 "explain (analyze, buffers)
SELECT\n", ' ' <repeats 24 times>, "r.id,\n", ' ' <repeats 24 times>,
"r.name,\n", ' ' <repeats 24 times>, "r.map_center_y,\n", ' ' <repeats 24
times>, "r.map_center_x,\n", ' '
<repeats 24 times>..., readOnlyTree=<optimized out>,
context=context@entry=PROCESS_UTILITY_TOPLEVEL, params=params@entry=0x0,
queryEnv=queryEnv@entry=0x0, dest=0x55bbbd3a01a0, qc=0x7ffdac2e4c70) at
./build/../src/backend/tcop/utility.c:862
#37 0x00007f13269e2221 in pgss_ProcessUtility (pstmt=0x55bbbd3b7fa8,
    queryString=0x55bbbd289148 "explain (analyze, buffers) SELECT\n", ' '
<repeats 24 times>, "r.id,\n", ' ' <repeats 24 times>, "r.name,\n", ' '
<repeats 24 times>, "r.map_center_y,\n", ' ' <repeats 24 times>,
"r.map_center_x,\n", ' ' <repeats 24 times>..., readOnlyTree=<optimized
out>, context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0,
dest=0x55bbbd3a01a0, qc=0x7ffdac2e4c70) at
./build/../contrib/pg_stat_statements/pg_stat_statements.c:1135
#38 0x000055bbbb804935 in PortalRunUtility
(portal=portal@entry=0x55bbbd373888, pstmt=0x55bbbd3b7fa8,
isTopLevel=isTopLevel@entry=true,
setHoldSnapshot=setHoldSnapshot@entry=true, dest=dest@entry=0x55bbbd3a01a0,
qc=qc@entry=0x7ffdac2e4c70)
    at ./build/../src/backend/tcop/pquery.c:1155
#39 0x000055bbbb804cab in FillPortalStore
(portal=portal@entry=0x55bbbd373888, isTopLevel=isTopLevel@entry=true) at
./build/../src/backend/tcop/pquery.c:1028
#40 0x000055bbbb8050bf in PortalRun (portal=portal@entry=0x55bbbd373888,
count=count@entry=9223372036854775807, isTopLevel=isTopLevel@entry=true,
run_once=run_once@entry=true, dest=dest@entry=0x55bbbd3cec48,
altdest=altdest@entry=0x55bbbd3cec48,
    qc=0x7ffdac2e4e80) at ./build/../src/backend/tcop/pquery.c:760
#41 0x000055bbbb8008e9 in exec_simple_query (
    query_string=0x55bbbd289148 "explain (analyze, buffers) SELECT\n", ' '
<repeats 24 times>, "r.id,\n", ' ' <repeats 24 times>, "r.name,\n", ' '
<repeats 24 times>, "r.map_center_y,\n", ' ' <repeats 24 times>,
"r.map_center_x,\n", ' ' <repeats 24 times>...) at
./build/../src/backend/tcop/postgres.c:1214
#42 0x000055bbbb802c4c in PostgresMain (argc=argc@entry=1,
argv=argv@entry=0x7ffdac2e5340, dbname=<optimized out>, username=<optimized
out>) at ./build/../src/backend/tcop/postgres.c:4486
#43 0x000055bbbb775e2a in BackendRun (port=<optimized out>, port=<optimized
out>) at ./build/../src/backend/postmaster/postmaster.c:4530
#44 BackendStartup (port=<optimized out>) at
./build/../src/backend/postmaster/postmaster.c:4252
#45 ServerLoop () at ./build/../src/backend/postmaster/postmaster.c:1745
#46 0x000055bbbb776c68 in PostmasterMain (argc=5, argv=0x55bbbd281d90) at
./build/../src/backend/postmaster/postmaster.c:1417
#47 0x000055bbbb4af83b in main (argc=5, argv=0x55bbbd281d90) at
./build/../src/backend/main/main.c:209

I can reproduce the issue easily, if you need more details.

On 2/15/22 18:32, PG Bug reporting form wrote:
> The following bug has been logged on the website:
> 
> Bug reference:      17406
> Logged by:          Victor Yegorov
> Email address:      vyegorov@gmail.com
> PostgreSQL version: 14.2
> Operating system:   Ubuntu 18.04.6 LTS (bionic)
> Description:
> 
> KVM guest, on Intel(R) Xeon(R) CPU E5-2697 v2.
> 
> PostgreSQL 12.9 had been upgraded to 14.2 using
> 
> pg_upgradecluster -k  -m link 12 main /mnt/postgres/14/
> 
> After that, one of the queries is crashing with Segmentation Fault.
> However, after REINDEX problem will be fixed. I thought I should report
> still.
> 

Hmm. So I guess there are three options:

1) The index was already broken on 12.9, but for some reason (choice of 
a different plan, ...) it was not causing any issues.

2) The index got broken during/after the upgrade, for some reason.

3) The index is fine, but there's a newly introduced bug in ltree (or 
gist in general).

Hard to say which it is.

How large is the table/index? Are you able to run the query with a 
custom build (without values optimized out)? Any chance you still have a 
backup from before the pg_upgrade, on which you might run the query?

> explain
> SELECT r.id, r.name, r.map_center_y, r.map_center_x,
>         COALESCE ((SELECT string_agg(id::TEXT, ',') FROM v3_region AS r2
> WHERE r2.id != r.id AND r2.ltree_path <@ r.ltree_path), '') AS children
>    FROM v3_region AS r;
>                                                   QUERY PLAN
> -------------------------------------------------------------------------------------------------------------
>   Seq Scan on v3_region r  (cost=0.00..3207.31 rows=349 width=580)
>     SubPlan 1
>       ->  Aggregate  (cost=8.17..8.18 rows=1 width=32)
>             ->  Index Scan using region_ltree_path_idx_gist on v3_region r2
> (cost=0.14..8.16 rows=1 width=4)
>                   Index Cond: (ltree_path <@ r.ltree_path)
>                   Filter: (id <> r.id)
> (6 rows)
> 
> Here is backtrace:
> #0  __memmove_sse2_unaligned_erms () at
> ../sysdeps/x86_64/multiarch/memmove-vec-unaligned-erms.S:435
> #1  0x00007f129244c266 in memcpy (__len=<optimized out>,
> __src=0x55bbbd430f4a, __dest=<optimized out>) at
> /usr/include/x86_64-linux-gnu/bits/string_fortified.h:34
> #2  copy_ltree (src=0x55bbbd430f4a) at
> ./build/../contrib/ltree/ltree_gist.c:446
> #3  0x00007f129244db51 in gist_ischild (siglen=28, query=0x55bbbd410cb8,
> key=0x55bbbd430f18) at ./build/../contrib/ltree/ltree_gist.c:454

Interesting. Too bad the memcpy() parameters are optimized out. But 
clearly src is not NULL, so perhas something is wrong with the dst pointer?

> #4  ltree_consistent (fcinfo=0x7ffdac2e3e20) at
> ./build/../contrib/ltree/ltree_gist.c:674
> #5  0x000055bbbb944a5d in FunctionCall5Coll
> (flinfo=flinfo@entry=0x55bbbd416b20, collation=<optimized out>,
> arg1=arg1@entry=140727492165472, arg2=<optimized out>, arg3=<optimized out>,
> arg4=<optimized out>, arg5=140727492165471)
>      at ./build/../src/backend/utils/fmgr/fmgr.c:1241
> #6  0x000055bbbb4db72d in gistindex_keytest (recheck_distances_p=<synthetic
> pointer>, recheck_p=<synthetic pointer>, offset=4, page=0x7f1293a45180
> "K\313\003", tuple=0x7f1293a47058, scan=0x55bbbd4196c8)
>      at ./build/../src/backend/access/gist/gistget.c:222
> #7  gistScanPage (scan=scan@entry=0x55bbbd4196c8,
> pageItem=pageItem@entry=0x7ffdac2e3fe0, myDistances=myDistances@entry=0x0,
> tbm=tbm@entry=0x0, ntids=ntids@entry=0x0) at
> ./build/../src/backend/access/gist/gistget.c:438

Can you print the pageItem->blkno? That should tell us which index page 
is causing issues. And then you can dump the page using pageinspect [1]. 
For example if blkno = 100, then this might tell us more:

  SELECT * FROM
  gist_page_opaque_info(get_raw_page('region_ltree_path_idx_gist', 100));

  SELECT * FROM
  gist_page_items(get_raw_page('region_ltree_path_idx_gist', 100),
                               'region_ltree_path_idx_gist');

  SELECT * FROM
  gist_page_items_bytea(get_raw_page('region_ltree_path_idx_gist', 0));


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On Wed, Feb 16, 2022 at 3:15 PM Victor Yegorov <vyegorov@gmail.com> wrote:

> For custom build I need some time to actually build it.
> What options would you recommend (for configure) me to use here?

Normally for debug builds you would use something like

--enable-cassert \
--enable-debug \
CFLAGS="-ggdb -Og -fno-omit-frame-pointer"

-Og still performs some optimization (on gcc it's like -O1 but with
some optimization passes taken out that interfere with debuging), so
it's somewhat realistic compared to production code. But to make sure
this argument is visible, you might have to use -O0 (no optimization).

-- 
John Naylor
EDB: http://www.enterprisedb.com

On 2/16/22 09:14, Victor Yegorov wrote:
> вт, 15 февр. 2022 г. в 22:51, Tomas Vondra 
> <tomas.vondra@enterprisedb.com <mailto:tomas.vondra@enterprisedb.com>>:
> 
>     Hmm. So I guess there are three options:
> 
>     1) The index was already broken on 12.9, but for some reason (choice of
>     a different plan, ...) it was not causing any issues.
> 
> 
> Nope, index is actively used on 12.9, plan hasn't changed.
> 

OK, that's valuable information.

>     How large is the table/index? Are you able to run the query with a
>     custom build (without values optimized out)? Any chance you still
>     have a
>     backup from before the pg_upgrade, on which you might run the query?
> 
> 
> Yes, this is a test DB restored from backup in order to test out 14 
> upgrade, production is still running on 12.9.
> v3_region is 2832 kB
> region_ltree_path_idx_gist is 472 kB
> 

That means it should be possible to reproduce the issue elsewhere by 
copying the files (and schema). Is there any sensitive data that'd 
prevent handing over this data?

> 
> (gdb) frame 7
> #7  gistScanPage (scan=scan@entry=0x55bbbd4196c8, 
> pageItem=pageItem@entry=0x7ffdac2e3fe0, 
> myDistances=myDistances@entry=0x0, tbm=tbm@entry=0x0, 
> ntids=ntids@entry=0x0) at ./build/../src/backend/access/gist/gistget.c:438
> 438     ./build/../src/backend/access/gist/gistget.c: No such file or 
> directory.
> (gdb) p pageItem->blkno
> $1 = 0
> (gdb) p pageItem->data->heap
> $5 = {heapPtr = {ip_blkid = {bi_hi = 0, bi_lo = 0}, ip_posid = 0}, 
> recheck = false, recheckDistances = false, recontup = 0x55bbbb96927e 
> <palloc+46>, offnum = 38600}
> 
> This query below also crashes with SegFault:
> SELECT * FROM gist_page_items(get_raw_page('region_ltree_path_idx_gist', 
> 0), 'region_ltree_path_idx_gist');
> 

Interesting! What's the backtrace from the crash?


FWIW when I try that query on the gist index from the ltree example in 
our documentation, I get this:

test=# SELECT * FROM gist_page_items(get_raw_page('path_gist_idx', 0), 
'path_gist_idx');
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21b4ae0, chunk 0x21b5ff8
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21b4ae0, chunk 0x21b6f20
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21b4ae0, chunk 0x21b7e48
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21b4ae0, chunk 0x21b8db0
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21b4ae0, chunk 0x21b9d18
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21b4ae0, chunk 0x21bac80
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21b0ad0, chunk 0x21b1360
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21b0ad0, chunk 0x21b2288
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21b0ad0, chunk 0x21b31f0
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21b0ad0, chunk 0x21b4158
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21aaab0, chunk 0x21adb20
WARNING:  problem in alloc set ExprContext: detected write past chunk 
end in block 0x21aaab0, chunk 0x21ae5c8
  itemoffset |  ctid  | itemlen | dead |   keys
------------+--------+---------+------+-----------
           1 | (0,1)  |      32 | f    | (path)=()
           2 | (0,2)  |      48 | f    | (path)=()
           3 | (0,3)  |      64 | f    | (path)=()
           4 | (0,4)  |      80 | f    | (path)=()
           5 | (0,5)  |      80 | f    | (path)=()
           6 | (0,6)  |      48 | f    | (path)=()
           7 | (0,7)  |      72 | f    | (path)=()
           8 | (0,8)  |      48 | f    | (path)=()
           9 | (0,9)  |      64 | f    | (path)=()
          10 | (0,10) |      80 | f    | (path)=()
          11 | (0,11) |      88 | f    | (path)=()
          12 | (0,12) |      96 | f    | (path)=()
          13 | (0,13) |      96 | f    | (path)=()
(13 rows)

This is on debug build with asserts. On non-assert build it crashes in 
AllocSetAlloc, but I'd bet the exact place where it crashes just depends 
on what place we corrupt by writing out of ExprContext. The empty paths 
seem strange too, of course.

But the confusing thing is I get similar issues even on 12.10 (after 
backporting the pageinspect gist changes) - but only with asserts, and 
without asserts it works (but the paths are still empty). Perhaps I 
backported that incorrectly, though.


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On Wed, Feb 16, 2022 at 4:16 PM Tomas Vondra
<tomas.vondra@enterprisedb.com> wrote:
> test=# SELECT * FROM gist_page_items(get_raw_page('path_gist_idx', 0),
> 'path_gist_idx');

Maybe this is obvious, but just in case: gist_page_items is *very*
trusting here. It's necessary to use gist_page_items_bytea() if you're
not 100% sure about the index definition for the index page you
provide. The fact that you can display the contents of each tuple
using the underlying type's own output function is very handy. But
potentially hazardous.

-- 
Peter Geoghegan

On 2/17/22 03:52, Peter Geoghegan wrote:
> On Wed, Feb 16, 2022 at 4:16 PM Tomas Vondra
> <tomas.vondra@enterprisedb.com> wrote:
>> test=# SELECT * FROM gist_page_items(get_raw_page('path_gist_idx', 0),
>> 'path_gist_idx');
> 
> Maybe this is obvious, but just in case: gist_page_items is *very*
> trusting here. It's necessary to use gist_page_items_bytea() if you're
> not 100% sure about the index definition for the index page you
> provide. The fact that you can display the contents of each tuple
> using the underlying type's own output function is very handy. But
> potentially hazardous.
> 

Sure, but I used this to inspect the index from example in our docs:

   https://www.postgresql.org/docs/14/ltree.html#id-1.11.7.30.8

I doubt we can be even more sure about the index definition.


I don't know what the root cause is yet, but the memory corruption 
happens simply because ltree_out() sees entirely bogus data when 
executed from gist_page_items.

For example it gets 16B varlena, allocates 16B string for it, and starts 
iterating over the ltree data. The it finds the first element is 60B 
long and happily copies it "into" the 16B buffer. That can't end well, 
obviously.

Clearly, the ltree values are mangled somehow / somewhere. The funny 
thing is the bytea always looks 8B longer and with bogus data. So for 
example if you select this ltree from the table directly

   Top.Collections.Pictures.Astronomy.Astronauts

then ltree_out sees it as 80B varlena, with 5 levels. But if ltree_out 
gets called from gist_page_items, then it sees 88B with 1 level, which 
is completely bogus.

And funnily enough, if you do this at the beginning of ltree_out:

   in = (ltree *) ((char *) in + 8);

then gist_page_items() starts working just fine.

So, I guess gist_page_items() is broken/confused in some way. I'm not 
sure if this is related to the crash reported by Victor or a separate, 
independent issue.


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 2/17/22 13:26, Tomas Vondra wrote:
> On 2/17/22 03:52, Peter Geoghegan wrote:
>> On Wed, Feb 16, 2022 at 4:16 PM Tomas Vondra
>> <tomas.vondra@enterprisedb.com> wrote:
>>> test=# SELECT * FROM gist_page_items(get_raw_page('path_gist_idx', 0),
>>> 'path_gist_idx');
>>
>> Maybe this is obvious, but just in case: gist_page_items is *very*
>> trusting here. It's necessary to use gist_page_items_bytea() if you're
>> not 100% sure about the index definition for the index page you
>> provide. The fact that you can display the contents of each tuple
>> using the underlying type's own output function is very handy. But
>> potentially hazardous.
>>
> 
> Sure, but I used this to inspect the index from example in our docs:
> 
>   https://www.postgresql.org/docs/14/ltree.html#id-1.11.7.30.8
> 
> I doubt we can be even more sure about the index definition.
> 
> 
> I don't know what the root cause is yet, but the memory corruption
> happens simply because ltree_out() sees entirely bogus data when
> executed from gist_page_items.
> 
> For example it gets 16B varlena, allocates 16B string for it, and starts
> iterating over the ltree data. The it finds the first element is 60B
> long and happily copies it "into" the 16B buffer. That can't end well,
> obviously.
> 
> Clearly, the ltree values are mangled somehow / somewhere. The funny
> thing is the bytea always looks 8B longer and with bogus data. So for
> example if you select this ltree from the table directly
> 
>   Top.Collections.Pictures.Astronomy.Astronauts
> 
> then ltree_out sees it as 80B varlena, with 5 levels. But if ltree_out
> gets called from gist_page_items, then it sees 88B with 1 level, which
> is completely bogus.
> 
> And funnily enough, if you do this at the beginning of ltree_out:
> 
>   in = (ltree *) ((char *) in + 8);
> 
> then gist_page_items() starts working just fine.
> 
> So, I guess gist_page_items() is broken/confused in some way. I'm not
> sure if this is related to the crash reported by Victor or a separate,
> independent issue.
> 

I may be wrong, but it seems gist_page_items() is entirely oblivious to
the fact that GiST does "compression", and fails to decompress the
values before passing them to out function. So instead of "ltree" it
extracts "ltree_gist" and passes that to "ltree_out".

This is consistent with the 8B offset I mentioned before, because
ltree_gist has 8B header and then stores the original ltree value.

But I may be missing something - this seems like such an obvious gap
that I don't know how this could have worked with anything but the most
trivial cases without GiST compression.

Furthermore, it seems more like a pageinspect issue, unrelated to the
original issue reported by Victor.


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 2/17/22 01:16, Tomas Vondra wrote:
>  ...
>
>>     How large is the table/index? Are you able to run the query with a
>>     custom build (without values optimized out)? Any chance you still
>>     have a
>>     backup from before the pg_upgrade, on which you might run the query?
>>
>>
>> Yes, this is a test DB restored from backup in order to test out 14
>> upgrade, production is still running on 12.9.
>> v3_region is 2832 kB
>> region_ltree_path_idx_gist is 472 kB
>>
> 
> That means it should be possible to reproduce the issue elsewhere by
> copying the files (and schema). Is there any sensitive data that'd
> prevent handing over this data?
> 

Maybe we could also try just dumping the data (the ltree_path column),
so that we can load it into 12 cluster and do a binary upgrade. That
would be simpler than trying to copy the existing data files.


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

>
> I got approval to send a table with its data and index in the subject
> datafile.
> Taken from the v14 database.
> 

Thanks for the data! I've been able to reproduce the issue (load into
12, pg_upgrade to 14 and run the query). After bisecting this for a
while, this seems like a bug in PG13 commit

commit 911e70207703799605f5a0e8aad9f06cff067c63 (HEAD)
Author: Alexander Korotkov <akorotkov@postgresql.org>
Date:   Mon Mar 30 19:17:11 2020 +0300

    Implement operator class parameters

    ...

It works fine when upgrading to an earlier build, and crashes since this
commit. I haven't investigated this further, but I guess there's some
thinko in gist_ltree_ops, affecting how we interpret existing indexes.

Alexander, any ideas?


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 2/23/22 16:36, Tomas Vondra wrote:
>>
>> I got approval to send a table with its data and index in the subject
>> datafile.
>> Taken from the v14 database.
>>
> 
> Thanks for the data! I've been able to reproduce the issue (load into
> 12, pg_upgrade to 14 and run the query). After bisecting this for a
> while, this seems like a bug in PG13 commit
> 
> commit 911e70207703799605f5a0e8aad9f06cff067c63 (HEAD)
> Author: Alexander Korotkov <akorotkov@postgresql.org>
> Date:   Mon Mar 30 19:17:11 2020 +0300
> 
>     Implement operator class parameters
> 
>     ...
> 
> It works fine when upgrading to an earlier build, and crashes since this
> commit. I haven't investigated this further, but I guess there's some
> thinko in gist_ltree_ops, affecting how we interpret existing indexes.
> 
> Alexander, any ideas?
> 

Sorry, I accidentally used Alexander's old address, so let me CC him
with the correct/current one.


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 2/23/22 16:41, Tomas Vondra wrote:
> On 2/23/22 16:36, Tomas Vondra wrote:
>>>
>>> I got approval to send a table with its data and index in the subject
>>> datafile.
>>> Taken from the v14 database.
>>>
>>
>> Thanks for the data! I've been able to reproduce the issue (load into
>> 12, pg_upgrade to 14 and run the query). After bisecting this for a
>> while, this seems like a bug in PG13 commit
>>
>> commit 911e70207703799605f5a0e8aad9f06cff067c63 (HEAD)
>> Author: Alexander Korotkov <akorotkov@postgresql.org>
>> Date:   Mon Mar 30 19:17:11 2020 +0300
>>
>>     Implement operator class parameters
>>
>>     ...
>>
>> It works fine when upgrading to an earlier build, and crashes since this
>> commit. I haven't investigated this further, but I guess there's some
>> thinko in gist_ltree_ops, affecting how we interpret existing indexes.
>>
>> Alexander, any ideas?
>>
> 
> Sorry, I accidentally used Alexander's old address, so let me CC him
> with the correct/current one.
> 

I tried investigating this a bit further, but my gist-foo is rather
limited so I haven't made much progress so far. But as Victor already
mentioned, REINDEX fixes this - so I tried comparing the broken index
with a new one built on PG13.

And the it seems the indexes are mostly the same, with the exception of
LSN in the page header. The only page that substantially differs is the
first page, which is also storing less data (the broken version):

test=# SELECT * FROM
page_header(get_raw_page('v3_region_copy_ltree_path_idx', 0));
    lsn    | checksum | flags | lower | upper | special | pagesize | ...
----------+----------+-------+-------+-------+---------+----------+- ...
 0/1CD80C8 |        0 |     0 |    40 |  7856 |    8176 |     8192 | ...
  (1 row)

test=# SELECT * FROM
page_header(get_raw_page('v3_region_copy_13_ltree_path_idx', 0));
    lsn    | checksum | flags | lower | upper | special | pagesize | ...
-----------+----------+-------+-------+-------+---------+----------+-...
 0/7029760 |        0 |     0 |    40 |  7760 |    8176 |     8192 | ...
(1 row)


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 2/24/22 16:18, Tomas Vondra wrote:
> On 2/23/22 16:41, Tomas Vondra wrote:
>> On 2/23/22 16:36, Tomas Vondra wrote:
>>>>
>>>> I got approval to send a table with its data and index in the subject
>>>> datafile.
>>>> Taken from the v14 database.
>>>>
>>>
>>> Thanks for the data! I've been able to reproduce the issue (load into
>>> 12, pg_upgrade to 14 and run the query). After bisecting this for a
>>> while, this seems like a bug in PG13 commit
>>>
>>> commit 911e70207703799605f5a0e8aad9f06cff067c63 (HEAD)
>>> Author: Alexander Korotkov <akorotkov@postgresql.org>
>>> Date:   Mon Mar 30 19:17:11 2020 +0300
>>>
>>>     Implement operator class parameters
>>>
>>>     ...
>>>
>>> It works fine when upgrading to an earlier build, and crashes since this
>>> commit. I haven't investigated this further, but I guess there's some
>>> thinko in gist_ltree_ops, affecting how we interpret existing indexes.
>>>
>>> Alexander, any ideas?
>>>
>>
>> Sorry, I accidentally used Alexander's old address, so let me CC him
>> with the correct/current one.
>>
> 
> I tried investigating this a bit further, but my gist-foo is rather
> limited so I haven't made much progress so far. But as Victor already
> mentioned, REINDEX fixes this - so I tried comparing the broken index
> with a new one built on PG13.
> 
> And the it seems the indexes are mostly the same, with the exception of
> LSN in the page header. The only page that substantially differs is the
> first page, which is also storing less data (the broken version):
> 
> test=# SELECT * FROM
> page_header(get_raw_page('v3_region_copy_ltree_path_idx', 0));
>     lsn    | checksum | flags | lower | upper | special | pagesize | ...
> ----------+----------+-------+-------+-------+---------+----------+- ...
>  0/1CD80C8 |        0 |     0 |    40 |  7856 |    8176 |     8192 | ...
>   (1 row)
> 
> test=# SELECT * FROM
> page_header(get_raw_page('v3_region_copy_13_ltree_path_idx', 0));
>     lsn    | checksum | flags | lower | upper | special | pagesize | ...
> -----------+----------+-------+-------+-------+---------+----------+-...
>  0/7029760 |        0 |     0 |    40 |  7760 |    8176 |     8192 | ...
> (1 row)
> 

It took me a bit of digging and debugging, but I think I got it. The
problem is that to determine siglen value, some of the functions use

  LTREE_GET_ASIGLEN

macro, which inspects the opclass options and returns the value. But if
there are no explicit options for the particular index (as happens for
indexes created in older versions), it uses LTREE_ASIGLEN_DEFAULT, which
is 28 bytes. But that's wrong - this value for ltree[] gist opclass, not
for plain ltree - that uses just 8B. So we're off by 20B, which messes
all kinds of stuff, of course.

My guess this is a simple mistake, because the macro is in section
labeled as

  /* GiST support for ltree[] */

and the "A" in the name probably refers to "array" too.

Attached is a patch that fixes this, but I wonder what will happen to
new indexes created on 13+. Will check.

Victor, can you try with this patch applied?


regards

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

On 2/24/22 19:36, Tomas Vondra wrote:
>
> ...
> 
> Attached is a patch that fixes this, but I wonder what will happen to
> new indexes created on 13+. Will check.
> 

Unfortunately, the patch fixes indexes built on PG12, but it also breaks
indexes created after pg_upgrade :-(

I'm not sure if a good solution even exists, because we can't really
distinguish those indexes. It only affects ltree_gist, though, and we
didn't get any other reports so far, so either few people are using it
or have not upgraded yet.

I've created a thread on pgsql-hackers [1], where it might get more
attention from other developers. Maybe they'll have a better idea on how
to fix this.

regards

[1]
https://www.postgresql.org/message-id/d80e0a55-6c3e-5b26-53e3-3c4f973f737c%40enterprisedb.com

-- 
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company