APPNAME in trace

Hi

Has anyone seen a trace file where APPNAME lines (DBMS_APPLICATION_INFO.SET_MODULE)
exceed 40% of the lines in the trace file?

I have run a 10046 trace (level 8) on a job that is not completing as quickly as we'd like.

I'm trying to calculate how much SET_MODULE is affecting response time. I've written a perl script to calculate the difference in the "tim=" value before and
after the calls to SET_MODULE since there is no timestamp, "e=", or "ela=" values given.
(I need to correct it so that I subtract any "e" or "ela" values as implied by
 page 101 of Optimizing Oracle Performance. [Thank you, Cary and Jeff!])

Would the trace be writing these lines out-of-order? I've looked at the PL/SQL (developed in-house) and I don't see consecutive calls to SET_MODULE.

I've searched the list and haven't found anything about this particular problem.

Thanks,
Nelson Petersen

OS: OpenVMS 7.3
Oracle: 9.2.0.4
Trace level: 8

>>> Small sample:

EXEC #12:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=4655143414947914 FETCH #12:c=0,e=0,p=0,cr=4,cu=0,mis=0,r=1,dep=1,og=4,tim=4655143414947914 APPNAME mod='get_cop219_records' mh=265427417 act='assign_released_detail' ah=902314959
APPNAME mod='get_item_reg_clist' mh=3358374899 act='' ah=4029777240 APPNAME mod='get_cop219_records' mh=265427417 act='assign_released_detail' ah=902314959
APPNAME mod='get_ovr_reg_clist_amt' mh=1537375804 act='' ah=4029777240 APPNAME mod='get_cop219_records' mh=265427417 act='assign_released_detail' ah=902314959
APPNAME mod='get_item_reg_zone' mh=733115880 act='' ah=4029777240 APPNAME mod='get_cop219_records' mh=265427417 act='assign_released_detail' ah=902314959
APPNAME mod='get_bo_cd' mh=3630673486 act='' ah=4029777240 APPNAME mod='get_cop219_records' mh=265427417 act='assign_released_detail' ah=902314959
APPNAME mod='get_in_season_cd' mh=3452384658 act='' ah=4029777240 APPNAME mod='determine_if_on_flyer' mh=870677255 act='' ah=4029777240 EXEC #13:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=4655143414953773 FETCH
#13:c=10000,e=6835,p=0,cr=83,cu=0,mis=0,r=0,dep=1,og=4,tim=4655143414960608

--
http://www.freelists.org/webpage/oracle-l