"Dynamic" WHERE clauses that aren't

What does the optimizer do with "dynamic" WHERE clauses? What I'm talking about is when you have a SELECT statement that has a "simple" WHERE clause like this:

WHERE column1 = NVL(:B1, column1) 
  AND column2 = NVL(:B2, column2)

The intention of this WHERE clause is to allow 4 different scenarios to be covered.
1) If :B1 is null and :B2 is null, then retrieve all rows.
2) If :B1 is null and :B2 is not null, then retrieve only rows where column2 = :B2.
3) If :B2 is null and :B1 is not null, then retrieve only rows where column1 = :B1.
4) If :B1 is not null and :B2 is not null, then retrieve only rows where column1 = :B1 and column2 = :B2.

The logic is that since the two conditions are AND'ed, that both have to evaluate to true in order to produce any rows. If, however, you wish to be flexible and allow for all 4 cases to be possible with a single query, then you have to find a way to ensure that both sides of the AND evaluate TRUE regardless of what inputs you receive. By using the NVL, you can accomplish that. You either pass in a null value or a not null value and the NVL check will make sure that the condition always evaluates to true. You get to either qualify which rows are returned by passing in a not null bind variable or you can leave the selection of rows unqualified by passing in a null value. Simple, huh?

Well, it may be simple in terms of the way the code looks, but what it does to the optimizer isn't that simple. The optimizer has to come up with a plan that can best serve all 4 possibilities equally. It can't/won't come up with 4 different plans.

Let me show you a few tests. I'll be using a test table I had in place from some previous tests for another post. It's a simple 2500 row table with 2 indexes (T2_I3 on the hair column and T2_I6 on the work column). Take a look at what happens when I execute my query 4 times using the 4 different scenarios I noted above.

SQL>set serveroutput off
SQL>variable b1 number
SQL>variable b2 number
SQL>exec :b1 := null;

PL/SQL procedure successfully completed.

SQL>exec :b2 := null ;

PL/SQL procedure successfully completed.

SQL>
SQL>select /*+ gather_plan_statistics */ count(*)
  2    from bitmap_t2
  3  where hair = NVL(:b1, hair)
  4    and work = NVL(:b2, work) ;

       COUNT(*)
---------------
           2500

1 row selected.

SQL>
SQL>@allstats_last

PLAN_TABLE_OUTPUT
------------------
SQL_ID  16jagac5xq0r4, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*)   from bitmap_t2 where hair = NVL(:b1, hair)   and work
= NVL(:b2, work)

Plan hash value: 2153464131
---------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
---------------------------------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE                |           |      1 |      1 |      1 |00:00:00.08 |    2504 |    342 |
|   2 |   CONCATENATION                |           |      1 |        |   2500 |00:00:00.07 |    2504 |    342 |
|*  3 |    FILTER                      |           |      1 |        |   2500 |00:00:00.06 |    2504 |    342 |
|*  4 |     TABLE ACCESS FULL          | BITMAP_T2 |      1 |    357 |   2500 |00:00:00.03 |    2504 |    342 |
|*  5 |    FILTER                      |           |      1 |        |      0 |00:00:00.01 |       0 |      0 |
|*  6 |     TABLE ACCESS BY INDEX ROWID| BITMAP_T2 |      0 |      5 |      0 |00:00:00.01 |       0 |      0 |
|*  7 |      INDEX RANGE SCAN          | T2_I6     |      0 |     32 |      0 |00:00:00.01 |       0 |      0 |
---------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(:B2 IS NULL)
   4 - filter(("HAIR"=NVL(:B1,"HAIR") AND "WORK" IS NOT NULL))
   5 - filter(:B2 IS NOT NULL)
   6 - filter("HAIR"=NVL(:B1,"HAIR"))
   7 - access("WORK"=:B2)

SQL>
SQL>exec :b2 := 45 ;

PL/SQL procedure successfully completed.

