BUG #8410: out of binary heap slots

The following bug has been logged on the website:

Bug reference: 8410
Logged by: Terje Elde
Email address: terje(at)elde(dot)net
PostgreSQL version: Unsupported/Unknown
Operating system: FreeBSD
Description:

Running:

PostgreSQL 9.3beta1 on amd64-portbld-freebsd9.1, compiled by cc (GCC) 4.2.1
20070831 patched [FreeBSD], 64-bit

I'm getting "out of binary heap slots", which offcourse spoils the fun of
the query.

I'm having trouble reproducing it, as I'm only seeing the issue in about 1
in 20 000 queries.

I can get the error, turn right around and run the same again manually, and
it'll run just fine.

I'd love to see if I can reproduce in on 9.3rc1, but seeing it is rare
enough as it is.

Slightly anonymised from the logs:

ERROR: out of binary heap slots
CONTEXT: PL/pgSQL function foo(integer,bigint,character[],timestamp without
time zone,integer,timestamp without time zone,integer,timestamp without time
zone,integer,inet,character varying) line 233 at FETCH
STATEMENT: SELECT a, b, c, d, e, f, g, h, i, j, k, l, m, n, o
FROM foo( 100, 2221::bigint, ARRAY['m', 'f', '', ' ', NULL]::char[],
'2013-07-05T19:11:41.958154'::timestamp, 30::int, NULL::timestamp, 10::int,
'2013-08-30T19:11:41.958168'::timestamp::timestamp, 100::int,
'123.123.123.123'::inet, 'FOO/1.1 CFNetwork/609.1.4 Darwin/13.0.0'::varchar
)

The FETCH-line is running off of a cursor, with a query going pretty much
like this:

OPEN curs FOR SELECT * FROM (
SELECT
'n'::char AS noo, p.id, p.pub, p.details, i.hash AS foo,
p.bam, p.goo,
e.name AS bar, p.meh, p.startt, p.endt, p.v, ps.s_likes AS
likes,
p.last_change, ARRAY( SELECT tag FROM foo_tag WHERE barzz =
p.id ) AS tags
FROM
p, ps, i, e, s
WHERE
s.tihi = i_cid AND
s.v = True AND
p.pub = s.id AND
p.id = ps.id AND
i.id = p.foo AND
e.id = p.bar AND
i.baz IS NOT NULL AND
p.bam = ANY( i_bam ) AND
endt > NOW() AND
startt < NOW() + INTERVAL '15 minutes' AND
p.startt > i_newerthan
ORDER BY p.startt DESC LIMIT i_maxnew
FOR UPDATE OF ps ) AS newer_than
UNION SELECT * FROM (
SELECT
'u'::char AS noo, p.id, p.pub, p.details, i.hash AS foo,
p.bam, p.goo,
e.name AS bar, p.meh, p.startt, p.endt, p.v, ps.s_likes AS
likes,
p.last_change, ARRAY( SELECT tag FROM foo_tag WHERE bazz =
p.id ) AS tags
FROM
p, ps, i, e, s
WHERE
s.tihi = i_cid AND
s.v = True AND
p.pub = s.id AND
p.id = ps.id AND
i.id = p.foo AND
e.id = p.bar AND
i.baz IS NOT NULL AND
p.bam = ANY( i_bam ) AND
endt > NOW() AND
startt < NOW() + INTERVAL '15 minutes' AND
startt > i_oldest AND
p.last_change > i_newerthan
ORDER BY p.last_change DESC LIMIT i_maxupdates
FOR UPDATE OF ps ) AS updated;

Yeah, I know. Mangled/obfuscated bits in bug-reports are no fun, but the
code isn't mine to put in a public list.

If you'd like to take a look, I can't imagine it'd be much of a problem for
me to mail you the proper query (and whole function) off-list.

This is not a crisis for us, and I've been meaning to clean up or rewrite
the query anyway, but I figured I should fire off an email anyway, just in
case there's a bug in PostgreSQL that hasn't been caught since beta1.

(again, sorry about the old version).

Explain analyze gives this plan (again anonymized a bit, but can send proper
off-list):

QUERY PLAN


