Often there a common question the case for reading tkprof where to start what should I look for are there guidelines to have a systematic approach? This article would try to address very basic portion for the beginners here.
I assume the readers have following background information
1. How to generate a Oracle trace
2. How to locate and identify Oracle trace file
3. How to convert it in verbose ( more readable format using tkprof utility)
Often asked question to DBAs is what is it that I should look for in tkprofed trace file.
4. Version and release of Oracle I am talking about is 10g and on.
5. Fundamental of wait event 10046 and sql tuning
When you get a trace file you need to get to the bottom of it ( great things start bottom up ) .....
1st and foremost thing to look for in a tkprof file of a concurrent program is
the summary at the bottom of the tkprof.
eg
Trace file: mydb_ora_36567.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
1 user SQL statements in trace file.
350 internal SQL statements in trace file.
351 SQL statements in trace file.
50 unique SQL statements in trace file.
4502290 lines in trace file.
984 elapsed seconds in trace file.
And what does this mean , 984 seconds is the total taime recorded in database.
which is 16 mins and 14 seconds. So if my target for improving the performance is say 5 mins , I am 11 mins away from where I should be.
The second thing you should look at is 4502290 lines in trace file. Which means there's whole lot of iterative fetches happening. Whic tells me that there's quite a sequential fetch logic (recursive) without even looking at the program.
Although I concluded lot of sequential fetching it's not always the case hence 50 unique sql statements is something worth considering. Also note than in Apps envrionment if someone tells you that the program ran for 22 mins or 30 mins and this is the trace file then , database side processing took only 16 mins out of that rest of the time to be checked separately , it might be
1. XML processing for a report ( Output post processor)
2. Writing to some files etc
Which is not a server side processing.
50 unique , 351 sql statements , 350 internal all this information has strong co-relation and you'll undertand it more as you go through several variety of tkprof files. Based on that one can develop his/her own art of catching trends ( that is what experience will teach you!!)
2. The second thing that is worth looking at is Recursive/Non-Recursive break up
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.04 0.05 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 159.20 259.48 30408 112839 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 159.24 259.53 30408 112839 0 10
Misses in library cache during parse: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 131 0.04 0.05 0 0 0 0
Execute 1721074 36.96 36.06 0 0 0 0
Fetch 2778885 148.74 683.91 109268 11974446 0 2498334
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4500090 185.74 720.03 109268 11974446 0 2498334
Misses in library cache during parse: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 131 0.04 0.05 0 0 0 0
Execute 1721074 36.96 36.06 0 0 0 0
Fetch 2778885 148.74 683.91 109268 11974446 0 2498334
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4500090 185.74 720.03 109268 11974446 0 2498334
Here you'll realize that total 683.91 seconds are spent in fetching 2498334 rows in all and which is biggest chunck ( out of 984 seconds, around 70% ) So it is worth attacking this recursive ( sequential logic which spends most of the time in fetching ) statements than non recursive. At this time the wild guess in observation 1 is more supported and is more concrete conclusion. But in a nutshell all that is required is to narrow down between recursive vs non- recursive. In 70% of the time you will find the logic skewed to either side of these to paradigms , challenge comes when both are almost same.
3. The third thing to look for is individual queries that are not performing good and checking element of wait ( Remember service time = execution/fetch + wait time)
Look at following example ,
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2090 0.08 0.09 0 0 0 0
Fetch 2090 72.87 73.68 159 12323851 0 2090
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4181 72.95 73.77 159 12323851 0 2090
We are fetching 2090 rows with 2090 execute and fetch operations and almost all of the time spent is in fetch if you look at wait events table below you'll realize that there's no place where it is waited even for 1 second ( Look at Total waited column)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
ges message buffer allocation 883 0.00 0.00
gc cr block 2-way 638 0.00 0.33
db file sequential read 159 0.03 0.46
gc current grant busy 104 0.00 0.09
gc cr block 3-way 11 0.00 0.00
gc cr grant 2-way 15 0.00 0.00
gc cr block busy 17 0.02 0.09
asynch descriptor resize 4180 0.00 0.01
gc current block 2-way 10 0.00 0.00
gc current block 3-way 7 0.00 0.00
gc current grant 2-way 3 0.00 0.00
latch: cache buffers chains 1 0.00 0.00
gc cr block congested 6 0.00 0.00
********************************************************************************
At this point you should be able to at least attribute the query to either DBA or to developer ( if you see waits on higher side , It's DBA to work on otherwise Developer) This was very optimistic example having no wait in real life things will be diferent. Like one below.
INSERT INTO FND_LOG_MESSAGES ( ECID_ID, ECID_SEQ, CALLSTACK, ERRORSTACK, MODULE, LOG_LEVEL, MESSAGE_TEXT, SESSION_ID, USER_ID, TIMESTAMP, LOG_SEQUENCE, ENCODED, NODE, NODE_IP_ADDRESS, PROCESS_ID, JVM_ID, THREAD_ID, AUDSID, DB_INSTANCE, TRANSACTION_CONTEXT_ID ) VALUES ( SYS_CONTEXT('USERENV', 'ECID_ID'), SYS_CONTEXT('USERENV', 'ECID_SEQ'), :B16 , :B15 , SUBSTRB(:B14 ,1,255), :B13 , SUBSTRB(:B12 , 1, 4000), :B11 , NVL(:B10 , -1), SYSDATE, FND_LOG_MESSAGES_S.NEXTVAL, :B9 , SUBSTRB(:B8 ,1, 60), SUBSTRB(:B7 ,1,30), SUBSTRB(:B6 ,1,120), SUBSTRB(:B5 ,1,120), SUBSTRB(:B4 ,1,120), :B3 , :B2 , :B1 ) RETURNING LOG_SEQUENCE INTO :O0
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 17626 24.75 818.40 1208 36758 318289 17626
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 17628 24.75 818.40 1208 36758 318289 17626
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
row cache lock 68 0.01 0.08
ges message buffer allocation 5754 0.00 0.02
library cache lock 48 0.00 0.02
library cache pin 261 0.00 0.11
gc current block 2-way 501 0.01 0.45
gc buffer busy acquire 5746 1.00 91.90
gc current block 3-way 189 0.01 0.19
gc current block busy 1433 1.01 21.06
gc current grant 2-way 211 0.00 0.08
db file sequential read 333 0.06 1.96
gc current split 94 0.09 0.68
enq: TX - index contention 1520 2.10 64.11
buffer busy waits 2474 1.08 4.23
gc current block congested 3 0.00 0.00
read by other session 46 0.04 0.36
buffer deadlock 2337 0.00 0.03
gc buffer busy release 1207 0.93 23.78
gc cr block 2-way 561 0.00 0.22
KJC: Wait for msg sends to complete 91 0.00 0.00
latch: ges resource hash list 402 0.00 0.03
gc cr block 3-way 19 0.00 0.01
enq: HW - contention 36 0.00 0.01
enq: TT - contention 12 0.00 0.00
gc current grant busy 297 0.11 2.56
enq: FB - contention 6 0.00 0.00
lock deadlock retry 87 0.00 0.00
latch: cache buffers chains 1166 0.00 0.08
gc current retry 16 0.03 0.10
lock escalate retry 11 0.00 0.00
enq: TX - allocate ITL entry 19 0.12 0.44
global enqueue expand wait 14 0.01 0.13
gc cr block busy 36 0.00 0.11
latch: gc element 8 0.00 0.00
enq: SQ - contention 23 0.02 0.11
latch: enqueue hash chains 7 0.00 0.00
enq: TX - contention 2 0.01 0.02
gc current multi block request 21 0.00 0.00
library cache: mutex X 7 0.00 0.00
wait list latch free 1 0.01 0.01
enq: TO - contention 1 0.00 0.00
gc cr block congested 1 0.00 0.00
gc current request 1 1.27 1.27
latch: redo allocation 1 0.00 0.00
latch: gcs resource hash 1 0.00 0.00
latch: session allocation 1 0.00 0.00
log file switch completion 1 0.07 0.07
********************************************************************************
Here following out of 818 seconds spent in inserting a record
91.90 are spent in gc buffer busy acquire
21.06 in gc current block busy
64.11 on enq: TX - index contention
23.78 on gc buffer busy release
So overall 200 seconds was wait time in 818 seconds transaction which attributes to 25% and all to be looked at by DBA
4. If sort options for the tkprofed file are default ( in point 1 we saw the summary where sort order is mentioned) , you need to look for the expensive queries by looking at total of each piece. My personal recommendation is to have 2 txt files
1 with default sort order ( this enables you to understad the flow with code) and second with prsela,exeela,fchela sort option.
5. The general guideline to estimate effort is
a. More the no of sql statements in file more the time/effort
b More the effort of changing code/design if the break up of non-recursive/recursive is towards recursive
c. More effort is required on tuning individual query/queries if the breakup is skewed towrds non-recursive
d. More DBA effort is invovled if the wait time is significant of the total time
e. More queries with high time will lead to more places to be tuned
This is a pattern for 80% of the cases bottmline... Devil is in the details so quick estimate is just a quick and dirty estimate estimate that will mostly (not always) work
I assume the readers have following background information
1. How to generate a Oracle trace
2. How to locate and identify Oracle trace file
3. How to convert it in verbose ( more readable format using tkprof utility)
Often asked question to DBAs is what is it that I should look for in tkprofed trace file.
4. Version and release of Oracle I am talking about is 10g and on.
5. Fundamental of wait event 10046 and sql tuning
When you get a trace file you need to get to the bottom of it ( great things start bottom up ) .....
1st and foremost thing to look for in a tkprof file of a concurrent program is
the summary at the bottom of the tkprof.
eg
Trace file: mydb_ora_36567.trc
Trace file compatibility: 10.01.00
Sort options: default
1 session in tracefile.
1 user SQL statements in trace file.
350 internal SQL statements in trace file.
351 SQL statements in trace file.
50 unique SQL statements in trace file.
4502290 lines in trace file.
984 elapsed seconds in trace file.
And what does this mean , 984 seconds is the total taime recorded in database.
which is 16 mins and 14 seconds. So if my target for improving the performance is say 5 mins , I am 11 mins away from where I should be.
The second thing you should look at is 4502290 lines in trace file. Which means there's whole lot of iterative fetches happening. Whic tells me that there's quite a sequential fetch logic (recursive) without even looking at the program.
Although I concluded lot of sequential fetching it's not always the case hence 50 unique sql statements is something worth considering. Also note than in Apps envrionment if someone tells you that the program ran for 22 mins or 30 mins and this is the trace file then , database side processing took only 16 mins out of that rest of the time to be checked separately , it might be
1. XML processing for a report ( Output post processor)
2. Writing to some files etc
Which is not a server side processing.
50 unique , 351 sql statements , 350 internal all this information has strong co-relation and you'll undertand it more as you go through several variety of tkprof files. Based on that one can develop his/her own art of catching trends ( that is what experience will teach you!!)
2. The second thing that is worth looking at is Recursive/Non-Recursive break up
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.04 0.05 0 0 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 2 159.20 259.48 30408 112839 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 159.24 259.53 30408 112839 0 10
Misses in library cache during parse: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 131 0.04 0.05 0 0 0 0
Execute 1721074 36.96 36.06 0 0 0 0
Fetch 2778885 148.74 683.91 109268 11974446 0 2498334
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4500090 185.74 720.03 109268 11974446 0 2498334
Misses in library cache during parse: 1
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 131 0.04 0.05 0 0 0 0
Execute 1721074 36.96 36.06 0 0 0 0
Fetch 2778885 148.74 683.91 109268 11974446 0 2498334
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4500090 185.74 720.03 109268 11974446 0 2498334
Here you'll realize that total 683.91 seconds are spent in fetching 2498334 rows in all and which is biggest chunck ( out of 984 seconds, around 70% ) So it is worth attacking this recursive ( sequential logic which spends most of the time in fetching ) statements than non recursive. At this time the wild guess in observation 1 is more supported and is more concrete conclusion. But in a nutshell all that is required is to narrow down between recursive vs non- recursive. In 70% of the time you will find the logic skewed to either side of these to paradigms , challenge comes when both are almost same.
3. The third thing to look for is individual queries that are not performing good and checking element of wait ( Remember service time = execution/fetch + wait time)
Look at following example ,
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 2090 0.08 0.09 0 0 0 0
Fetch 2090 72.87 73.68 159 12323851 0 2090
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4181 72.95 73.77 159 12323851 0 2090
We are fetching 2090 rows with 2090 execute and fetch operations and almost all of the time spent is in fetch if you look at wait events table below you'll realize that there's no place where it is waited even for 1 second ( Look at Total waited column)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
ges message buffer allocation 883 0.00 0.00
gc cr block 2-way 638 0.00 0.33
db file sequential read 159 0.03 0.46
gc current grant busy 104 0.00 0.09
gc cr block 3-way 11 0.00 0.00
gc cr grant 2-way 15 0.00 0.00
gc cr block busy 17 0.02 0.09
asynch descriptor resize 4180 0.00 0.01
gc current block 2-way 10 0.00 0.00
gc current block 3-way 7 0.00 0.00
gc current grant 2-way 3 0.00 0.00
latch: cache buffers chains 1 0.00 0.00
gc cr block congested 6 0.00 0.00
********************************************************************************
At this point you should be able to at least attribute the query to either DBA or to developer ( if you see waits on higher side , It's DBA to work on otherwise Developer) This was very optimistic example having no wait in real life things will be diferent. Like one below.
INSERT INTO FND_LOG_MESSAGES ( ECID_ID, ECID_SEQ, CALLSTACK, ERRORSTACK, MODULE, LOG_LEVEL, MESSAGE_TEXT, SESSION_ID, USER_ID, TIMESTAMP, LOG_SEQUENCE, ENCODED, NODE, NODE_IP_ADDRESS, PROCESS_ID, JVM_ID, THREAD_ID, AUDSID, DB_INSTANCE, TRANSACTION_CONTEXT_ID ) VALUES ( SYS_CONTEXT('USERENV', 'ECID_ID'), SYS_CONTEXT('USERENV', 'ECID_SEQ'), :B16 , :B15 , SUBSTRB(:B14 ,1,255), :B13 , SUBSTRB(:B12 , 1, 4000), :B11 , NVL(:B10 , -1), SYSDATE, FND_LOG_MESSAGES_S.NEXTVAL, :B9 , SUBSTRB(:B8 ,1, 60), SUBSTRB(:B7 ,1,30), SUBSTRB(:B6 ,1,120), SUBSTRB(:B5 ,1,120), SUBSTRB(:B4 ,1,120), :B3 , :B2 , :B1 ) RETURNING LOG_SEQUENCE INTO :O0
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 17626 24.75 818.40 1208 36758 318289 17626
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 17628 24.75 818.40 1208 36758 318289 17626
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
row cache lock 68 0.01 0.08
ges message buffer allocation 5754 0.00 0.02
library cache lock 48 0.00 0.02
library cache pin 261 0.00 0.11
gc current block 2-way 501 0.01 0.45
gc buffer busy acquire 5746 1.00 91.90
gc current block 3-way 189 0.01 0.19
gc current block busy 1433 1.01 21.06
gc current grant 2-way 211 0.00 0.08
db file sequential read 333 0.06 1.96
gc current split 94 0.09 0.68
enq: TX - index contention 1520 2.10 64.11
buffer busy waits 2474 1.08 4.23
gc current block congested 3 0.00 0.00
read by other session 46 0.04 0.36
buffer deadlock 2337 0.00 0.03
gc buffer busy release 1207 0.93 23.78
gc cr block 2-way 561 0.00 0.22
KJC: Wait for msg sends to complete 91 0.00 0.00
latch: ges resource hash list 402 0.00 0.03
gc cr block 3-way 19 0.00 0.01
enq: HW - contention 36 0.00 0.01
enq: TT - contention 12 0.00 0.00
gc current grant busy 297 0.11 2.56
enq: FB - contention 6 0.00 0.00
lock deadlock retry 87 0.00 0.00
latch: cache buffers chains 1166 0.00 0.08
gc current retry 16 0.03 0.10
lock escalate retry 11 0.00 0.00
enq: TX - allocate ITL entry 19 0.12 0.44
global enqueue expand wait 14 0.01 0.13
gc cr block busy 36 0.00 0.11
latch: gc element 8 0.00 0.00
enq: SQ - contention 23 0.02 0.11
latch: enqueue hash chains 7 0.00 0.00
enq: TX - contention 2 0.01 0.02
gc current multi block request 21 0.00 0.00
library cache: mutex X 7 0.00 0.00
wait list latch free 1 0.01 0.01
enq: TO - contention 1 0.00 0.00
gc cr block congested 1 0.00 0.00
gc current request 1 1.27 1.27
latch: redo allocation 1 0.00 0.00
latch: gcs resource hash 1 0.00 0.00
latch: session allocation 1 0.00 0.00
log file switch completion 1 0.07 0.07
********************************************************************************
Here following out of 818 seconds spent in inserting a record
91.90 are spent in gc buffer busy acquire
21.06 in gc current block busy
64.11 on enq: TX - index contention
23.78 on gc buffer busy release
So overall 200 seconds was wait time in 818 seconds transaction which attributes to 25% and all to be looked at by DBA
4. If sort options for the tkprofed file are default ( in point 1 we saw the summary where sort order is mentioned) , you need to look for the expensive queries by looking at total of each piece. My personal recommendation is to have 2 txt files
1 with default sort order ( this enables you to understad the flow with code) and second with prsela,exeela,fchela sort option.
5. The general guideline to estimate effort is
a. More the no of sql statements in file more the time/effort
b More the effort of changing code/design if the break up of non-recursive/recursive is towards recursive
c. More effort is required on tuning individual query/queries if the breakup is skewed towrds non-recursive
d. More DBA effort is invovled if the wait time is significant of the total time
e. More queries with high time will lead to more places to be tuned
This is a pattern for 80% of the cases bottmline... Devil is in the details so quick estimate is just a quick and dirty estimate estimate that will mostly (not always) work