SQL>
SQL>select /*+ gather_plan_statistics */ count(*)
  2    from bitmap_t2
  3  where hair = NVL(:b1, hair)
  4    and work = NVL(:b2, work) ;

       COUNT(*)
---------------
             32

1 row selected.

SQL>
SQL>@allstats_last

PLAN_TABLE_OUTPUT
------------------
SQL_ID  16jagac5xq0r4, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*)   from bitmap_t2 where hair = NVL(:b1, hair)   and work
= NVL(:b2, work)

Plan hash value: 2153464131
---------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
---------------------------------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE                |           |      1 |      1 |      1 |00:00:00.01 |      67 |      4 |
|   2 |   CONCATENATION                |           |      1 |        |     32 |00:00:00.01 |      67 |      4 |
|*  3 |    FILTER                      |           |      1 |        |      0 |00:00:00.01 |       0 |      0 |
|*  4 |     TABLE ACCESS FULL          | BITMAP_T2 |      0 |    357 |      0 |00:00:00.01 |       0 |      0 |
|*  5 |    FILTER                      |           |      1 |        |     32 |00:00:00.01 |      67 |      4 |
|*  6 |     TABLE ACCESS BY INDEX ROWID| BITMAP_T2 |      1 |      5 |     32 |00:00:00.01 |      67 |      4 |
|*  7 |      INDEX RANGE SCAN          | T2_I6     |      1 |     32 |     32 |00:00:00.01 |      35 |      0 |
---------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(:B2 IS NULL)
   4 - filter(("HAIR"=NVL(:B1,"HAIR") AND "WORK" IS NOT NULL))
   5 - filter(:B2 IS NOT NULL)
   6 - filter("HAIR"=NVL(:B1,"HAIR"))
   7 - access("WORK"=:B2)

SQL>
SQL>exec :b1 := 5;

PL/SQL procedure successfully completed.

SQL>exec :b2 := null ;

PL/SQL procedure successfully completed.

SQL>
SQL>select /*+ gather_plan_statistics */ count(*)
  2    from bitmap_t2
  3  where hair = NVL(:b1, hair)
  4    and work = NVL(:b2, work) ;

       COUNT(*)
---------------
            357

1 row selected.

SQL>
SQL>@allstats_last

PLAN_TABLE_OUTPUT
------------------
SQL_ID  16jagac5xq0r4, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*)   from bitmap_t2 where hair = NVL(:b1, hair)   and work
= NVL(:b2, work)

Plan hash value: 2153464131
---------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
---------------------------------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE                |           |      1 |      1 |      1 |00:00:00.04 |    2504 |    342 |
|   2 |   CONCATENATION                |           |      1 |        |    357 |00:00:00.04 |    2504 |    342 |
|*  3 |    FILTER                      |           |      1 |        |    357 |00:00:00.03 |    2504 |    342 |
|*  4 |     TABLE ACCESS FULL          | BITMAP_T2 |      1 |    357 |    357 |00:00:00.03 |    2504 |    342 |
|*  5 |    FILTER                      |           |      1 |        |      0 |00:00:00.01 |       0 |      0 |
|*  6 |     TABLE ACCESS BY INDEX ROWID| BITMAP_T2 |      0 |      5 |      0 |00:00:00.01 |       0 |      0 |
|*  7 |      INDEX RANGE SCAN          | T2_I6     |      0 |     32 |      0 |00:00:00.01 |       0 |      0 |
---------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(:B2 IS NULL)
   4 - filter(("HAIR"=NVL(:B1,"HAIR") AND "WORK" IS NOT NULL))
   5 - filter(:B2 IS NOT NULL)
   6 - filter("HAIR"=NVL(:B1,"HAIR"))
   7 - access("WORK"=:B2)

SQL>
SQL>exec :b1 := 5;

PL/SQL procedure successfully completed.

SQL>exec :b2 := 45 ;

PL/SQL procedure successfully completed.