-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
HashAggregate (cost=423.84..424.15 rows=31 width=223) (actual
time=0.668..0.675 rows=30 loops=1)
-> Append (cost=35.50..422.67 rows=31 width=223) (actual
time=0.123..0.608 rows=30 loops=1)
-> Subquery Scan on apples (cost=35.50..412.18 rows=30 width=223)
(actual time=0.123..0.600 rows=30 loops=1)
-> Limit (cost=35.50..411.88 rows=30 width=217) (actual
time=0.122..0.591 rows=30 loops=1)
-> LockRows (cost=35.50..2494.50 rows=196 width=217)
(actual time=0.121..0.584 rows=30 loops=1)
-> Nested Loop (cost=35.50..2492.54 rows=196
width=217) (actual time=0.113..0.544 rows=30 loops=1)
-> Nested Loop (cost=35.23..410.51
rows=196 width=207) (actual time=0.085..0.343 rows=30 loops=1)
-> Nested Loop (cost=34.95..319.23
rows=202 width=164) (actual time=0.078..0.264 rows=32 loops=1)
-> Nested Loop
(cost=34.81..263.23 rows=211 width=147) (actual time=0.073..0.203 rows=32
loops=1)
-> Merge Append
(cost=34.66..172.40 rows=354 width=141) (actual time=0.067..0.126 rows=32
loops=1)
Sort Key: p.startt
-> Sort
(cost=0.01..0.02 rows=1 width=669) (actual time=0.016..0.016 rows=0
loops=1)
Sort Key:
p.startt
Sort Method:
quicksort Memory: 25kB
-> Seq Scan
on cars p (cost=0.00..0.00 rows=1 width=669) (actual time=0.001..0.001
rows=0 loops=1)
Filter:
((startt > '2013-07-05 19:11:41.958154'::timestamp without time zone) AND
(endt > now()) AND (bus = ANY ('{m,f," "," ",NULL}'::character(1)[])) AND
(startt < (now() + '00:15:00'::interval)))
-> Index Scan
Backward using cars_startt on cars_2013 p_1 (cost=0.28..129.49 rows=351
width=136) (actual time=0.043..0.096 rows=32 loops=1)
Index Cond:
((startt < (now() + '00:15:00'::interval)) AND (startt > '2013-07-05
19:11:41.958154'::timestamp without time zone))
Filter:
((endt > now()) AND (bus = ANY ('{m,f," "," ",NULL}'::character(1)[])))
-> Sort
(cost=13.45..13.45 rows=1 width=669) (actual time=0.004..0.004 rows=0
loops=1)
Sort Key:
p_2.startt
Sort Method:
quicksort Memory: 25kB
-> Seq Scan
on cars_2014 p_2 (cost=0.00..13.44 rows=1 width=669) (actual
time=0.000..0.000 rows=0 loops=1)
Filter:
((startt > '2013-07-05 19:11:41.958154'::timestamp without time zone) AND
(endt > now()) AND (bus = ANY ('{m,f," "," ",NULL}'::character(1)[])) AND
(startt < (now() + '00:15:00'::interval)))
-> Sort
(cost=13.45..13.45 rows=1 width=669) (actual time=0.004..0.004 rows=0
loops=1)
Sort Key:
p_3.startt
Sort Method:
quicksort Memory: 25kB
-> Seq Scan
on cars_2015 p_3 (cost=0.00..13.44 rows=1 width=669) (actual
time=0.000..0.000 rows=0 loops=1)
Filter:
((startt > '2013-07-05 19:11:41.958154'::timestamp without time zone) AND
(endt > now()) AND (bus = ANY ('{m,f," "," ",NULL}'::character(1)[])) AND
(startt < (now() + '00:15:00'::interval)))
-> Index Scan using
oranges_pkey on oranges s (cost=0.14..0.25 rows=1 width=10) (actual
time=0.002..0.002 rows=1 loops=32)
Index Cond: (id =
p.agent)
Filter: (visible
AND (carpool = 100))
-> Index Scan using
roadworkers_pkey on roadworkers e (cost=0.14..0.26 rows=1 width=25) (actual
time=0.001..0.001 rows=1 loops=32)
Index Cond: (id =
p.employee)
-> Index Scan using bikes_pkey on
bikes i (cost=0.28..0.44 rows=1 width=55) (actual time=0.002..0.002 rows=1
loops=32)
Index Cond: (id = p.bike)
Filter: (source IS NOT NULL)
Rows Removed by Filter: 0
-> Index Scan using cars_stats_pkey on
cars_stats ps (cost=0.28..0.48 rows=1 width=18) (actual time=0.003..0.003
rows=1 loops=30)
Index Cond: (id = p.id)
SubPlan 2
-> Index Only Scan using fruit_tags_pkey
on fruit_tags fruit_tags_1 (cost=0.28..10.14 rows=3 width=4) (actual
time=0.001..0.002 rows=2 loops=30)
Index Cond: (fruit = p.id)
Heap Fetches: 60
-> Subquery Scan on updated (cost=10.16..10.18 rows=1 width=221)
(actual time=0.005..0.005 rows=0 loops=1)
-> Limit (cost=10.16..10.17 rows=1 width=0) (actual
time=0.005..0.005 rows=0 loops=1)
-> LockRows (cost=10.16..10.17 rows=1 width=0)
(actual time=0.005..0.005 rows=0 loops=1)
-> Sort (cost=10.16..10.16 rows=1 width=0)
(actual time=0.005..0.005 rows=0 loops=1)
Sort Key: last_change
Sort Method: quicksort Memory: 25kB
-> Result (cost=0.00..10.15 rows=1
width=0) (actual time=0.000..0.000 rows=0 loops=1)
One-Time Filter: false
SubPlan 1
-> Index Only Scan using
fruit_tags_pkey on fruit_tags (cost=0.28..10.14 rows=3 width=4) (never
executed)
Index Cond: (fruit = id)
Heap Fetches: 0
Total runtime: 0.885 ms
(57 rows)

Terje