On Sun, Apr 04, 2021 at 07:52:50PM +0200, Tomas Vondra wrote:
> On 4/4/21 7:25 AM, Jaime Casanova wrote:
> >
> > pgbench -i postgres
> > psql -c "CREATE INDEX ON pgbench_history USING brin (tid
> > int4_minmax_multi_ops);" postgres
> > pgbench -c2 -j2 -T 300 -n postgres
> >
>
> Fixed and pushed too.
>
> Turned out to be a silly bug in forgetting to remember the number of
> ranges after deduplication, which sometimes resulted in assert failure.
> It's a bit hard to trigger because concurrency / good timing is needed
> while summarizing the range, requiring a call to "union" function. Just
> running the pgbench did not trigger the issue for me, I had to manually
> call the brin_summarize_new_values().
>
> For the record, I did a lot of testing with data randomized in various
> ways - the scripts are available here:
>
> https://github.com/tvondra/brin-randomized-tests
>
> It was focused on discovering issues in the distance functions, and
> comparing results with/without the index. Maybe the next step should be
> adding some changes to the data, which might trigger more issues like
> this one.
>
Just found one more ocurrance of this one with this index while an
autovacuum was running:
"""
CREATE INDEX bt_f8_heap_seqno_idx
ON public.bt_f8_heap
USING brin (seqno float8_minmax_multi_ops);
"""
Attached is a backtrace.
--
Jaime Casanova
Director de Servicios Profesionales
SystemGuards - Consultores de PostgreSQL
#0 __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:50
set = {__val = {4194304, 140737005547296, 2, 6, 6807829,
94364324073680, 4611686018427388799, 140153051314854, 0, 281470681751456, 0, 0,
0,
0, 0, 0}}
pid = <optimized out>
tid = <optimized out>
ret = <optimized out>
#1 0x00007f77ec9a4535 in __GI_abort () at abort.c:79
save_stage = 1
act = {__sigaction_handler = {sa_handler = 0x0, sa_sigaction = 0x0},
sa_mask = {__val = {0, 0, 0, 0, 0, 140153048813557, 2,
3631085705129160672, 7018350057190602853, 94364324073680,
7003715780713122240, 0, 12346699825684934912, 140737005547536,
94364359032568, 140737005548400}}, sa_flags = -402386736,
sa_restorer = 0x55d2ea197ef8}
sigs = {__val = {32, 0 <repeats 15 times>}}
#2 0x000055d2e870514a in ExceptionalCondition (conditionName=0x55d2e87843b0
"neranges >= 2", errorType=0x55d2e8783f14 "FailedAssertion",
fileName=0x55d2e8783f00 "brin_minmax_multi.c", lineNumber=1338) at
assert.c:69
No locals.
#3 0x000055d2e804966f in build_distances (distanceFn=0x55d2ea1b2c88,
colloid=0, eranges=0x55d2ea1bf7c0, neranges=1) at brin_minmax_multi.c:1338
i = 21970
ndistances = -367317728
distances = 0x55d2ea1b2c88
#4 0x000055d2e804c595 in brin_minmax_multi_union (fcinfo=0x7fffe338f4c0) at
brin_minmax_multi.c:2841
bdesc = 0x55d2ea1b2e88
col_a = 0x55d2ea196fb8
col_b = 0x55d2ea1bb7c8
colloid = 0
serialized_a = 0x55d2ea1b1dc0
serialized_b = 0x55d2ea1b1df8
ranges_a = 0x55d2ea198798
ranges_b = 0x55d2ea196d78
attno = 1
attr = 0x7f77e3693e88
eranges = 0x55d2ea1bf7c0
neranges = 1
cmpFn = 0x55d2ea1b2cc0
distanceFn = 0x55d2ea1b2c88
distances = 0x55d2e8785c27
ctx = 0x55d2ea1bf6a0
oldctx = 0x55d2ea196b30
#5 0x000055d2e87100e0 in FunctionCall3Coll (flinfo=0x55d2ea1adbb0,
collation=0, arg1=94364359143048, arg2=94364359028664, arg3=94364359178184)
at fmgr.c:1171
fcinfodata = {fcinfo = {flinfo = 0x55d2ea1adbb0, context = 0x0,
resultinfo = 0x0, fncollation = 0, isnull = false, nargs = 3,
args = 0x7fffe338f4e0},
fcinfo_data = "\260\333\032\352\322U", '\000' <repeats 23 times>,
"\177\003\000\210.\033\352\322U\000\000\000k\031\352\322U\000\000\270o\031\352\322U\000\000\000\266\033\352\v\022\000\000ȷ\033\352\322U\000\000\000\333\032\352\322U\000"}
fcinfo = 0x7fffe338f4c0
result = 16812436272
__func__ = "FunctionCall3Coll"
#6 0x000055d2e804451d in union_tuples (bdesc=0x55d2ea1b2e88, a=0x55d2ea196f90,
b=0x55d2ea1b1cd0) at brin.c:1643
unionFn = 0x55d2ea1adbb0
col_a = 0x55d2ea196fb8
col_b = 0x55d2ea1bb7c8
opcinfo = 0x55d2ea1b2c70
keyno = 0
db = 0x55d2ea1bb7a0
cxt = 0x55d2ea1bb680
oldcxt = 0x55d2ea196b30
#7 0x000055d2e8043fb2 in summarize_range (indexInfo=0x55d2ea1989b0,
state=0x55d2ea198ac8, heapRel=0x7f77e3692330, heapBlk=5760, heapNumBlks=7281)
at brin.c:1452
newtup = 0x55d2ea1b1cd0
newsize = 40
didupdate = false
samepage = false
phbuf = 14589
phtup = 0x55d2ea1b1cd0
phsz = 40
offset = 16
scanNumBlks = 128
__func__ = "summarize_range"
#8 0x000055d2e804415b in brinsummarize (index=0x7f77e3693b40,
heapRel=0x7f77e3692330, pageRange=4294967295, include_partial=false,
numSummarized=0x55d2ea197ba8, numExisting=0x55d2ea197ba8) at brin.c:1534
tup = 0x0
off = 15
revmap = 0x55d2ea1b1b78
state = 0x55d2ea198ac8
indexInfo = 0x55d2ea1989b0
heapNumBlocks = 7281
pagesPerRange = 128
buf = 14589
startBlk = 5760
#9 0x000055d2e8043118 in brinvacuumcleanup (info=0x7fffe338f760,
stats=0x55d2ea197ba0) at brin.c:957
heapRel = 0x7f77e3692330
#10 0x000055d2e80e1ab0 in index_vacuum_cleanup (info=0x7fffe338f760,
istat=0x55d2ea197ba0) at indexam.c:720
indexRelation = 0x7f77e3693b40
__func__ = "index_vacuum_cleanup"
#11 0x000055d2e82f7f4b in vac_cleanup_one_index (ivinfo=0x7fffe338f760,
istat=0x55d2ea197ba0) at vacuum.c:2343
__func__ = "vac_cleanup_one_index"
#12 0x000055d2e80dba95 in lazy_cleanup_one_index (indrel=0x7f77e3693b40,
istat=0x55d2ea197ba0, reltuples=1009947, estimated_count=true,
vacrel=0x55d2ea197028) at vacuumlazy.c:2774
ivinfo = {index = 0x7f77e3693b40, analyze_only = false, report_progress
= false, estimated_count = true, message_level = 13,
num_heap_tuples = 1009947, strategy = 0x55d2ea1a3018}
saved_err_info = {blkno = 4294967295, offnum = 0, phase =
VACUUM_ERRCB_PHASE_SCAN_HEAP}
#13 0x000055d2e80db870 in lazy_cleanup_all_indexes (vacrel=0x55d2ea197028) at
vacuumlazy.c:2672
indrel = 0x7f77e3693b40
istat = 0x55d2ea197ba0
idx = 0
reltuples = 1009947
estimated_count = true
#14 0x000055d2e80d91e8 in lazy_scan_heap (vacrel=0x55d2ea197028) at
vacuumlazy.c:1278
rel_pages = 7270
blkno = 7270
next_unskippable_block = 7270
next_failsafe_block = 0
next_fsm_block_to_vacuum = 0
dead_items = 0x7f77e2a53050
vmbuffer = 11641
next_unskippable_allvis = true
skipping_current_range = false
initprog_index = {0, 1, 5}
initprog_val = {1, 7270, 2115570}
__func__ = "lazy_scan_heap"
#15 0x000055d2e80d7a95 in heap_vacuum_rel (rel=0x7f77e3692330,
params=0x55d2ea1a1f1c, bstrategy=0x55d2ea1a3018) at vacuumlazy.c:534
vacrel = 0x55d2ea197028
verbose = false
instrument = true
aggressive = false
skipwithvm = true
frozenxid_updated = false
minmulti_updated = false
OldestXmin = 126264
FreezeLimit = 4245093560
OldestMxact = 401
MultiXactCutoff = 4289967697
orig_rel_pages = 7270
new_rel_pages = 3812162160
new_rel_allvisible = 3897824358
ru0 = {tv = {tv_sec = 1664404096, tv_usec = 799267}, ru = {ru_utime =
{tv_sec = 0, tv_usec = 2353}, ru_stime = {tv_sec = 0,
tv_usec = 4707}, {ru_maxrss = 11896, __ru_maxrss_word = 11896},
{ru_ixrss = 0, __ru_ixrss_word = 0}, {ru_idrss = 0,
__ru_idrss_word = 0}, {ru_isrss = 0, __ru_isrss_word = 0},
{ru_minflt = 508, __ru_minflt_word = 508}, {ru_majflt = 0,
__ru_majflt_word = 0}, {ru_nswap = 0, __ru_nswap_word = 0},
{ru_inblock = 0, __ru_inblock_word = 0}, {ru_oublock = 0,
__ru_oublock_word = 0}, {ru_msgsnd = 0, __ru_msgsnd_word = 0},
{ru_msgrcv = 0, __ru_msgrcv_word = 0}, {ru_nsignals = 0,
__ru_nsignals_word = 0}, {ru_nvcsw = 0, __ru_nvcsw_word = 0},
{ru_nivcsw = 8, __ru_nivcsw_word = 8}}}
starttime = 717719296799269
startreadtime = 0
startwritetime = 0
startwalusage = {wal_records = 2, wal_fpi = 0, wal_bytes = 286}
StartPageHit = 10
StartPageMiss = 0
StartPageDirty = 0
errcallback = {previous = 0x0, callback = 0x55d2e80dc955
<vacuum_error_callback>, arg = 0x55d2ea197028}
indnames = 0x55d2ea197bf8
__func__ = "heap_vacuum_rel"
#16 0x000055d2e82f48dc in table_relation_vacuum (rel=0x7f77e3692330,
params=0x55d2ea1a1f1c, bstrategy=0x55d2ea1a3018)
at ../../../src/include/access/tableam.h:1680
No locals.
#17 0x000055d2e82f799f in vacuum_rel (relid=130030, relation=0x55d2ea1a8fb0,
params=0x55d2ea1a1f1c) at vacuum.c:2086
lmode = 4
rel = 0x7f77e3692330
lockrelid = {relId = 130030, dbId = 129438}
toast_relid = 0
save_userid = 10
save_sec_context = 0
save_nestlevel = 2
__func__ = "vacuum_rel"
#18 0x000055d2e82f56b0 in vacuum (relations=0x55d2ea1ab018,
params=0x55d2ea1a1f1c, bstrategy=0x55d2ea1a3018, isTopLevel=true) at
vacuum.c:475
vrel = 0x55d2ea1a9008
cur__state = {l = 0x55d2ea1ab018, i = 0}
cur = 0x55d2ea1ab030
_save_exception_stack = 0x7fffe338fd60
_save_context_stack = 0x0
_local_sigjmp_buf = {{__jmpbuf = {0, -4624763917282687273,
94364324073680, 140737005554112, 0, 0, -4624763917198801193,
-1473908981240543529}, __mask_was_saved = 0, __saved_mask =
{__val = {64, 56, 12884901920, 140737005550720, 94364331381944, 64,
94364359102096, 32, 16812510864, 94364359102504, 64,
94364359102096, 32, 94364359102096, 7784, 93460373792104}}}}
_do_rethrow = false
in_vacuum = true
stmttype = 0x55d2e888c0df "VACUUM"
in_outer_xact = false
use_own_xacts = true
__func__ = "vacuum"
#19 0x000055d2e8490983 in autovacuum_do_vac_analyze (tab=0x55d2ea1a1f18,
bstrategy=0x55d2ea1a3018) at autovacuum.c:3149
rangevar = 0x55d2ea1a8fb0
rel = 0x55d2ea1a9008
rel_list = 0x55d2ea1a9040
#20 0x000055d2e848f812 in do_autovacuum () at autovacuum.c:2472
_save_exception_stack = 0x7fffe33900b0
_save_context_stack = 0x0
_local_sigjmp_buf = {{__jmpbuf = {0, -4624763903416318249,
94364324073680, 140737005554112, 0, 0, -4624763917276395817,
-1473909250818423081}, __mask_was_saved = 0, __saved_mask =
{__val = {94364333376464, 988, 94364358181060, 140737005551208,
94364358264416, 94364358181068, 94364358181060, 94364358182047,
0, 139637976727552, 94364331565121, 140737005551168,
94364331613613, 140737005551264, 94364333376464, 988}}}}
_do_rethrow = false
tab = 0x55d2ea1a1f18
skipit = false
stdVacuumCostDelay = 0
stdVacuumCostLimit = 200
iter = {cur = 0x7f77ec467da0, end = 0x7f77ec467da0}
relid = 130030
classTup = 0x7f77e3691dc8
isshared = false
cell__state = {l = 0x55d2ea154f80, i = 0}
classRel = 0x7f77e3680698
tuple = 0x0
relScan = 0x55d2ea1549b8
dbForm = 0x7f77e368a838
table_oids = 0x55d2ea154f80
orphan_oids = 0x0
ctl = {num_partitions = 94364333376676, ssize = 960051505, dsize = 0,
max_dsize = 94364331379135, keysize = 4, entrysize = 96,
hash = 0x7fffe338ff40, match = 0x55d2e8739b38 <AllocSetFree+563>,
keycopy = 0x55d2ea0c80a0, alloc = 0x55d2ea0c7f80, hcxt = 0x70000002c,
hctl = 0x55d2ea0c80a0}
table_toast_map = 0x55d2ea198c60
cell = 0x55d2ea154dd0
bstrategy = 0x55d2ea1a3018
key = {sk_flags = 0, sk_attno = 17, sk_strategy = 3, sk_subtype = 0,
sk_collation = 950, sk_func = {fn_addr = 0x55d2e85b2600 <chareq>,
fn_oid = 61, fn_nargs = 2, fn_strict = true, fn_retset = false,
fn_stats = 2 '\002', fn_extra = 0x0, fn_mcxt = 0x55d2ea153880,
fn_expr = 0x0}, sk_argument = 116}
pg_class_desc = 0x55d2ea1539a0
effective_multixact_freeze_max_age = 400000000
did_vacuum = false
found_concurrent_worker = false
i = 21970
__func__ = "do_autovacuum"
#21 0x000055d2e848e576 in AutoVacWorkerMain (argc=0, argv=0x0) at
autovacuum.c:1715
dbname = "regression", '\000' <repeats 53 times>
local_sigjmp_buf = {{__jmpbuf = {0, -4624763903439386921,
94364324073680, 140737005554112, 0, 0, -4624763903418415401,
-1473909251212949801}, __mask_was_saved = 1, __saved_mask =
{__val = {18446744066192964099, 0, 0, 0, 0, 0, 0, 0, 94364327554518, 0,
38333309328, 140737005552000, 94364328627294, 0, 3973570960,
140737005552000}}}}
dbid = 129438
__func__ = "AutoVacWorkerMain"
#22 0x000055d2e848e126 in StartAutoVacWorker () at autovacuum.c:1493
worker_pid = 0
__func__ = "StartAutoVacWorker"
#23 0x000055d2e849c06e in StartAutovacuumWorker () at postmaster.c:5534
bn = 0x55d2ea0ebfd0
__func__ = "StartAutovacuumWorker"
#24 0x000055d2e849bb89 in sigusr1_handler (postgres_signal_arg=10) at
postmaster.c:5239
save_errno = 4
__func__ = "sigusr1_handler"
#25 <signal handler called>
No locals.
#26 0x00007f77eca72a27 in __GI___select (nfds=9, readfds=0x7fffe3390670,
writefds=0x0, exceptfds=0x0, timeout=0x7fffe33906f0)
at ../sysdeps/unix/sysv/linux/select.c:41
resultvar = 18446744073709551612
sc_ret = <optimized out>
#27 0x000055d2e849754e in ServerLoop () at postmaster.c:1770
timeout = {tv_sec = 59, tv_usec = 587395}
rmask = {fds_bits = {448, 0 <repeats 15 times>}}
selres = -1
now = 1664404096
readmask = {fds_bits = {448, 0 <repeats 15 times>}}
nSockets = 9
last_lockfile_recheck_time = 1664404093
last_touch_time = 1664402232
__func__ = "ServerLoop"
#28 0x000055d2e8496eed in PostmasterMain (argc=3, argv=0x55d2ea0c5ed0) at
postmaster.c:1478
opt = -1
status = 0
userDoption = 0x55d2ea0e98c0 "data"
listen_addr_saved = true
i = 64
output_config_variable = 0x0
__func__ = "PostmasterMain"
#29 0x000055d2e83962e5 in main (argc=3, argv=0x55d2ea0c5ed0) at main.c:202
do_check_root = true
quit