SQL>
SQL>select /*+ gather_plan_statistics */ count(*)
  2    from bitmap_t2
  3  where hair = NVL(:b1, hair)
  4    and work = NVL(:b2, work) ;

       COUNT(*)
---------------
              5

1 row selected.

SQL>
SQL>@allstats_last

PLAN_TABLE_OUTPUT
------------------
SQL_ID  16jagac5xq0r4, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*)   from bitmap_t2 where hair = NVL(:b1, hair)   and work
= NVL(:b2, work)

Plan hash value: 2153464131
---------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name      | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
---------------------------------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE                |           |      1 |      1 |      1 |00:00:00.02 |      67 |      5 |
|   2 |   CONCATENATION                |           |      1 |        |      5 |00:00:00.02 |      67 |      5 |
|*  3 |    FILTER                      |           |      1 |        |      0 |00:00:00.01 |       0 |      0 |
|*  4 |     TABLE ACCESS FULL          | BITMAP_T2 |      0 |    357 |      0 |00:00:00.01 |       0 |      0 |
|*  5 |    FILTER                      |           |      1 |        |      5 |00:00:00.02 |      67 |      5 |
|*  6 |     TABLE ACCESS BY INDEX ROWID| BITMAP_T2 |      1 |      5 |      5 |00:00:00.02 |      67 |      5 |
|*  7 |      INDEX RANGE SCAN          | T2_I6     |      1 |     32 |     32 |00:00:00.01 |      35 |      0 |
---------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - filter(:B2 IS NULL)
   4 - filter(("HAIR"=NVL(:B1,"HAIR") AND "WORK" IS NOT NULL))
   5 - filter(:B2 IS NOT NULL)
   6 - filter("HAIR"=NVL(:B1,"HAIR"))
   7 - access("WORK"=:B2)

Note how with each different set of bind variable values, the query produces a different result. But the plan remains the same (check the SQL_ID, child_number and plan hash values...they all match). You can also see how one set of the plan operations doesn't execute (note the 0's in the A-Rows, Buffers and Reads columns).

What this tells you is that the optimizer created a plan that would work dynamically. Well, sorta. Basically, the checks (step 3 and step 5) are made to see if :B2 IS NULL. If it is null, then step 4 executes. If it is not null, then steps 6-7 execute. This works fine for when you want the whole table (both bind values are null) or when you want to retrieve rows only where the work column equals some value. But, when you want to retrieve rows where you need to qualify both the work and hair columns or when you want to access rows for a particular hair value, the plan is sub-optimal.

So, OK...you're batting .500. Not bad I suppose. ;) But what if your SLA says you have to bat .900 or better? This plan just won't do. You need each different scenario to produce as optimal a plan as possible. How can you do that?

One way is to write your code to build the WHERE clause on the fly and use EXECUTE IMMEDIATE. The pseudo-code to do this might go something like this:

full_string := 'SELECT (rest of stuff).....';
if :b1 is null and :b2 is null then
   where_string := null;
elsif :b1 is not null and :b2 is not null then
   where_string := ' WHERE hair = :B1 AND work = :B2';
elsif :b1 is null and :b2 is not null then
   where_string := ' WHERE work = :B2';
elsif :b1 is not null and :b2 is null then
   where_string := ' WHERE hair = :B1';

full_string := full_string || where_string;
EXECUTE IMMEDIATE...

This way, you have 4 different statements and therefore 4 different plans. Each one (hopefully) optimal.

Another option would be to change your indexing strategy. Perhaps you could create a multi-column index using both columns. But, even with this option, you're not going to get "perfect" results. Depending on which column you decide to lead the index with, one of the index scans would likely have to do a skip scan or a full scan which wouldn't be as effective.

