Sql_trace and Tkprof Analysis

I. Sql_trace

When the SQL statement performance problem, we can use Sql_trace to track the execution of SQL, through the trace, we can understand the operation of a SQL or PL $ package, the Sql_trace command will be the entire SQL execution process output to a trace file, We can read this trace file to see what Oracle has done during this SQL execution.

You can start sql_trace with the SQL command, or in the initialization parameters.

Sql>alter session Set Sql_trace=true;

Or

sql> ALTER DATABASE set sql_trace=true;

The difference between the two commands:

At the session level, only the current session is tracked, and at the instance level, all SQL on the instance is tracked, which tracks too many SQL, at a very high cost, and is seldom used.

If it is set in the initialization file, simply add a sql_trace parameter to the parameter file.

Example:

1 SQL command to start sql_trace

Sql> alter session set Sql_trace=true;

Session altered.

2 by setting the trace file identity

Sql> alter session set tracefile_identifier= ' Andy ';

Session altered.

The purpose of setting the identity is to make it easier for us to find the generated trace file. We just need to find the file with the ID in the trace directory. In ORACLE 10g, the trace file generated by Sql_trace is $oracle_base/admin/sid/udump.

To the 11g,trace default path in: $ORACLE _base/diag/rdbms/orcl/orcl/trace directory.

3. Directly with the following SQL directly detected, the current trace file name.

Sql> SELECT * from v$diag_info where name like ' default% ';

inst_id NAME
---------- ----------------------------------------------------------------
VALUE
--------------------------------------------------------------------------------
1 Default Trace File
/home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc

4. Perform related transaction operations

Sql> select * from T;

5. Close Sql_trace

Sql> alter session set Sql_trace=false;

The session has changed.

Note that here is the display of the closed Sql_trace, at the session level, or you can exit Sqlplus directly to terminate the Sql_trace.

——————————————————————————————————————

6. View the trace file (original view, i.e. not using the Tkprof tool)

If you want to know exactly what each step of the SQL statement is doing, you need to parse the original trace file. Although this trace is easy to read without the Tkprof tool, it is clear to know what SQL does at that point and how SQL works, which is useful for understanding the execution of SQL statements.

Open/HOME/ORACLE/APP/DIAG/RDBMS/ORCL/ORCL/TRACE/ORCL_ORA_24020_ANDY.TRC file directly:

T[[email protected] ~]$ VI/HOME/ORACLE/APP/DIAG/RDBMS/ORCL/ORCL/TRACE/ORCL_ORA_24020_ANDY.TRC

Trace FILE/HOME/ORACLE/APP/DIAG/RDBMS/ORCL/ORCL/TRACE/ORCL_ORA_24020_ANDY.TRC
Oracle Database 11g Enterprise Edition Release 11.2.0.1.0-64bit Production
With the partitioning, OLAP, Data Mining and Real application testing options
Oracle_home =/home/oracle/app/oracle/product/11.2.0/dbhome_1
System Name:linux
Node name:11g
Release:2.6.32-573.el6.x86_64
Version: #1 SMP Thu Jul 15:44:03 UTC 2015
Machine:x86_64
Oracle Process number:19
Unix process pid:24020, Image: [email protected] (TNS v1-v3)

。。。。。 Omit output

