Section 5.6. Forward Attribution | Optimizing Oracle Performance

5.6 Forward Attribution

When you identify a time-consuming wait event in an Oracle extended SQL trace file, your next task will be to determine which application action you might modify to reduce the time consumption. Doing this with extended SQL trace data is straightforward. You should attribute each WAIT # n duration to the first database call for cursor # n that follows the WAIT line in the trace file. I call this method forward attribution . Forward attribution helps you accurately identify which application SQL is responsible for motivating the wait time. Perhaps remarkably, forward attribution works both for events that are executed within database calls and for events that are executed between database calls.

5.6.1 Forward Attribution for Within-Call Events

For events executed within database calls, the reason for forward attribution is easy to understand. Because lines are written to the trace file as their corresponding actions complete, the wait events executed by a given database call appear in the trace stream before the call's trace file line. The following excerpt (snipped from Example 5-3) shows how the Oracle kernel emits within-call event lines:

 = = = = = = = = = = = = = = = = = = = = = PARSING IN CURSOR #4 len=132 dep=1 uid=0 oct=3 lid=0 tim=1033064137929238  hv=3111103299 ad='517ba4d8' select /*+ index(idl_ub1$ i_idl_ub11) +*/ piece#,length,piece from idl_ub1$ where  obj#=:1 and part=:2 and version=:3 order by piece# END OF STMT PARSE #4:c=0,e=306,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137929139 EXEC #4:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137931262  [1]  WAIT #4: nam='db file sequential read' ela= 13060 p1=1 p2=53903 p3=1  [2]  WAIT #4: nam='db file sequential read' ela= 6978 p1=1 p2=4726 p3=1  [3]  FETCH #4:c=0,e=21340,p=2,cr=3,cu=0,mis=0,r=0,dep=1,og=4,tim=1033064137953092

In this example, the db file sequential read events on lines [1] and [2] were executed within the context of the FETCH depicted on line [3] .

5.6.2 Forward Attribution for Between-Call Events

For events executed between database calls, the reason that forward attribution works is more subtle. The following Oracle8 i example (snipped from Example 5-4) helps to illustrate the issue. Because of a database driver deficiency, this application actually submitted each parse call to the database two times. ^[2] Notice the identical PARSING IN CURSOR sections separated by a to / from SQL*Net message pair:

^[2] Lots of drivers provide an option to behave this way. The extra parse is used to produce a "describe" of the SQL being parsed, so that the driver can produce more informative error messages for the developer. Even the Perl DBI behaves this way by default. In Perl, you can deactivate this behavior by specifying the ora_check_sql=>0 attribute in prepare calls.

 = = = = = = = = = = = = = = = = = = = = = PARSING IN CURSOR #9 len=360 dep=0 uid=26 oct=2 lid=26 tim=1716466757 hv=2475520707  ad='d4c55480' INSERT INTO STAGING_AREA (TMSP_LAST_UPDT, OBJECT_RESULT, USER_LAST_UPDT, DOC_OBJ_ID,  TRADE_NAME_ID, LANGUAGE_CODE) values(TO_DATE('11/05/2001 16:39:06', 'MM/DD/YYYY HH24: MI:SS'), 'if ( exists ( stdphrase ( "PCP_MAV_1" ) ) , langconv ( "Incompatibility  With Other Materials" ) + ":  " , log_omission ( "Materials to Avoid: " ) )', 'sa',  222, 54213, 'NO_LANG')  END OF STMT PARSE #9:c=0,  e=0  ,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=1716466757  [1]  WAIT #9: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0  [2]  WAIT #9: nam='SQL*Net message from client' ela= 3 p1=1413697536 p2=1 p3=0 = = = = = = = = = = = = = = = = = = = = = PARSING IN CURSOR #9 len=360 dep=0 uid=26 oct=2 lid=26 tim=1716466760 hv=2475520707  ad='d4c55480' INSERT INTO STAGING_AREA (TMSP_LAST_UPDT, OBJECT_RESULT, USER_LAST_UPDT, DOC_OBJ_ID,  TRADE_NAME_ID, LANGUAGE_CODE) values(TO_DATE('11/05/2001 16:39:06', 'MM/DD/YYYY HH24: MI:SS'), 'if ( exists ( stdphrase ( "PCP_MAV_1" ) ) , langconv ( "Incompatibility  With Other Materials" ) + ":  " , log_omission ( "Materials to Avoid: " ) )', 'sa',  222, 54213, 'NO_LANG')  END OF STMT  [3]  PARSE #9:c=0,  e=0  ,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1716466760

Even though the parse calls were routinely inexpensive (note the two e=0 durations highlighted in the example), the response time for the overall user action suffered brutally from the tremendous number of unnecessary SQL*Net message from client executions, which consumed an average of over 0.027 seconds per call. The overall impact to response time was several minutes on a user action that should have consumed less than 10 seconds in total (see Section 12.3). To eliminate the SQL*Net event executions shown on lines [1] and [2] , you can eliminate the parse call depicted on line [3] that follows it. In general, the database call that has "caused" a between-call event is the database call whose trace file line follows the WAIT .

Top