So, while the idea to use a single statement with conditional logic (in this case, NVL) and binds looks appealing, just remember that the plan you end up with may not provide the performance you want/need for all possible scenarios. If you use this approach, be prepared to create indexes properly so as to get the best possible coverage for all scenarios. I think the bottom line is that if you truly want dynamic SQL, then really use dynamic SQL. The attempt to simplify or to have a single statement that covers many different possible needs can cause performance to suffer for a some percentage (perhaps a significant %) of the scenarios.

You say, "Thank you". I say, "You're welcome".

You say "Thank you". I say, "You're welcome". At least that's how my mother taught me. It's good manners to respond to a "thank you", with a "you're welcome". But, it seems like many people either didn't learn their manners the same way I did or maybe they just don't have any manners. Either way, I've got a pet peeve to rant on as a hiatus from the heavy tech nature of my last couple of posts (Cheryl, I'm primarily thinking of you as I write this non-techie post).

It's pandemic: waiters, store clerks, gas station attendants, even the phone person who helped me with my recent airfare purchase. All of them responded to my "thank you" by saying something like "no problem" or "yep" or "sure". It may be my upbringing to be mannerly. It may be my Southern roots. It may be just some other voice in my head that translates what I hear, when I hear any of those responses. But whatever the reason, when I hear anything other than "you're welcome", it immediately seems rude to me. When I hear "no problem", I think, "it shouldn't be a problem since I'm paying you for your time and service". Or, when I hear "yep", I immediately picture a gum-smacking, sixteen year old rolling their eyes at me and breathing a long-suffering sigh in my direction as they trudge back to the kitchen to get the baked potato that was left off my order.

Somehow saying "you're welcome" at least gives me the impression that you are having a personal interaction with me and not just giving me your time/attention/service because you have to be there when you'd really rather be anywhere else. It just seems like the "nice" and polite thing to say.

I know it's likely that only I have an objection to such flip responses, but I admit it. I do.

So, if you happen to get a "thank you" from me, I'd really appreciate a "you're welcome".

Thank you for reading. ;)

Round 2: BITMAP AND

OK. I thought this would be pretty straightforward, but as it turns out, it wasn't (is it ever?). I finally got around to testing out the BITMAP CONVERSION stuff as related to my previous post. I've actually been working on this off and on since my previous post, but am just now to the point where I'm willing to share the results. Jeff Holt was a huge help and determined the correct trace events needed to investigate this fully. Thanks Jeff!

First, an interesting/surprising thing I found in trying to reproduce the behavior originally noted was that I wasn't able to reproduce it! What I could consistently reproduce (on both 10.2.0.1 and 11.1.0.6 instances) was essentially the opposite behavior of what the original client case showed. So, I decided to just make sure I could understand how the two operations (BITMAP AND vs AND-EQUAL) worked for what I could reproduce. This post is just about the BITMAP AND operation. I'll post another day about AND-EQUAL.

From here on out, this post has lots of code and trace data output, so if you just want the punch-line, scroll to the bottom. :)

If you'd like to try the tests yourself, here's how I created the test data and performed the test.

-- Create test table, populate with data and collect statistics (setup.sql)
drop table bitmap_test;

create table bitmap_test as
select rownum id
from all_objects
where rownum <= 50 /* make larger for more data */;

drop table bitmap_t2;

define isto="pctfree 99 storage (initial 5m)"
define tsto="pctused 1 &isto"

create table bitmap_t2
nologging
&tsto
as select /*+ ordered use_nl(v2) */
    lpad('x',20,'x')    facts,
    mod(rownum, 2)  sex,
    mod(rownum, 3)  eyes,
    mod(rownum, 7)  hair,
    mod(rownum, 31) town,
    mod(rownum, 47) age,
    mod(rownum, 79) work
from bitmap_test v1,
     bitmap_test v2
/

create index t2_i3 on bitmap_t2(hair) nologging &isto;
create index t2_i6 on bitmap_t2(work) nologging &isto;

exec dbms_stats.gather_table_stats(user, 'bitmap_t2', estimate_percent=>100, -
method_opt=>'for all columns size 1', cascade=>TRUE, no_invalidate=>FALSE)

