Re: performance of bitmap scans in nested loop joins

On Wed, 4 May 2005, Tom Lane wrote:

I figured out part of the problem: I had made nodeBitmapIndexscan
re-open the index on each call, thinking that that would save amrescan
calls. But an amrescan is a whole lot cheaper than index open/close,
so that was a bad tradeoff.

This seems to account for about half of the slowdown you exhibited.
I'm not sure where the other half went ... gprof isn't turning up
any obvious candidates.

Great!!!
Thanks.

Now I have done again the profiling. Really, now the bitmap index scan is
faster and take 90 seconds instead of 120 seconds. But it still more than the
sum of two simple index scans (26+38 secs).

I also tried to help you, Tom, to find the exact location of the remaining
problem. For that purpose I did the profiling of those queries:

test=# explain analyze select * from q3c,q3c as q3cs where
q3c.ipix>=q3cs.ipix-3 AND q3c.ipix<=q3cs.ipix+3;

test=# EXPLAIN ANALYZE SELECT * FROM q3c,q3c as q3cs WHERE
(q3c.ipix>=q3cs.ipix-1000 AND q3c.ipix<=q3cs.ipix-993);

test=# explain analyze select * from q3c,q3c as q3cs where
(q3c.ipix>=q3cs.ipix-3 AND q3c.ipix<=q3cs.ipix+3) OR
(q3c.ipix>=q3cs.ipix-1000 AND q3c.ipix<=q3cs.ipix-993);

And I coadded the "flat profiles" of first two (index scan) queries and
compared it with the flat profile of bitmap scan:
self seconds | self seconds
Function of TWO index scans | of bitmap scan
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
LWLockAcquire 51.29 46.29
LWLockRelease 40.29 38.65
_bt_compare 38.35 36.20
hash_seq_search 0.00 30.08
hash_search 26.90 29.32
AllocSetAlloc 10.73 27.23
btint8cmp 30.95 24.05
PinBuffer 23.25 22.56
hash_any 18.58 20.18
_bt_binsrch 19.73 19.09
UnpinBuffer 18.27 17.44
_bt_first 13.92 16.20
FunctionCall2 18.23 14.62
_bt_preprocess_keys 12.01 13.67
_bt_moveright 13.42 11.87
InstrStopNode 7.62 11.24
seg_alloc 0.00 11.13
ReadBuffer 11.42 10.68
InstrEndLoop 4.11 10.38
ExecProcNode 14.60 10.17
fmgr_info_cxt_security 13.87 9.96
_bt_search 10.41 9.80
AllocSetReset 9.70 9.47
AllocSetFree 4.00 7.75
_bt_getroot 7.54 7.35
LockBuffer 9.32 7.07
MemoryContextAlloc 3.22 6.93
ExecMakeFunctionResultNoSets 5.95 6.85
element_alloc 0.12 6.73
_bt_checkkeys 8.68 6.07
slot_deform_tuple 7.71 5.77
ExecReScan 2.89 5.67
MemoryContextAllocZero 0.00 5.43
ReleaseAndReadBuffer 6.20 5.00
ExecEvalVar 4.02 4.80
ReleaseBuffer 5.39 4.28
ExecScan 4.39 4.11
ExecutorRun 1.64 4.08
slot_getattr 4.80 4.00
_bt_relandgetbuf 4.31 3.70
MemoryContextCreate 0.00 3.54

The strongest difference is in hash_seq_search (30 seconds) and
AllocSetAlloc -- 17 seconds. (which contribute a significant part into
slowness of bitmap scan) (I remind that in my case bitmap scan is slower
than 2 index scans by ~ 20-30seconds (34 seconds when postgres was compiled
with profiling support, 25 seconds when postgres was compiled without
profiling support)).

Since I don't know exactly the normal sequence of function calls in postgres,
I cannot judge whether those functions are true reason of the problem or not,
but probably that information can help.

In any case, again I have put all the full profiling results on the web

http://lnfm1.sai.msu.ru/~math/public_misc/idxscan1.gprof
profiling of
test=# EXPLAIN ANALYZE SELECT * FROM q3c,q3c as q3cs WHERE
(q3c.ipix>=q3cs.ipix-1000 AND q3c.ipix<=q3cs.ipix-993);

http://lnfm1.sai.msu.ru/~math/public_misc/_idxscan1.gprof
profiling of
test=# explain analyze select * from q3c,q3c as q3cs where
q3c.ipix>=q3cs.ipix-3 AND q3c.ipix<=q3cs.ipix+3;

http://lnfm1.sai.msu.ru/~math/public_misc/bitmap1.gprof
profiling of
test=# explain analyze select * from q3c,q3c as q3cs where
(q3c.ipix>=q3cs.ipix-3 AND q3c.ipix<=q3cs.ipix+3) OR
(q3c.ipix>=q3cs.ipix-1000 AND q3c.ipix<=q3cs.ipix-993);

Here, this is just the new output of explain analyze (for the postgres
compiled without profiling support)

