Hi, while repeating some full-text benchmarks on master, I've discovered that there's a data corruption bug somewhere. What happens is that while loading data into a table with GIN indexes (using multiple parallel connections), I sometimes get this:
TRAP: FailedAssertion("!(((PageHeader) (page))->pd_special >=
(__builtin_offsetof (PageHeaderData, pd_linp)))", File: "ginfast.c",
Line: 537)
LOG: server process (PID 22982) was terminated by signal 6: Aborted
DETAIL: Failed process was running: autovacuum: ANALYZE messages
The details of the assert are always exactly the same - it's always
autovacuum and it trips on exactly the same check. And the backtrace
always looks like this (full backtrace attached):
#0 0x00007f133b635045 in raise () from /lib64/libc.so.6
#1 0x00007f133b6364ea in abort () from /lib64/libc.so.6
#2 0x00000000007dc007 in ExceptionalCondition
(conditionName=conditionName@entry=0x81a088 "!(((PageHeader)
(page))->pd_special >= (__builtin_offsetof (PageHeaderData, pd_linp)))",
errorType=errorType@entry=0x81998b "FailedAssertion",
fileName=fileName@entry=0x83480a "ginfast.c",
lineNumber=lineNumber@entry=537) at assert.c:54
#3 0x00000000004894aa in shiftList (stats=0x0, fill_fsm=1 '\001',
newHead=26357, metabuffer=130744, index=0x7f133c0f7518) at ginfast.c:537
#4 ginInsertCleanup (ginstate=ginstate@entry=0x7ffd98ac9160,
vac_delay=vac_delay@entry=1 '\001', fill_fsm=fill_fsm@entry=1 '\001',
stats=stats@entry=0x0) at ginfast.c:908
#5 0x00000000004874f7 in ginvacuumcleanup (fcinfo=<optimized out>) at
ginvacuum.c:662
...
It's not perfectly deterministic - sometimes I had repeat the whole load
multiple times (up to 5x, and each load takes ~30minutes).
I'm pretty sure this is not external issue, because I've reproduced it
on a different machine (different CPU / kernel / libraries / compiler).
It's however interesting that on the other machine I've also observed a
different kind of lockups, where the sessions get stuck on semop() in
gininsert (again, full backtrace attached):
#0 0x0000003f3d4eaf97 in semop () from /lib64/libc.so.6
#1 0x000000000067a41f in PGSemaphoreLock (sema=0x7f93290405d8) at
pg_sema.c:387
#2 0x00000000006df613 in LWLockAcquire (lock=0x7f92a4dce900,
mode=LW_EXCLUSIVE) at lwlock.c:1049
#3 0x00000000004878c6 in ginHeapTupleFastInsert
(ginstate=0x7ffd969c88f0, collector=0x7ffd969caeb0) at ginfast.c:250
#4 0x000000000047423a in gininsert (fcinfo=<value optimized out>) at
gininsert.c:531
...
I'm not sure whether this is a different manifestation of the same issue
or another bug. The systems are not exactly the same - one has a single
socket (i5) while the other one has 2 (Xeon), the compilers and kernels
are different and so on.
I've also seen cases when the load seemingly completed OK, but trying to
dump the table to disk using COPY resulted in
ERROR: compressed data is corrupted
which I find rather strange as there was no previous error, and also
COPY should only dump table data (while the asserts were in GIN code
handling index pages, unless I'm mistaken). Seems like a case of
insufficient locking where two backends scribble on the same page
somehow, and then autovacuum hits the assert. Ot maybe not, not sure.
I've been unable to reproduce the issue on REL9_5_STABLE (despite
running the load ~20x on each machine), so that seems safe, and the
issue was introduced by some of the newer commits.
I've already spent too much CPU time on this, so perhaps someone with
better knowledge of the GIN code can take care of this. To reproduce it
you may use the same code I did - it's available here:
https://bitbucket.org/tvondra/archie
it's a PoC of database with pgsql mailing lists with fulltext. It's a
bit messy, but it's rather simple
1) clone the repo
$ git clone https://bitbucket.org/tvondra/archie.git
2) create a directory for downloading the mbox files
$ mkdir archie-data
3) download the mbox files (~4.5GB of data) using the download
script (make sure archie/bin is on PATH)
$ cd archie-data
$ export PATH=../archie/bin:$PATH
$ ../archie/download
4) use "run" scipt (attached) to run the load n-times on a given
commit
$ run.sh master 10
NOTICE: The run script is the messiest one, you'll have to
edit it to fix paths etc.
regards
--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Core was generated by `postgres: autovacuum worker process archie
'.
Program terminated with signal SIGABRT, Aborted.
#0 0x00007f133b635045 in raise () from /lib64/libc.so.6
(gdb) bt
#0 0x00007f133b635045 in raise () from /lib64/libc.so.6
#1 0x00007f133b6364ea in abort () from /lib64/libc.so.6
#2 0x00000000007dc007 in ExceptionalCondition
(conditionName=conditionName@entry=0x81a088 "!(((PageHeader)
(page))->pd_special >= (__builtin_offsetof (PageHeaderData, pd_linp)))",
errorType=errorType@entry=0x81998b "FailedAssertion",
fileName=fileName@entry=0x83480a "ginfast.c", lineNumber=lineNumber@entry=537)
at assert.c:54
#3 0x00000000004894aa in shiftList (stats=0x0, fill_fsm=1 '\001',
newHead=26357, metabuffer=130744, index=0x7f133c0f7518) at ginfast.c:537
#4 ginInsertCleanup (ginstate=ginstate@entry=0x7ffd98ac9160,
vac_delay=vac_delay@entry=1 '\001', fill_fsm=fill_fsm@entry=1 '\001',
stats=stats@entry=0x0) at ginfast.c:908
#5 0x00000000004874f7 in ginvacuumcleanup (fcinfo=<optimized out>) at
ginvacuum.c:662
#6 0x00000000007e39ef in FunctionCall2Coll
(flinfo=flinfo@entry=0x7ffd98acbb20, collation=collation@entry=0,
arg1=arg1@entry=140727164910976, arg2=arg2@entry=0) at fmgr.c:1323
#7 0x00000000004b6758 in index_vacuum_cleanup (info=info@entry=0x7ffd98acbd80,
stats=stats@entry=0x0) at indexam.c:717
#8 0x0000000000574909 in do_analyze_rel (onerel=onerel@entry=0x7f133c0e2820,
options=options@entry=98, va_cols=va_cols@entry=0x0,
acquirefunc=0x40f8928000000000, relpages=82810,
inh=inh@entry=0 '\000', in_outer_xact=in_outer_xact@entry=0 '\000',
elevel=elevel@entry=13, params=<optimized out>) at analyze.c:628
#9 0x00000000005758f3 in analyze_rel (relid=relid@entry=5350190,
relation=relation@entry=0x7ffd98acc120, options=options@entry=98,
params=params@entry=0x20aabd0,
va_cols=va_cols@entry=0x0, in_outer_xact=0 '\000', bstrategy=0x20aac60) at
analyze.c:257
#10 0x00000000005d1c3d in vacuum (options=98,
relation=relation@entry=0x7ffd98acc120, relid=<optimized out>,
params=0x20aabd0, params@entry=0xe, va_cols=va_cols@entry=0x0,
bstrategy=<optimized out>, bstrategy@entry=0x20aac60,
isTopLevel=isTopLevel@entry=1 '\001') at vacuum.c:313
#11 0x000000000067e400 in autovacuum_do_vac_analyze (bstrategy=0x20aac60,
tab=0x6) at autovacuum.c:2807
#12 do_autovacuum () at autovacuum.c:2328
#13 0x000000000067e8fa in AutoVacWorkerMain (argv=0x0, argc=0) at
autovacuum.c:1647
#14 0x000000000067e9b2 in StartAutoVacWorker () at autovacuum.c:1454
#15 0x000000000068bd40 in StartAutovacuumWorker () at postmaster.c:5289
#16 sigusr1_handler (postgres_signal_arg=<optimized out>) at postmaster.c:4973
#17 <signal handler called>
#18 0x00007f133b6e2573 in select () from /lib64/libc.so.6
#19 0x0000000000465945 in ServerLoop () at postmaster.c:1648
#20 0x000000000068ce1a in PostmasterMain (argc=argc@entry=3,
argv=argv@entry=0x1febc70) at postmaster.c:1292
#21 0x0000000000466d4f in main (argc=3, argv=0x1febc70) at main.c:223
(gdb) bt
#0 0x0000003f3d4eaf97 in semop () from /lib64/libc.so.6
#1 0x000000000067a41f in PGSemaphoreLock (sema=0x7f93290405d8) at pg_sema.c:387
#2 0x00000000006df613 in LWLockAcquire (lock=0x7f92a4dce900,
mode=LW_EXCLUSIVE) at lwlock.c:1049
#3 0x00000000004878c6 in ginHeapTupleFastInsert (ginstate=0x7ffd969c88f0,
collector=0x7ffd969caeb0) at ginfast.c:250
#4 0x000000000047423a in gininsert (fcinfo=<value optimized out>) at
gininsert.c:531
#5 0x00000000007e18e3 in FunctionCall6Coll (flinfo=<value optimized out>,
collation=<value optimized out>, arg1=<value optimized out>, arg2=<value
optimized out>,
arg3=<value optimized out>, arg4=<value optimized out>,
arg5=140267807601056, arg6=0) at fmgr.c:1436
#6 0x00000000004b4b97 in index_insert (indexRelation=0x7f92a4d8c6b8,
values=0x7ffd969cb3d0, isnull=0x7ffd969cb4d0 "", heap_t_ctid=0x2fa58ac,
heapRelation=0x7f92a4d871a0,
checkUnique=UNIQUE_CHECK_NO) at indexam.c:226
#7 0x00000000005d8db7 in ExecInsertIndexTuples (slot=0x2f18b80,
tupleid=0x2fa58ac, estate=0x2d3c0a8, noDupErr=0 '\000', specConflict=0x0,
arbiterIndexes=0x0) at execIndexing.c:384
#8 0x00000000005f876d in ExecInsert (node=0x2d3ceb8) at nodeModifyTable.c:458
#9 ExecModifyTable (node=0x2d3ceb8) at nodeModifyTable.c:1430
#10 0x00000000005dd678 in ExecProcNode (node=0x2d3ceb8) at execProcnode.c:396
#11 0x00000000005db3f2 in ExecutePlan (queryDesc=0x2affb98, direction=<value
optimized out>, count=0) at execMain.c:1566
#12 standard_ExecutorRun (queryDesc=0x2affb98, direction=<value optimized out>,
count=0) at execMain.c:338
#13 0x00000000006f15ef in ProcessQuery (plan=0x2f00c68,
sourceText=0x2ef36a8 "INSERT INTO messages (list, message_id, in_reply_to,
refs, sent, subject, author, body_plain, headers, raw_message) VALUES
('pgsql-hackers', '3a931fa9.1d698...@tpf.co.jp', NULL,
ARRAY['EKEJJICOHDIEMGP"..., params=0x0, dest=<value optimized out>,
completionTag=0x7ffd969cb920 "") at pquery.c:185
#14 0x00000000006f184c in PortalRunMulti (portal=0x2a83ed8, isTopLevel=1
'\001', dest=0x2f00d60, altdest=0x2f00d60, completionTag=0x7ffd969cb920 "") at
pquery.c:1275
#15 0x00000000006f1f92 in PortalRun (portal=0x2a83ed8,
count=9223372036854775807, isTopLevel=1 '\001', dest=0x2f00d60,
altdest=0x2f00d60, completionTag=0x7ffd969cb920 "") at pquery.c:812
#16 0x00000000006eebc7 in exec_simple_query (
query_string=0x2ef36a8 "INSERT INTO messages (list, message_id,
in_reply_to, refs, sent, subject, author, body_plain, headers, raw_message)
VALUES ('pgsql-hackers', '3a931fa9.1d698...@tpf.co.jp', NULL,
ARRAY['EKEJJICOHDIEMGP"...) at postgres.c:1105
#17 0x00000000006f0262 in PostgresMain (argc=<value optimized out>, argv=<value
optimized out>, dbname=0x2a6a878 "archie", username=<value optimized out>) at
postgres.c:4031
#18 0x000000000068d89b in BackendRun (argc=<value optimized out>, argv=<value
optimized out>) at postmaster.c:4235
#19 BackendStartup (argc=<value optimized out>, argv=<value optimized out>) at
postmaster.c:3911
#20 ServerLoop (argc=<value optimized out>, argv=<value optimized out>) at
postmaster.c:1684
#21 PostmasterMain (argc=<value optimized out>, argv=<value optimized out>) at
postmaster.c:1292
#22 0x0000000000616238 in main (argc=3, argv=0x2a69a20) at main.c:223
run.sh
Description: application/shellscript
-- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