-- Test (test.sql)
select value from v$parameter where name = 'user_dump_dest';

-- Get SPID so I can easily find trace file
select p.spid from v$session s, v$process p 
where audsid = userenv('sessionid') and s.paddr = p.addr;

-- Turn on all pertinent trace events
alter session set events '10046 trace name context forever';
alter session set events '10202 trace name context forever';
alter session set events '10711 trace name context forever, level 127';
alter session set events '10713 trace name context forever, level 127';
alter session set events '10715 trace name context forever, level 127';
alter session set events '10717 trace name context forever, level 127';
alter session set statistics_level=all;

set termout off pause off

-- Run once for each query 
-- Run with index_combine hint to get BITMAP AND plan
select /*+ index_combine(bitmap_t2 t2_i6 t2_i3) */ * 
from bitmap_t2 where hair = 5 and work = 45;

-- Run with RULE hint to get AND-EQUAL plan
-- select /*+ rule */ * from bitmap_t2 where hair = 5 and work = 45;

set termout on
exit

Test 1 trace output (STAT lines only)

STAT #2 id=1 cnt=5 pid=0 pos=1 obj=56968 op='TABLE ACCESS BY INDEX ROWID BITMAP_T2 (cr=400 pr=362 pw=0 time=79714 us)'
STAT #2 id=2 cnt=5 pid=1 pos=1 obj=0 op='BITMAP CONVERSION TO ROWIDS (cr=395 pr=361 pw=0 time=78988 us)'
STAT #2 id=3 cnt=1 pid=2 pos=1 obj=0 op='BITMAP AND  (cr=395 pr=361 pw=0 time=78694 us)'
STAT #2 id=4 cnt=1 pid=3 pos=1 obj=0 op='BITMAP CONVERSION FROM ROWIDS (cr=35 pr=1 pw=0 time=11851 us)'
STAT #2 id=5 cnt=32 pid=4 pos=1 obj=56970 op='INDEX RANGE SCAN T2_I6 (cr=35 pr=1 pw=0 time=11297 us)'
STAT #2 id=6 cnt=1 pid=3 pos=2 obj=0 op='BITMAP CONVERSION FROM ROWIDS (cr=360 pr=360 pw=0 time=66579 us)'
STAT #2 id=7 cnt=357 pid=6 pos=1 obj=56969 op='INDEX RANGE SCAN T2_I3 (cr=360 pr=360 pw=0 time=65355 us)'

Test 2 trace output (STAT lines only)

STAT #3 id=1 cnt=5 pid=0 pos=1 obj=56968 op='TABLE ACCESS BY INDEX ROWID BITMAP_T2 (cr=282 pr=4 pw=0 time=10833 us)'
STAT #3 id=2 cnt=5 pid=1 pos=1 obj=0 op='AND-EQUAL  (cr=277 pr=0 pw=0 time=8651 us)'
STAT #3 id=3 cnt=38 pid=2 pos=1 obj=56969 op='INDEX RANGE SCAN T2_I3 (cr=147 pr=0 pw=0 time=4553 us)'
STAT #3 id=4 cnt=37 pid=2 pos=2 obj=56970 op='INDEX RANGE SCAN T2_I6 (cr=130 pr=0 pw=0 time=3614 us)'

Here's the result comparison

BITMAP CONVERSION cr=395 pr=361 pw=0 time=78988 us
AND-EQUAL         cr=282 pr=4   pw=0 time=10833 us

I did a couple of simple count queries to verify how many rows matched each predicate. You can also note the number of buffer accesses are required to satisfy each count.

SQL> select /*+ gather_plan_statistics */ count(*) from bitmap_t2 where work = 45 ;

       COUNT(*)
---------------
             32
SQL> @allstats_last

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------
SQL_ID  9xbjw9v72xnty, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from bitmap_t2 where work = 45

