12 | 12 | 2017
Latest Articles
Popular Articles

Performance Tuning

Format your trace files with tkprof

User Rating:  / 0
PoorBest 

Format your trace files with tkprof.

 

We have seen it does not take a hero to enable session tracing with the event 10046 or to enable session tracing with the dbms_monitor package.

The trace files are generated in the user_dump_directory if we are running in dedicated server mode or in the background_dump_dest if we are running in shared server mode. Afterwards we can format the trace files with tkprof to have them in a readable format. The formatting itself is easy.

 

$ORACLE_HOME/bin/tkprof mydb_ora_4732.trc mydb_tracefile.txt

The mydb_tracefile.txt contains the formatted readble output as. The tuning work can start. Here you can find an example. I limit the output to the most relevant part. The most important wait event for the  select below - which makes use of the sql operator "with" - is the db file scattered read which is the wait event related to multiblock reads.

 

 ***********************************************************************************************************************************************
 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
 ***********************************************************************************************************************************************

 

*******************************************************************************************************

with
sum_records AS
( select /*+ MATERIALIZE */ count(*) records_per_country, CODE1_ID country from t_table1 group by CODE1_id),
avg_record_country AS
( select /*+ MATERIALIZE */ avg(nr_records) avg_records from
(select count(*) nr_records,CODE1_ID from t_table1
group by CODE1_ID) )
select records_per_country, country from sum_records, avg_record_country
where
records_per_country > avg_records

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.04 0.02 46 2282 2 0
Execute 1 2.46 6.30 3798 8265 14 0
Fetch 3 0.00 0.00 2 12 2 16
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 2.50 6.33 3846 10559 18 16

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 2130

Rows Row Source Operation
------- ---------------------------------------------------
16 TEMP TABLE TRANSFORMATION (cr=8277 pr=3800 pw=2 time=6308530 us)
1 LOAD AS SELECT (cr=4218 pr=3798 pw=1 time=5205786 us)
28 HASH GROUP BY (cr=4127 pr=3798 pw=0 time=5185388 us)
1059274 INDEX FAST FULL SCAN C_NX_REC_CODE1 (cr=3956 pr=3798 pw=0 time=4248018 us)(object id 3012824)
1 LOAD AS SELECT (cr=4047 pr=0 pw=1 time=1102096 us)
1 SORT AGGREGATE (cr=3956 pr=0 pw=0 time=1082370 us)
28 VIEW (cr=3956 pr=0 pw=0 time=1082352 us)
28 SORT GROUP BY (cr=3956 pr=0 pw=0 time=1082318 us)
1059274 INDEX FAST FULL SCAN C_NX_REC_CODE1 (cr=3956 pr=0 pw=0 time=236 us)(object id 3012824)
16 NESTED LOOPS (cr=12 pr=2 pw=0 time=215 us)
1 VIEW (cr=5 pr=1 pw=0 time=117 us)
1 TABLE ACCESS FULL SYS_TEMP_0FD9D6602_DFD57EC4 (cr=5 pr=1 pw=0 time=112 us)
16 VIEW (cr=7 pr=1 pw=0 time=94 us)
28 TABLE ACCESS FULL SYS_TEMP_0FD9D6601_DFD57EC4 (cr=7 pr=1 pw=0 time=91 us)


Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 5 0.00 0.00
SQL*Net message from client 5 30.48 66.60
SQL*Net break/reset to client 2 0.00 0.00
control file sequential read 8 0.00 0.00
db file sequential read 4 0.00 0.01
db file scattered read 774 0.02 3.91
direct path write temp 2 0.00 0.00
log file sync 1 0.00 0.00