It's the little things....

That can really mess up your day.

I'm using this little script:

declare
v_flush varchar2(3) := '&1';
err_mesg varchar2(250);

begin
if substr(upper(v_flush),1,2) = 'BP' then
sys.hotsos_pkg.flush_bp;
dbms_output.put_line ('*** Buffer Pool Flushed ***') ;
end if;
if substr(upper(v_flush),1,2) = 'SP' then
sys.hotsos_pkg.flush_sp;
dbms_output.put_line ('*** Shared pool flushed ***') ;
end if;
exception
when others then
err_mesg := SQLERRM;
dbms_output.put_line ('****** Error! '||err_mesg) ;
end ;
/

And it's not working, as in, it's not flushing the pools. I get no errors. For the life of me I can't figure it out. I put in several DBMS_OUTPUT.PUT_LINE commands to print out what is going on as it runs. Eventually I notice that the variable v_flush is set to literally &1 while this thing runs. WHAT?

It turned out that DEFINE had some how gotten turned OFF in the session. How I'm not exactly sure, but now this script file has:

set define on

at the top of it.

New read events in 11G DIRECT PATH READ and DIRECT PATH READ TEMP

In prior version of Oracle, Oracle used the SEQUENTIAL READ event to read temp objects into the PGA. With 11 Oracle seems to use some new read events. The DIRECT PATH READ appears to be used to read information from the data files into the temp segment, then DIRECT PATH READ TEMP will be used while manipulating the temp segment. There is also a DIRECT PATH WRITE TEMP event. This was always writing out a max of 31 blocks in my tests. (Which sure seemed like an strange number to me.)

In my simple test I have a query on a table with @2.3 Million rows and no indexes. Oracle version 11.2.0.1 on a Dell Inspiron. The query has a order by on the 3 columns I'm selecting and there is no choice other then to read the entire table via a full table scan and then sort the rows in temp.

SELECT OWNER, OBJECT_NAME, STATUS FROM AHWM ORDER BY 1,2,3;

I wanted to see if the setting of DB_FILE_MULTIBLOCK_READ_COUNT had any affect on the DIRECT PATH READ and DIRECT PATH READ TEMP events. Here is the findings:

With DB_FILE_MULTIBLOCK_READ_COUNT set to 8 I didn’t see a read more then 8 in my trace:
WAIT #8: nam='direct path read' ela= 9760 file number=4 first dba=5120 block cnt=8 obj#=76480 tim=102097583805


With DB_FILE_MULTIBLOCK_READ_COUNT set to 16 I didn’t see a read more then 16 in my trace:
WAIT #8: nam='direct path read' ela= 9916 file number=4 first dba=5728 block cnt=16 obj#=76480 tim=104104097173


With DB_FILE_MULTIBLOCK_READ_COUNT set to 32 I didn’t see a read more then 32 in my trace:
WAIT #9: nam='direct path read' ela= 1965 file number=4 first dba=5600 block cnt=32 obj#=76480 tim=106136990814


With DB_FILE_MULTIBLOCK_READ_COUNT set to 0 (128) I didn’t see a read more then 128 in my trace:
WAIT #4: nam='direct path read' ela= 516 file number=4 first dba=29952 block cnt=128 obj#=76480 tim=109775067490


Ah! So YES the setting of good old DB_FILE_MULTIBLOCK_READ_COUNT will impact how many blocks are requested with each DIRECT PATH READ event.

Now for DIRECT PATH READ TEMP, the setting of DB_FILE_MULTIBLOCK_READ_COUNT made no difference. It was a max of 7 in all my tests, and only for very few events. For the most part it was reading 1 block at a time.

Did the changes have any performance impact? Well not really. Looking at the stat lines for each one they all did the same LIOs, PIOs and really ran in about the same amount of time:

Actual lines from extended SQL trace for a_sort:a_sort_8
----------------------------------------------------------------------------------------------------------------------------------
STAT #7 id=1 cnt=2291136 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=32542 pr=45112 pw=12575 time=9488819 us cost=31576 size=87063168 card=2291136)'
STAT #7 id=2 cnt=2291136 pid=1 pos=1 obj=76480 op='TABLE ACCESS FULL AHWM (cr=32542 pr=32537 pw=0 time=5905761 us cost=8895 size=87063168 card=2291136)'

Actual lines from extended SQL trace for a_sort:a_sort_16
----------------------------------------------------------------------------------------------------------------------------------
STAT #8 id=1 cnt=2291136 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=32542 pr=45112 pw=12575 time=9409541 us cost=29880 size=87063168 card=2291136)'
STAT #8 id=2 cnt=2291136 pid=1 pos=1 obj=76480 op='TABLE ACCESS FULL AHWM (cr=32542 pr=32537 pw=0 time=5615230 us cost=7199 size=87063168 card=2291136)'

Actual lines from extended SQL trace for a_sort:a_sort_32
----------------------------------------------------------------------------------------------------------------------------------
STAT #9 id=1 cnt=2291136 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=32542 pr=45112 pw=12575 time=8508505 us cost=29032 size=87063168 card=2291136)'
STAT #9 id=2 cnt=2291136 pid=1 pos=1 obj=76480 op='TABLE ACCESS FULL AHWM (cr=32542 pr=32537 pw=0 time=5264382 us cost=6351 size=87063168 card=2291136)'

Actual lines from extended SQL trace for a_sort:a_sort_0
----------------------------------------------------------------------------------------------------------------------------------
STAT #4 id=1 cnt=2291136 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=32542 pr=45112 pw=12575 time=9435964 us cost=28396 size=87063168 card=2291136)'
STAT #4 id=2 cnt=2291136 pid=1 pos=1 obj=76480 op='TABLE ACCESS FULL AHWM (cr=32542 pr=32537 pw=0 time=4780372 us cost=5715 size=87063168 card=2291136)'