Plan hash value: 806960853
-------------------------------------------------------------------------------------
| Id  | Operation         | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE   |       |      1 |      1 |      1 |00:00:00.01 |      35 |
|*  2 |   INDEX RANGE SCAN| T2_I6 |      1 |     32 |     32 |00:00:00.01 |      35 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("WORK"=45)

SQL>
SQL> select /*+ gather_plan_statistics */ count(*) from bitmap_t2 where hair = 5 ;

       COUNT(*)
---------------
            357

1 row selected.

SQL> @allstats_last

PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------------------
SQL_ID  5h1vvmx6wd2j2, child number 0
-------------------------------------
select /*+ gather_plan_statistics */ count(*) from bitmap_t2 where hair = 5

Plan hash value: 3466781003
-------------------------------------------------------------------------------------
| Id  | Operation         | Name  | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------
|   1 |  SORT AGGREGATE   |       |      1 |      1 |      1 |00:00:00.03 |     360 |
|*  2 |   INDEX RANGE SCAN| T2_I3 |      1 |    357 |    357 |00:00:00.03 |     360 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("HAIR"=5)

From this information, you can see that the buffer gets for a single predicate match the cr values in the bitmap plan. So, what happened with the AND-EQUAL plan? The STAT line rowsource totals for two INDEX RANGE SCAN operations in the AND-EQUAL plan don't seem to make any sense at all.

STAT #3 id=3 cnt=38 pid=2 pos=1 obj=56969 op='INDEX RANGE SCAN T2_I3 (cr=147 pr=0 pw=0 time=4553 us)'
STAT #3 id=4 cnt=37 pid=2 pos=2 obj=56970 op='INDEX RANGE SCAN T2_I6 (cr=130 pr=0 pw=0 time=3614 us)'

The index T2_I3 is on the hair column. According to the counts, there are 357 rows where hair=5. So, why does the execution information show 38 rows returned (cnt=38) and cr=147? Further, why does the scan on the T2_I6 (work column) index show 37 rows returned and cr=130? That makes no sense to me at all. Anyway, as I said, I'll review the details of the AND-EQUAL plan in another post.

Let's go back to the BITMAP AND plan. I learned a lot from reviewing the trace file about how the BITMAP AND operation works. Here's some of the content that shows you what's going on:

-- Trace file excerpt

qerbtStart(8217284): started
qerbtStart(8228444): started
qerbtStart(8228b0c): started
qerbaStart(8217170): started
qerbtFetch bitmap to rowids(8217284):
qerbtFetch rowids to bitmap(8228444):
kdibcoinit(82286b4): srid=011389bb.0000

<< At this point a series of block gets were performed to read the T2_I6 index blocks >>

kdibcoend(82286b4): erid=013252ea.0007status=0

-- The following call is what shows up in the plan as the BITMAP CONVERSION FROM ROWIDS for T2_I6 (work) step
qerbtFetch out bitmap(8228444): bml 127 srid=011389bb.0000, erid=013252ea.0007 objn 56968

-- The following line shows the starting (srid) and ending (erid) rowids for rows where work = 45 (from index T2_I6)
kdibr1r2r(8217184): bml 127 srid=011389bb.0000, erid=013252ea.0007

kdibci3init(8351904): src_stream=a4bd1ac

qerbtFetch rowids to bitmap(8228b0c):

<< At this point a series of block gets were performed to read the T2_I3 index blocks >>

kdibcoend(8228d7c): erid=01325308.0007status=0

-- The following call is what shows up in the plan as the BITMAP CONVERSION FROM ROWIDS for T2_I3 (hair) step
qerbtFetch out bitmap(8228b0c): bml 1054 srid=011389bb.0000, erid=01325308.0007 objn 56968  

-- The following line shows the starting (srid) and ending (erid) rowids for rows where hair = 5 (from index T2_I3)
kdibr1r2r(8217184): bml 1054 srid=011389bb.0000, erid=01325308.0007

