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)'


MBRC and DB_FILE_MULTIBLOCK_READ_COUNT

Maybe you have this down but I found out today that I had understood this completely backwards. It was my understanding that DB_FILE_MULTIBLOCK_READ_COUNT (if set) was only used to COST the plan but MBRC (if set) would be used for each scattered read. This doesn’t appear to be the case, in fact it appears I have this exactly opposite.

I have on my test box collected workload system stats and MBRC is set to 8.


I tried it with DB_FILE_MULTIBLOCK_READ_COUNT set to 0, in which case the system sets it to 128. I expected to get scattered reads of 8. But I got my first read on the table at 128, and then next got what was left. (I created the table with 1024 blocks in the first extent.)


WAIT #10: nam='db file scattered read' ela= 16051 file#=4 block#=290066 blocks=128 obj#=77649 tim=891367221237

WAIT #10: nam='db file scattered read' ela= 1341 file#=4 block#=290194 blocks=24 obj#=77649 tim=891367282208


OK, not what I expected. Then I set DB_FILE_MULTIBLOCK_READ_COUNT to 16 and dag-nab-bit, I got a bunch of 16 block reads.


file scattered read' ela= 903 file#=4 block#=290082 blocks=16 obj#=77649 tim=891493998398

file scattered read' ela= 807 file#=4 block#=290098 blocks=16 obj#=77649 tim=891493999573

file scattered read' ela= 839 file#=4 block#=290114 blocks=16 obj#=77649 tim=891494000751

file scattered read' ela= 824 file#=4 block#=290130 blocks=16 obj#=77649 tim=891494001988

file scattered read' ela= 815 file#=4 block#=290146 blocks=16 obj#=77649 tim=891494003176

file scattered read' ela= 23783 file#=4 block#=290162 blocks=16 obj#=77649 tim=891494027343

...


Well then I looked at the COST of the plan, I get the same COST for a setting of 8, 16, and 32 for DB_FILE_MULTIBLOCK_READ_COUNT (it's kinda hard to read, the cost is 50 in the plan below):


SQL> get zz_test1
1 select *
2 from MBRC_TEST
3* where object_id between 1 and 4

SQL> @hxplan

Enter .sql file name (without extension): zz_test1

Enter the display level (TYPICAL, ALL, BASIC, SERIAL) [TYPICAL] :

Plan hash value: 3059191348


-------------------------------------------------------------------------------
| Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time |
-------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 503 | 52312 | 50 (0)| 00:47:06 |
|* 1 | TABLE ACCESS FULL| MBRC_TEST | 503 | 52312 | 50 (0)| 00:47:06 |
-------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

1 - filter("OBJECT_ID"<=4 AND "OBJECT_ID">=1)


So there you have it, the MBRC value is used to COST the plan but NOT for the scattered read event. Honestly reading the docs it was less then clear, hence my confusion. Nothing beats a test! (or more then one really, I did this several times just to make sure I was seeing it right.)

This number keeps coming up....

Happy Holidays! Hawaiian style...

Baby Blues BBQ in Philadelphia

I visited Baby Blues BBQ in Philly this past week and had the “Mason Dixon” (1/2 RACK of MEMPHIS RIBS, 1/4 of a CHICKEN). The Mac and Cheese is great with the hot sauce by the way. If you're in Philly and want some ribs instead of a cheese stake sandwich, try them out. Great folks working the grill and super servers.

I sat where I was looking right on to the grill and watched the guys making the food. Makes ya more hungry watching the food get prepared. They were cooking up ribs and chicken and shrimp and corn on the cob all on the grill! It was great.

The place is a little of the beaten path, and worth the time to find:

3402 Sansom St
Philadelphia, PA 19104

Error Logging in SQLPlus

This is pretty cool. You can now log errors in to table within SQLPlus. I think when this feature first came out it was just for DML (insert, update and delete) but now it seems to work for any error that is raised within a SQLplus session.

The command to turn this on is a SQLPlus SET command, it's simplest format is:

SET ERRORLOGGING on

With this SQLPlus will start putting errors into a table called sperrorlog. What's cool about this statement is that if the table doesn't exist it will created it. In the more verbose format it would look something like this:

SET ERRORLOGGING on TABLE hsperrorlog TRUNCATE IDENTIFIER HARNESS

With this I have to create a table named hsperrorlog. The TRUNCATE option truncates the contents of the table before it starts logging anything into it. The IDENTIFIER option allows you to populate a column in the table, with the name of (you guessed it) IDENTIFIER. (Pretty cleaver eh?)

The table has these columns (all can be null):

USERNAME data type VARCHAR2(256) the user running the command.

TIMESTAMP data type TIMESTAMP(6) when the error was encountered.

SCRIPT data type VARCHAR2(1024) the name of the script being run. If this is an interactively entered command this will be null.

IDENTIFIER data type VARCHAR2(256) the optional id used when turning on error logging. You can change the identifier by just doing a set command like this:

set errorlogging ON IDENTIFIER RVD

This doesn't change the table that the errors are being logged into.

MESSAGE data type CLOB this is the error message.

STATEMENT data type CLOB this is the statement that raised the error.

I've been using it to add some needed functionality to the Hotsos Harness and it's already helped me clean up a few minor errors in the harness that have been quite hard to track down with out this.

Here is a very simple example, the output was reformatted to make this easier to read:

OP@ORCL112> SET ERRORLOGGING on TABLE hsperrorlog TRUNCATE IDENTIFIER HARNESS
OP@ORCL112> select * from XYZ;
select * from XYZ
*
ERROR at line 1:
ORA-00942: table or view does not exist

OP@ORCL112> select * from hsperrorlog;

USERNAME
-----------
OP

TIMESTAMP
----------------------------
23-NOV-10 12.59.39.000000 PM

SCRIPT
----------------------------


IDENTIFIER
----------
HARNESS

MESSAGE
---------------------------------------
ORA-00942: table or view does not exist

STATEMENT
-----------------
select * from XYZ

Check this out, it should make debugging SQL scripts a lot easier!! There are some limitations to it of course, it's not on for recursive SQL which makes a lot of sense since it could easily get into an infinite loop. Also if your scripts do reconnections, you'll have to turn it back on each time you reconnect. It is off by default.

Oh and to turn it off it looks like:

OP@ORCL112> SET ERRORLOGGING off
OP@ORCL112>
OP@ORCL112> show errorl
errorlogging is OFF