2014-11-17 08:06:08.981
CLOSE #1: c=0,e=14,dep=0,type=1,tim=1416229568981377
=====================
Parsing in CURSOR #1 len=23 dep=0 uid=0 oct=3 lid=0 tim=1416229568981763 hv=665675061 ad= ' 87d2dfb0 ' sqlid= ' ckyh1gcmuut9p '
SELECT * FROM Dba_users
END of STMT
PARSE #1: c=0,e=291,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3422547789,tim=1416229568981762
EXEC #1: c=0,e=135,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3422547789,tim=1416229568981961
FETCH #1: c=4000,e=3231,p=0,cr=52,cu=0,mis=0,r=1,dep=0,og=1,plh=3422547789,tim=1416229568985261
FETCH #1: c=0,e=67,p=0,cr=1,cu=0,mis=0,r=15,dep=0,og=1,plh=3422547789,tim=1416229568985934
FETCH #1: c=0,e=64,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=3422547789,tim=1416229569004724
FETCH #1: c=0,e=83,p=0,cr=1,cu=0,mis=0,r=4,dep=0,og=1,plh=3422547789,tim=1416229569022491
STAT #1 id=1 cnt=35 pid=0 pos=1 obj=0 op= ' HASH JOIN (cr=54 pr=0 pw=0 time=0 US cost=26 size=2664 card=12) '
STAT #1 id=2 cnt=35 pid=1 pos=1 obj=0 op= ' HASH JOIN (cr=49 pr=0 pw=0 time=0 US cost=24 size=2436 card=12) '
STAT #1 id=3 cnt=35 pid=2 pos=1 obj=0 op= ' HASH JOIN (cr=34 pr=0 pw=0 time=34 US cost=18 size=2316 card=12) '
STAT #1 id=4 cnt=35 pid=3 pos=1 obj=0 op= ' HASH JOIN OUTER (cr=19 pr=0 pw=0 time=68 US cost=13 size=2196 card=12) '
STAT #1 id=5 cnt=35 pid=4 pos=1 obj=0 op= ' HASH JOIN (cr=16 pr=0 pw=0 time=0 US cost=10 size=1740 card=12) '
STAT #1 id=6 cnt=35 pid=5 pos=1 obj=0 op= ' HASH JOIN (cr=13 pr=0 pw=0 time=136 US cost=8 size=1620 card=12) '
STAT #1 id=7 cnt=2 pid=6 pos=1 obj=0 op= ' MERGE JOIN Cartesian (cr=6 pr=0 pw=0 time=1 US cost=4 size=26 card=1) '
STAT #1 id=8 cnt=1 pid=7 pos=1 obj=280 op= ' TABLE ACCESS full profile$ (cr=3 pr=0 pw=0 time=0 US cost=2 size=13 card=1) '
STAT #1 id=9 cnt=2 pid=7 pos=2 obj=0 op= ' BUFFER SORT (cr=3 pr=0 pw=0 time=1 US cost=2 size=13 card=1) '
STAT #1 id=10 cnt=2 pid=9 pos=1 obj=280 op= ' TABLE ACCESS full profile$ (cr=3 pr=0 pw=0 time=1 US cost=2 size=13 card=1) '
STAT #1 id=11 cnt=35 pid=6 pos=2 obj=22 op= ' TABLE ACCESS full user$ (cr=7 pr=0 pw=0 time=102 US cost=3 size=3597 card=33) '
STAT #1 id=12 cnt=2 pid=5 pos=2 obj=281 op= ' TABLE ACCESS full profname$ (cr=3 pr=0 pw=0 time=1 US cost=2 size=10 card=1) '
STAT #1 id=13 cnt=2 pid=4 pos=2 obj=297 op= ' TABLE ACCESS full resource_group_mapping$ (cr=3 pr=0 pw=0 time=0 US cost=2 siz e=38 card=1) '
STAT #1 id=14 cnt=8 pid=3 pos=2 obj=16 op= ' TABLE ACCESS full ts$ (cr=15 pr=0 pw=0 time=105 US cost=5 size=80 card=8) '
STAT #1 id=15 cnt=8 pid=2 pos=2 obj=16 op= ' TABLE ACCESS full ts$ (cr=15 pr=0 pw=0 time=14 US cost=5 size=80 card=8) '
STAT #1 id=16 cnt=9 pid=1 pos=2 obj=292 op= ' TABLE ACCESS full User_astatus_map (cr=5 pr=0 pw=0 time=0 US cost=2 size=171 C ard=9) '

This file is much less readable. Some of these parameters are explained:

Parsing in CURSOR section: Parse,exec,fetch part STATS section:

Len: Length of parsed SQL C: CPU time Id consumed: line source number of execution plan
DEP: Produces a recursive SQL e:elapsed time operation time Cnt: The number of rows returned by the current row source

Uid:user ID p:physical reads number of physical reads Pid: The parent of the current line source number

otc:oracle command type cr:consistent reads consistent read data block Pos: Execution Plan location

Lid: Private User ID cu:current read Data block OBJ: Object ID of the current operation (if the current row is the original object)

Tim: Timestamp mis:cursor misss in cache hard Parse count Op: Data access operation for the current row source

Hv:hash value R: Number of rows processed by-rows

Ad:sql address dep:depth The depth of recursive SQL

Og:optimizer Goal Optimizer mode

Tim:timestamp time Stamp

Two TKPROF Tools

Sql_trace produces the most primitive trace files with poor readability, so we usually use the Tkprof tool to process trace files. The Tkprof tool is a tool that Oracle comes with to work with the original trace file, which is designed to consolidate some of the items in the trace file, normalize the format of the file, and make the file more readable.

Note: The Tkprof tool can only be used to process traces generated by sql_trace and 10046 events, and other events such as 10053 cannot be processed.

Tkprof is system-level and can be executed directly under the system. Let's take a look at Tkprof's help documentation:

[Email protected] ~]$ tkprof
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 all 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

This helps to explain the parameters of the Tkprof tool.

2.1 Explain=user/password

Enter the SQL execution plan in the trace file, and note that if you do not use explain, we see the actual execution brutishness (process) of SQL in the trace file. If you use Explain,tkprof to enter not only the actual execution path (procedure) of SQL in the trace file, the execution plan for that SQL is also generated.

2.2 Sys=no

If set to Yes, all of the SYS user's actions will be entered in the trace file, and the recursive SQL raised by the user's SQL statement will also be included.

If no, the information is not output. However, by default Yes, the trace file is more readable when it is actually set to No, so it is usually manually set to No when using the Tkprof tool.

2.3 Aggregate=yes|no

By default, the Tkprof tool merges all the same SQL into the input file and, if set to No, lists each SQL information separately. After the general merger looks relatively concise, if you need to view each SQL separate information, you can set the aggregate to No.

2.4 Using the Tkprof tool to view the trace files generated in

[Email protected] ~]$ TKPROF/HOME/ORACLE/APP/DIAG/RDBMS/ORCL/ORCL/TRACE/ORCL_ORA_24020_ANDY.TRC andy.txt sys=no

[Email protected] ~]$ VI andy.txt

Tkprof:release 11.2.0.1.0-development on Mon Nov 17 08:25:36 2014

Copyright (c) 1982, the Oracle and/or its affiliates. All rights reserved.

Trace File:/home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.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

********************************************************************************
# # above the header information describes the version information of the tkprof, and the meaning of some of the columns in the report

OVERALL TOTALS for all non-recursive statements #非递归SQL语句

Call count CPU Elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 3 0.00 0.00 0 0 0 0
Fetch 6 0.00 0.03 0 54 0 36
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Total 11 0.00 0.03 0 54 0 36

Misses in library cache during parse:0

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 #shared pool hit, instructions made 0 hard parsing.

2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.

Misses in library cache during parse:0

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

2 user SQL statements in session.
0 internal SQL statements in session.
2 SQL statements in session.
********************************************************************************
Trace File:/home/oracle/app/diag/rdbms/orcl/orcl/trace/orcl_ora_24020_andy.trc
Trace file compatibility:11.1.0.7
Sort Options:default

1 session in Tracefile.
2 user SQL statements in trace file.
0 internal SQL statements in trace file.
2 SQL statements in trace file.
2 Unique SQL statements in trace file.
lines in trace file.
1719 elapsed seconds in trace file.

OK, end.

Sql_trace and Tkprof Analysis