test=# explain analyze select * from q3c,q3c as q3cs where (q3c.ipix>=q3cs.ipix-3 AND q3c.ipix<=q3cs.ipix+3) OR (q3c.ipix>=q3cs.ipix-1000 AND q3c.ipix<=q3cs.ipix-993);
QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=5832.03..190281569757.46 rows=1888909037091 width=96) (actual time=0.173..88500.469 rows=3000000 loops=1)
-> Seq Scan on q3c q3cs (cost=0.00..60928.16 rows=3000016 width=48) (actual time=0.072..3750.724 rows=3000000 loops=1)
-> Bitmap Heap Scan on q3c (cost=5832.03..43426.73 rows=666670 width=48) (actual time=0.021..0.022 rows=1 loops=3000000)
Recheck Cond: (((q3c.ipix >= ("outer".ipix - 3)) AND (q3c.ipix <= ("outer".ipix + 3))) OR ((q3c.ipix >= ("outer".ipix - 1000)) AND (q3c.ipix <= ("outer".ipix - 993))))
-> BitmapOr (cost=5832.03..5832.03 rows=666670 width=0) (actual time=0.017..0.017 rows=0 loops=3000000)
-> Bitmap Index Scan on ipix_idx (cost=0.00..2916.02 rows=333335 width=0) (actual time=0.008..0.008 rows=1 loops=3000000)
Index Cond: ((q3c.ipix >= ("outer".ipix - 3)) AND (q3c.ipix <= ("outer".ipix + 3)))
-> Bitmap Index Scan on ipix_idx (cost=0.00..2916.02 rows=333335 width=0) (actual time=0.006..0.006 rows=0 loops=3000000)
Index Cond: ((q3c.ipix >= ("outer".ipix - 1000)) AND (q3c.ipix <= ("outer".ipix - 993)))
Total runtime: 90241.180 ms

test=# EXPLAIN ANALYZE SELECT * FROM q3c,q3c as q3cs WHERE
test-# (q3c.ipix>=q3cs.ipix-1000 AND q3c.ipix<=q3cs.ipix-993);
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.01..49059519577.21 rows=1000010666695 width=96) (actual time=26391.542..26391.542 rows=0 loops=1)
-> Seq Scan on q3c q3cs (cost=0.00..60928.16 rows=3000016 width=48) (actual time=0.059..3393.616 rows=3000000 loops=1)
-> Index Scan using ipix_idx on q3c (cost=0.01..9686.37 rows=333335 width=48) (actual time=0.006..0.006 rows=0 loops=3000000)
Index Cond: ((q3c.ipix >= ("outer".ipix - 1000)) AND (q3c.ipix <= ("outer".ipix - 993)))
Total runtime: 26391.623 ms
(5 rows)

test=# explain analyze select * from q3c,q3c as q3cs where q3c.ipix>=q3cs.ipix-3 AND q3c.ipix<=q3cs.ipix+3;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------
Nested Loop (cost=0.01..49059519577.21 rows=1000010666695 width=96) (actual time=0.108..37355.388 rows=3000000 loops=1)
-> Seq Scan on q3c q3cs (cost=0.00..60928.16 rows=3000016 width=48) (actual time=0.039..3403.276 rows=3000000 loops=1)
-> Index Scan using ipix_idx on q3c (cost=0.01..9686.37 rows=333335 width=48) (actual time=0.007..0.008 rows=1 loops=3000000)
Index Cond: ((q3c.ipix >= ("outer".ipix - 3)) AND (q3c.ipix <= ("outer".ipix + 3)))
Total runtime: 38588.672 ms
(5 rows)

With best regards,

Sergey Koposov

"Sergey E. Koposov" <math@sai.msu.ru> writes:

And I coadded the "flat profiles" of first two (index scan) queries and
compared it with the flat profile of bitmap scan:

Thanks, I had been thinking of doing that same calculation but hadn't
got round to it yet. It looks like the bitmap case is actually a little
ahead on buffer access (as you'd expect) and btree work (which is
surprising because it ought to be dead even; are these numbers very
repeatable?). Where we are losing is mostly on the actual manipulation
of the bitmaps (particularly hash_seq_search which is done in
tbm_begin_iterate; and it looks like memory allocation for the bitmap
hashtables is nontrivial too). I had already had a TODO item to look
into speeding up hash_seq_search ... will see what I can find.

regards, tom lane

On Thu, 5 May 2005, Tom Lane wrote:

"Sergey E. Koposov" <math@sai.msu.ru> writes:

And I coadded the "flat profiles" of first two (index scan) queries and
compared it with the flat profile of bitmap scan:

Thanks, I had been thinking of doing that same calculation but hadn't
got round to it yet. It looks like the bitmap case is actually a little
ahead on buffer access (as you'd expect) and btree work (which is
surprising because it ought to be dead even; are these numbers very
repeatable?). Where we are losing is mostly on the actual manipulation

Yes, all those timings are rather stable and have been obtained on the very
unloaded system (and in fully cached regime).

With Best regards,
Sergey Koposov

I wrote:

... Where we are losing is mostly on the actual manipulation
of the bitmaps (particularly hash_seq_search which is done in
tbm_begin_iterate; and it looks like memory allocation for the bitmap
hashtables is nontrivial too). I had already had a TODO item to look
into speeding up hash_seq_search ... will see what I can find.

I got around to looking at this some more. It seems that the basic
problem is that dynahash.c isn't optimized for very small hashtables.
The test case I'm looking at (which may be an oversimplification of
Sergey's problem) never has more than one entry in the hashtables it
creates for in-memory bitmaps, and so the hashtable overhead is pretty
significant. Particularly the overhead of creating and deleting 'em.

The other uses of dynahash.c that are at all performance-critical seem
to deal with hashtables that are (a) fairly large and (b) long-lived.
So I'm thinking that hacking dynahash.c itself to improve this situation
would probably be counterproductive overall.

An idea that comes to mind is to allow tidbitmap.c to handle the cases
of zero or one page entry directly, storing the page entry in a simple
field of the TIDBitmap struct. Only when the bitmap needs entries for
more than one heap page will we create a subsidiary hash table. (Note
that we could store bits for more than one tuple, if they happen to be
on the same heap page.)

This would uglify the logic in tidbitmap.c a bit, but it doesn't seem
completely preposterous. The main objection I can see is that it would
only optimize the zero-or-one-page cases, which might be insufficient.

Anyone have a better idea for speeding up operations on small bitmaps?

regards, tom lane