kdibci3init(8351938): src_stream=a4bd1ac

-- The following call is setting up the BITMAP AND with the info collected from the two indexes
kdibc3init(8217198): buf(16116)=83527b0, srid=011389bb.0000
kdibc3end(8217198)

-- The following call is what shows up in the plan as the BITMAP AND step in the plan
kdibr2s2r out bitmap(8217184): bml 6 srid=011389bb.0000, erid=01325108.0007   

-- The following shows the final range of rowids that will need to be fetched 
kdibr1r2r(8217298): bml 19 srid=011389bb.0000, erid=01325108.0007 
kdibci3init(82172ac): src_stream=a4bd354

-- The following call shows the number of rows to be retrieved (5) and lists their rowid
kdibc3sids(82172ac): want=57, got=5
 011389bb.0000 01138bec.0000 01138e1f.0000 01139050.0000
 01325108.0000

-- This call fetches the first rowid from the list
qerbtFetch(8217284): rowid=011389bb.0000 tobj 56968

-- DATA block cr 0x011389bb is fetched here

-- Then, the first FETCH line is emitted to the trace data.  
-- Note that it shows cr=396.  That's the total of T2_I6 index block reads plus
-- T2_I3 index block reads plus the 1 data block read that just occurred.

FETCH #2:c=15625,e=78684,p=361,cr=396,cu=0,mis=0,r=1,dep=0,og=1,tim=84895456678

-- The next series of calls gets the remaining 4 rows from the list above. 
qerbtFetch bitmap to rowids(8217284):
qerbtFetch(8217284): rowid=01138bec.0000 tobj 56968
-- DATA block cr 0x01138bec is fetched here
qerbtFetch bitmap to rowids(8217284):
qerbtFetch(8217284): rowid=01138e1f.0000 tobj 56968
-- DATA block cr 0x01138e1f is fetched here
qerbtFetch bitmap to rowids(8217284):
qerbtFetch(8217284): rowid=01139050.0000 tobj 56968
-- DATA block cr 0x01139050 is fetched here
qerbtFetch bitmap to rowids(8217284):
qerbtFetch(8217284): rowid=01325108.0000 tobj 56968
-- DATA block cr 0x01325108 is fetched here
qerbtFetch bitmap to rowids(8217284):
kdibc3sids(82172ac): want=57, got=0

-- The 2nd, and final, FETCH line is emitted showing the 4 block
-- accesses for the remaining rows.

FETCH #2:c=0,e=735,p=1,cr=4,cu=0,mis=0,r=4,dep=0,og=1,tim=84895457801

So, here's the bottom-line with BITMAP AND plans as best I can decipher from my tests:
1) The index blocks are all read first and the applicable rows (i.e. ROWIDs) matching the predicate are placed into memory. The first FETCH line emitted by the 10046 trace shows the reads (cr and pr) that count these index blocks being collected.
2) A separate memory area is associated with each INDEX that is involved.
3) The index ROWIDs are converted to bitmaps.
4) Once all the index ROWIDs are collected and converted, they are AND'ed together to produce a final bitmap that represents the range of ROWIDs needed for the result.
5) That final bitmap is converted back to a list of ROWIDs.
6) Each ROWID on the list is then retrieved. This is where the data blocks are retrieved. You'll see just a cr (consistent read) or a cr and a pr (physical read) if the block isn't already in the buffer cache.

So, what you should see is that the first FETCH (10046 trace data) will have the stats for the collection of all the index blocks needed and placing them into memory. After that, only data blocks are read.

It makes sense when I look at now. I still don't quite understand what happened in the original case noted in my earlier post, but I believe I've come a long way in my understanding of how bitmap conversion operations function.

For those geeks out there like me who really find this interesting and want to do the tests yourself, please have at it! I'd love to hear back from you if you get contradictory results or if your understanding of how the process is working is different than mine. I was able to reproduce my tests with larger data sets but it would be great if you get another set of results you would share. Let me know!