Are bitmap index scans slow to start? - Mailing list pgsql-performance

(Sorry moderators for any double posts, I keep making subscription errors.
Hopefully this one gets through)

Hi speed freaks,

Can anyone tell me why the bitmap heap scan takes so long to start for this
query? (SQL and EXPLAIN ANALYZE follows).

The big culprit in this appears to be:
->  Bitmap Index Scan on log_2013_01_session_idx  (cost=0.00..63186.52
rows=2947664 width=0) (actual time=32611.918..32611.918 rows=2772042
loops=1)"
Index Cond: (session_id = 27)"

I can't see anything that occurs between actual time 0.0..32611.918 that
this could be waiting on. Is it building the bitmap?

Running the query a second time yields this:

->  Bitmap Index Scan on log_2013_01_session_idx  (cost=0.00..63186.52
rows=2947664 width=0) (actual time=2896.601..2896.601 rows=2772042 loops=1)"
Index Cond: (session_id = 27)"

Does the bitmap then get cached? These queries are built dynamically and
called rarely, so their first-time performance is important. I'd prefer a
strategy that allowed fast performance the first time, rather than slow the
first time and extremely fast subsequently.

Thanks,

Carlo

SELECT
   l.session_id,
   l.log_id,
   s.session_type_code,
   coalesce(st.name, '?' || s.session_type_code || '?') AS
session_type_name,
   l.input_resource_id,
   ir.impt_schema AS input_resource_table_schema,
   ir.impt_table  AS input_resource_table_name,
   ir.resource AS input_resource_name,
   l.input_resource_pkey_id,
   tar_table.table_schema,
   tar_table.table_name,
   l.target_pkey_id AS table_pkey_id,
   tar_op.name AS operation,
   tar_note.name AS note
FROM mdx_audit.log_2013_01 AS l
JOIN mdx_audit.session AS s USING (session_id) JOIN mdx_audit.target_table
AS tar_table USING (target_table_id) JOIN mdx_audit.target_operation_type AS
tar_op USING (target_operation_type_code) LEFT OUTER JOIN
mdx_audit.target_note AS tar_note USING (target_note_id) LEFT OUTER JOIN
mdx_audit.session_type AS st USING (session_type_code) LEFT OUTER JOIN
mdx_core.input_resource AS ir USING (input_resource_id) WHERE
   l.session_id = 27
   AND
   (
      input_resource_pkey_id IS NULL
      OR input_resource_pkey_id IN (
         494568472,
         494568473,
         494568474,
         494568475,
         494568476,
         494568477,
         494568478,
         494568479,
         494568480,
         494568481,
         494568482,
         494568483,
         494568484,
         494568485,
         494568486,
         494568487,
         494568488,
         494568489,
         494568490
      )
   )

"Hash Left Join  (cost=63191.88..853169.29 rows=92 width=2199) (actual
time=34185.045..44528.710 rows=603 loops=1)"
"  Hash Cond: (l.input_resource_id = ir.input_resource_id)"
"  ->  Hash Left Join  (cost=63190.22..853165.68 rows=92 width=1377) (actual
time=34184.963..44528.391 rows=603 loops=1)"
"        Hash Cond: (l.target_note_id = tar_note.target_note_id)"
"        ->  Hash Join  (cost=63189.07..853164.06 rows=92 width=1161)
(actual time=34184.872..44528.167 rows=603 loops=1)"
"              Hash Cond: (l.target_operation_type_code =
tar_op.target_operation_type_code)"
"              ->  Nested Loop  (cost=63188.00..853161.72 rows=92
width=1125) (actual time=34184.809..44527.884 rows=603 loops=1)"
"                    ->  Nested Loop Left Join  (cost=0.00..9.34 rows=1
width=65) (actual time=12.057..12.068 rows=1 loops=1)"
"                          Join Filter: (s.session_type_code =
st.session_type_code)"
"                          ->  Index Scan using session_pkey on session s
(cost=0.00..8.27 rows=1 width=7) (actual time=6.847..6.850 rows=1 loops=1)"
"                                Index Cond: (session_id = 27)"
"                          ->  Seq Scan on session_type st  (cost=0.00..1.03
rows=3 width=70) (actual time=5.204..5.207 rows=3 loops=1)"
"                    ->  Hash Join  (cost=63188.00..853151.47 rows=92
width=1064) (actual time=34172.746..44515.696 rows=603 loops=1)"
"                          Hash Cond: (l.target_table_id =
tar_table.target_table_id)"
"                          ->  Bitmap Heap Scan on log_2013_01 l
(cost=63186.57..853148.39 rows=194 width=34) (actual
time=34172.631..44515.318 rows=603 loops=1)"
"                                Recheck Cond: (session_id = 27)"
"                                Filter: ((input_resource_pkey_id IS NULL)
OR (input_resource_pkey_id = ANY
('{494568472,494568473,494568474,494568475,494568476,494568477,494568478,494
568479,494568480,494568481,494568482,494568483,494568484,494568485,494568486
,494568487,494568488,494568489,494568490}'::bigint[])))"
"                                ->  Bitmap Index Scan on
log_2013_01_session_idx  (cost=0.00..63186.52 rows=2947664 width=0) (actual
time=32611.918..32611.918 rows=2772042 loops=1)"
"                                      Index Cond: (session_id = 27)"
"                          ->  Hash  (cost=1.19..1.19 rows=19 width=1034)
(actual time=0.059..0.059 rows=44 loops=1)"
"                                Buckets: 1024  Batches: 1  Memory Usage:
4kB"
"                                ->  Seq Scan on target_table tar_table
(cost=0.00..1.19 rows=19 width=1034) (actual time=0.023..0.037 rows=44
loops=1)"
"              ->  Hash  (cost=1.03..1.03 rows=3 width=46) (actual
time=0.029..0.029 rows=3 loops=1)"
"                    Buckets: 1024  Batches: 1  Memory Usage: 1kB"
"                    ->  Seq Scan on target_operation_type tar_op
(cost=0.00..1.03 rows=3 width=46) (actual time=0.024..0.025 rows=3 loops=1)"
"        ->  Hash  (cost=1.07..1.07 rows=7 width=220) (actual
time=0.060..0.060 rows=59 loops=1)"
"              Buckets: 1024  Batches: 1  Memory Usage: 4kB"
"              ->  Seq Scan on target_note tar_note  (cost=0.00..1.07 rows=7
width=220) (actual time=0.021..0.025 rows=59 loops=1)"
"  ->  Hash  (cost=1.29..1.29 rows=29 width=826) (actual time=0.035..0.035
rows=33 loops=1)"
"        Buckets: 1024  Batches: 1  Memory Usage: 4kB"
"        ->  Seq Scan on input_resource ir  (cost=0.00..1.29 rows=29
width=826) (actual time=0.015..0.025 rows=33 loops=1)"
"Total runtime: 44529.075 ms"