Tales From A Lazy Fat DBA

TKPROF:
————————–
TKProf is oracle provided trace reading utility which converts results in to more human readable format.
It required one to Enable SQL_Trace and set TIMED_Statistics which helps Oracle to create trace files with extra information.

Example:
SQL> alter session set timed_statistics = true;
Session altered.

SQL> alter session set sql_trace = true;
Session altered.

I’ve created a query to find my Oracle Server process id:
SELECT p.spid oracle_dedicated_process, s.process clientpid FROM v$process p, v$session s WHERE p.addr = s.paddr AND s.sid = (select sid from v$mystat where rownum = 1);

ORACLE_DEDIC CLIENTPID
———— ————
11653        11636

SQL> select * from scott.emp where job=’CLERK’;

EMPNO ENAME      JOB              MGR HIREDATE         SAL       COMM     DEPTNO
———- ———- ——— ———- ——— ———- ———- ———-
7369 SMITH      CLERK           7902 17-DEC-80        800                    20
7876 ADAMS      CLERK           7788 23-MAY-87       1100                    20
7900 JAMES      CLERK           7698 03-DEC-81        950                    30
7934 MILLER     CLERK           7782 23-JAN-82       1300                    10

[oracle@localhost udump]$ ls -ltr
total 128

-rw-r—– 1 oracle oinstall   635 Jan 17 23:05 orcl_ora_11331.trc
-rw-r—– 1 oracle oinstall   692 Jan 17 23:05 orcl_ora_11358.trc
-rw-r—– 1 oracle oinstall 21454 Jan 17 23:08 orcl_ora_11359.trc
-rw-r—– 1 oracle oinstall  2862 Jan 17 23:31 orcl_ora_11653.trc

[oracle@localhost udump]$ tkprof orcl_ora_11653.trc Prashant_tkprof_study.txt

TKPROF: Release 10.2.0.1.0 – Production on Thu Jan 17 23:32:41 2013
Copyright (c) 1982, 2005, Oracle.  All rights reserved.

[oracle@localhost udump]$ ls -ltr
total 145

-rw-r–r– 1 oracle oinstall  5925 Jan 17 23:32 Prashant_tkprof_study.txt

 
[oracle@localhost udump]$ cat Prashant_tkprof_study.txt

TKPROF: Release 10.2.0.1.0 – Production on Thu Jan 17 23:32:41 2013

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

Trace file: orcl_ora_11653.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
********************************************************************************

alter session set sql_trace = true

call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        0      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
——- ——  ——– ———- ———- ———- ———-  ———-
total        1      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: SYS
********************************************************************************

SELECT p.spid oracle_dedicated_process, s.process clientpid
FROM
v$process p, v$session s WHERE p.addr = s.paddr AND s.sid = (select sid from
v$mystat where rownum = 1)

call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        1      0.01       0.01          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          0          0           1
——- ——  ——– ———- ———- ———- ———-  ———-
total        4      0.01       0.01          0          0          0           1

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

Rows     Row Source Operation
——-  —————————————————
1  NESTED LOOPS  (cr=0 pr=0 pw=0 time=2133 us)
1   HASH JOIN  (cr=0 pr=0 pw=0 time=2511 us)
1    FIXED TABLE FULL X$KSUSE (cr=0 pr=0 pw=0 time=643 us)
1     COUNT STOPKEY (cr=0 pr=0 pw=0 time=20 us)
1      FIXED TABLE FULL X$KSUMYSTA (cr=0 pr=0 pw=0 time=14 us)
1       FIXED TABLE FULL X$KSUSGIF (cr=0 pr=0 pw=0 time=4 us)
20    FIXED TABLE FULL X$KSUPR (cr=0 pr=0 pw=0 time=43 us)
1   FIXED TABLE FIXED INDEX X$KSLED (ind:2) (cr=0 pr=0 pw=0 time=6 us)

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

select *
from
scott.emp where job=’CLERK’

call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          8          0           4
——- ——  ——– ———- ———- ———- ———-  ———-
total        4      0.00       0.00          0          8          0           4

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

Rows     Row Source Operation
——-  —————————————————
4  TABLE ACCESS FULL EMP (cr=8 pr=0 pw=0 time=388 us)

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

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        2      0.01       0.01          0          0          0           0
Execute      3      0.00       0.00          0          0          0           0
Fetch        4      0.00       0.00          0          8          0           5
——- ——  ——– ———- ———- ———- ———-  ———-
total        9      0.01       0.02          0          8          0           5

Misses in library cache during parse: 2
Misses in library cache during execute: 1

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
——- ——  ——– ———- ———- ———- ———-  ———-
Parse        0      0.00       0.00          0          0          0           0
Execute      0      0.00       0.00          0          0          0           0
Fetch        0      0.00       0.00          0          0          0           0
——- ——  ——– ———- ———- ———- ———-  ———-
total        0      0.00       0.00          0          0          0           0

Misses in library cache during parse: 0

3  user  SQL statements in session.
0  internal SQL statements in session.
3  SQL statements in session.
********************************************************************************
Trace file: orcl_ora_11653.trc
Trace file compatibility: 10.01.00
Sort options: default

1  session in tracefile.
3  user  SQL statements in trace file.
0  internal SQL statements in trace file.
3  SQL statements in trace file.
3  unique SQL statements in trace file.
48  lines in trace file.
35  elapsed seconds in trace file.