Friday, June 3, 2011

Hidden updates - another reason to trace

An insert or update statement that is taking a long time to complete is often working on the indexes belonging to the table rather than the table itself. If you look at the plan and finds nothing wrong, it is easy to forget that the indexes have to be updated as well.

The solution as always when something takes time is to enable trace. When updating the indexes the trace file will usually show waits of type db file sequential read, and usually one block at the time.

Full table scan normally causes db file scattered read with many blocks at the time. The number of blocks it fetches is limited, but not exclusively, by the parameter db_file_multiblock_read_count.

In other words, with lots of full table scans you expect db file scattered read but your GUI gives you db file sequential read. The trace file will show you what objects are causing waits and may remind you that the table has an index or two that you can drop and add later.

This command counts the number of waits of one type grouped by object_id (as in dba_objects):

grep "db file sequential read" FOOPROD_ora_6237.trc |awk '{ print $12}' |sort | uniq –c

You can find total elapsed time (in seconds) for a specific object_id (106836 in this example) with:

awk '/106836/ { ela += $8} END {print ela/1000000}' FOOPROD_ora_6237.trc

Repeat this for the object ids from the first list to find where most time is spent.

Then you can find the type and name of the object:

select object_type, object_name
from dba_objects
where object_id=106836;

Of course a decent profiler will do this for you. I wrote this post to remind myself that the trace file will tell me what the fancy GUI hides for me. And it is kind of cool that on a mature OS a string of simple commands allow me to make my own ad-hoc profiler.