How to generate a trace file for a concurrent program

During program build/development phase developers focus on getting the program functionality correct from all aspects. Once the program goes into production and starts running, users look first at the output of the program and then at the performance. Sometimes some programs are sent back to the user for improving the performance of the program if the user finds that the program takes too long to complete.

To start the tuning process it is best to get a trace file from the program. The method of getting the trace file for a concurrent program is detailed below.

Step 1: Enable trace on the concurrent program

Responsibility: System Administrator

Navigation: Concurrent > Program > Define

Query for the concurrent program

Check the box labeled, Enable Trace, .

Save the form.

Step 2: Execute the concurrent program

Go to the responsibility from which you can execute the concurrent program. Click on View > Requests and open the SRS form. Run the concurrent program.

Submit the request.

Note the request ID. It is 18068414.

Step 3: Locate the trace file directory

Connect to the database and execute the following SQL,

1 2 3

SELECT *   FROM v$parameter  WHERE NAME = 'user_dump_dest'

You will get the directory where the trace files are created by Oracle. It will be under value column. We get the value as,/d02/oraprod/proddb/11.2.0/admin/DEV_eyerpqa/diag/rdbms/dev/DEV/trace.

Now get the Oracle process ID for this request. Execute the following script

1 2 3

SELECT oracle_process_id   FROM fnd_concurrent_requests  WHERE request_id = 18068414

We get the Oracle Process ID as 17156

Step 4: Get the trace file

Login to Unix. We need to go the trace file directory we found earlier. Execute the following command to change the directory.

1	$ cd /d02/oraprod/proddb/11.2.0/admin/DEV_eyerpqa/diag/rdbms/dev/DEV/trace

Now we shall search for the trace file within this directory. The trace file will contain the Oracle Process ID and the schema name. Hence the trace file will be named *17156*APPS*.trc. Let us search for the file using the following command.

1	$ ls –ltr *17156*APPS*.trc

We now get the actual name of the trace file. It is DEV_ora_17156_APPS.trc.

Open the trace file using read only VI editor (view editor)

1	$ view DEV_ora_17156_APPS.trc

This is the beginning of the huge trace file. We shall use TKPROF utility given by Oracle to make the file readable.

Step 5: Use TKPROF

On the Unix command execute TKPROF without any parameter and you will get the list of switches that can be used with this utility.

1

$ tkprof

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67

Usage: tkprof tracefile outputfile [explain= ] [table= ] [print= ] [insert= ] [sys= ] [sort= ] table=schema.tablename Use 'schema.tablename' with 'explain=' option. explain=user/password Connect to ORACLE and issue EXPLAIN PLAN. print=integer List only the first 'integer' SQL statements. aggregate=yes|no insert=filename List SQL statements and data inside INSERT statements. sys=no TKPROF does not list SQL statements run as user SYS. record=filename Record non-recursive statements found in the trace file. waits=yes|no Record summary for any wait events found in the trace file. sort=option Set of zero or more of the following sort options: prscnt number of times parse was called prscpu cpu time parsing prsela elapsed time parsing prsdsk number of disk reads during parse prsqry number of buffers for consistent read during parse prscu number of buffers for current read during parse prsmis number of misses in library cache during parse execnt number of execute was called execpu cpu time spent executing exeela elapsed time executing exedsk number of disk reads during execute exeqry number of buffers for consistent read during execute execu number of buffers for current read during execute exerow number of rows processed during execute exemis number of library cache misses during execute fchcnt number of times fetch was called fchcpu cpu time spent fetching fchela elapsed time fetching fchdsk number of disk reads during fetch fchqry number of buffers for consistent read during fetch fchcu number of buffers for current read during fetch fchrow number of rows fetched userid userid of user that parsed the cursor

We shall get the tkprof output with the following command

1	$ tkprof DEV_ora_17156_APPS.trc program.tkp

Open the tkprof output using view command. The file will look like the following,

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275

TKPROF: Release 11.2.0.1.0 - Development on Sun Jul 22 16:20:03 2012 Copyright (c) 1982, 2009, Oracle and/or its affiliates. All rights reserved. Trace file: DEV_ora_17156_APPS.trc Sort options: default ******************************************************************************** count = number of times OCI procedure was executed cpu = cpu time in seconds executing elapsed = elapsed time in seconds executing disk = number of physical reads of buffers from disk query = number of buffers gotten for consistent read current = number of buffers gotten in current mode (usually for update) rows = number of rows processed by the fetch or execute call ******************************************************************************** SQL ID: 4g2612tvbn0j8 Plan Hash: 0 begin FND_TRACE.START_TRACE; end; call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 0 0.00 0.00 0 0 0 0 Execute 1 0.05 0.04 0 0 0 1 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 1 0.05 0.04 0 0 0 1 Misses in library cache during parse: 0 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: 44 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 1 0.00 0.00 SQL*Net message from client 1 0.00 0.00 ******************************************************************************** SQL ID: 8w57t3xaxs89k Plan Hash: 3712617803 SELECT NAME, VERSION FROM FND_CACHE_VERSIONS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 0 0.00 0.00 0 0 0 0 Execute 16 0.00 0.00 0 0 0 0 Fetch 16 0.00 0.00 0 16 0 128 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 32 0.00 0.00 0 16 0 128 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 44 (recursive depth: 1) ******************************************************************************** ……. ……. …….. SQL ID: 2b5134r46d3pf Plan Hash: 3299112255 UPDATE AP_CHECKS SET ATTRIBUTE13='Y' WHERE DOC_SEQUENCE_VALUE BETWEEN :b1 AND :b2 AND ORG_ID = FND_PROFILE.VALUE('ORG_ID') call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.02 0 0 0 0 Execute 1 0.38 1.76 528 18662 3 1 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 0.38 1.79 528 18662 3 1 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: 44 Rows Row Source Operation ------- --------------------------------------------------- 0 UPDATE AP_CHECKS_ALL (cr=18662 pr=528 pw=0 time=0 us) 1 FILTER (cr=18662 pr=528 pw=0 time=0 us) 1 TABLE ACCESS FULL AP_CHECKS_ALL (cr=18662 pr=528 pw=0 time=0 us cost=5319 size=12 card=1) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 3 0.00 0.00 SQL*Net message from client 3 0.00 0.00 Disk file operations I/O 52 0.00 0.01 db file sequential read 257 0.04 0.93 db file scattered read 36 0.05 0.22 latch: cache buffers chains 1 0.00 0.00 ******************************************************************************** OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 9 0.03 0.11 0 0 0 0 Execute 24 15.90 18.56 528 18665 3 20 Fetch 5 0.10 3.21 409 777 0 257 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 38 16.03 21.89 937 19442 3 277 Misses in library cache during parse: 5 Misses in library cache during execute: 3 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 41 0.00 0.00 SQL*Net message from client 41 0.49 1.07 db file sequential read 666 0.07 4.04 asynch descriptor resize 1 0.00 0.00 Disk file operations I/O 87 0.00 0.01 SQL*Net more data to client 8 0.00 0.00 SQL*Net more data from client 1 0.06 0.06 db file scattered read 36 0.05 0.22 latch: cache buffers chains 1 0.00 0.00 log file sync 1 0.00 0.00 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 564 0.33 1.39 0 0 0 0 Execute 1546 0.57 1.20 0 40 5 5 Fetch 3581 0.80 2.78 346 7065 0 4512 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 5691 1.70 5.38 346 7105 5 4517 Misses in library cache during parse: 81 Misses in library cache during execute: 60 Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 4 0.00 0.00 SQL*Net message from client 4 0.00 0.00 db file sequential read 346 0.04 1.78 asynch descriptor resize 40 0.00 0.00 199 user SQL statements in session. 1364 internal SQL statements in session. 1563 SQL statements in session. ******************************************************************************** Trace file: DEV_ora_17156_APPS.trc Trace file compatibility: 11.1.0.7 Sort options: default 1 session in tracefile. 199 user SQL statements in trace file. 1364 internal SQL statements in trace file. 1563 SQL statements in trace file. 101 unique SQL statements in trace file. 16242 lines in trace file. 28 elapsed seconds in trace file.

I have compressed the TKPROF output to the beginning and the ending. Actually the TKPROF output is more than 3500 lines. By going through the TKPROF output we can identify which SQL(s) in the concurrent program need(s) to be tuned for performance.