Oracle Performance Analysis: Enabling SQL tracking and obtaining trace files

Oracle Performance Analysis 1: Enabling SQL tracking and obtaining trace files when Oracle queries encounter efficiency problems, we often need to understand the problem so as to provide solutions to the problem. Oracle provides the trace information for SQL Execution, including the text information of SQL statements, execution statistics, waiting during processing, and parsing stages (such

Oracle Performance Analysis 1: Enabling SQL tracking and obtaining trace files when Oracle queries encounter efficiency problems, we often need to understand the problem so as to provide solutions to the problem. Oracle provides the trace information for SQL Execution, including the text information of SQL statements, execution statistics, waiting during processing, and parsing stages (such

Oracle Performance Analysis 1: Enabling SQL tracking and obtaining trace files

When there is an issue with Oracle query efficiency, we often need to understand the problem so that we can provide a solution to the problem. Oracle provides the trace information for SQL Execution, including the text information of SQL statements, execution statistics, waiting during processing, and information generated during the parsing phase (such as generating an execution plan. This information helps you break down the SQL statement service time and wait time, and learn more about the resources used and synchronization points, so as to help you diagnose existing performance problems.
This article describes how to enable SQL tracking and obtain trace files. The details are as follows.

Enable SQL tracking

From the internal technical details, SQL tracking is based on 10046 debugging events. The following levels are supported:

0
Disable debugging events
1
Debugging events are activated. For each processed database call, the following information is given: SQL statement, response time, and service time.
Number of rows processed, number of rows processed, number of logical reads, number of physical reads and writes, execution plan, and additional information
4
If Level 1 includes additional information about the variable to be bound. Mainly data types, precision, and values used for each execution
8
Level 1, plus detailed information about the wait time. For each wait in the processing process, the following information is provided: the name, duration, and some additional parameters of the waiting time, indicating the resources to be waited
12
Both startup level 4 and Level 8
Before Oracle 9i or, the following SQL statement activates an SQL trace for the session:

?

1	Alter session set SQL _trace = true

You can also use the set_ SQL _trace stored procedure in the dbms_session package or the set_ SQL _tarce_in_session Stored Procedure Method in the dbms_system package. However, these methods are only used to activate SQL tracing at level 1, which is of little use in practice, I will not go into detail.
It is more useful to specify the level. The following is an SQL trace of the session start Level 12:

?

1	Alter session set events '2017 trace name context forever, level 12'

The statement used to disable SQL tracing for the session is as follows:

?

1	Alter session set events '10046 trace name context off'

You can also use the set_ev stored procedure in the dbms_system package, which is not described here. I will focus on the methods provided after Oracle 10 Gb.
After 10 Gbit/s, Oracle provides the dbms_monitor package to enable or disable SQL tracking, and enables SQL tracking at the session, client, component, and database level. Note that only dba users are allowed to use SQL tracking.

Session level

The following PL/SQL statements enable SQL tracking at level 122 for sessions with ID 6734 and serial number 8th:

?

1 2 3 4 5 6

Begin Dbms_monitor.session_trace_enable (session_id = & gt; 122, Serial_num => 6734, Waits => true, Binds => false ); End;

Session_id
Session id, which corresponds to the SID column in the v $ session view. The following describes how to obtain the current session id:

?

1	Select userenv ('sid ') from dual

Serial_num
Corresponds to the SERIAL # column in the v $ session view. Because the SID is reused, SERIAL # is added when the SID is reused. The Obtaining method is as follows:

?

1	Select serial # from v $ session where sid = 122

Waits
Corresponding to SQL _TRACE_WAITS in the v $ session view, which indicates waiting for event tracking to be activated. The default value is true.

Binds
Corresponding to SQL _TRACE_BINDS in the v $ session view, which indicates whether the binding trace is activated. The default value is false.

After the execution is successful, SQL _TRACE in the v $ session view is modified to ENABLED. The corresponding values of SQL _TRACE_WAITS and SQL _TRACE_BINDS are set for you.
The following PL/SQL statements are used to disable SQL tracking:

?

1 2 3

Begin Dbms_monitor.session_trace_disable (session_id => 122, serial_num => 6734 ); End;

Client-level

The following PL/SQL calls enable SQL tracking at level 8th for all sessions with the specified client Tag:

?

1 2 3 4 5

Begin Dbms_monitor.client_id_trace_enable (client_id => 'test ', Waits => true, Binds => false ); End;

Note that the client tag is case sensitive. You can use the following method to check whether the setting is successful:

?

1 2 3

Select primary_id as client_id, waits, binds From dba_enabled_traces Where trace_type = 'client _ id'

After the configuration is successful, you can enable SQL tracking by specifying the corresponding client tag before each query. The method for specifying the client tag is as follows:

?

1 2 3 4

Begin DBMS_SESSION.SET_IDENTIFIER ('test '); End; // The SQL trace for this session is enabled

After you set a flag for a session, you can view the flag in the client_identifier column of the v $ session.
The following PL/SQL statements are used to disable SQL tracking:

?

1 2 3

Begin Dbms_monitor.client_id_trace_disable (client_id => 'test '); End;

Component level

The following PL/SQL calls enable SQL tracking at level 8th for all sessions with the specified client Tag:

?

1 2 3 4 5 6 7 8

Begin Dbms_monitor.serv_mod_act_trace_enable (service_name => 'ly ', Module_name => 'pl/SQL Developer ', Action_name => 'SQL window-new ', Waits => true, Binds => false, Instance_name => null ); End;

In the parameter, service_name corresponds to service_name in the v $ session view, module_name corresponds to module in the v $ session view, and action_name corresponds to action in the v $ session view. The query method is as follows:

?

1 2 3

SELECT sid, serial #, Client_identifier, service_name, action, module From v $ SESSION

You can view the settings as follows:

?

1 2 3 4 5 6 7

Select primary_id as service_name, Qualifier_id1 as module_name, Qualifier_id2 as action_name, Waits, Binds From dba_enabled_traces Where trace_type = 'service _ MODULE_ACTION'

The following PL/SQL statements are used to disable SQL tracking:

?

1 2 3 4 5 6

Begin Dbms_monitor.serv_mod_act_trace_disable (service_name => 'ly ', Module_name => 'pl/SQL Developer ', Action_name => 'SQL window-new ', Instance_name => null ); End;

Database-level

The following PL/SQL calls enable database-Level 12 SQL tracking:

?

1 2 3 4 5

Begin Dbms_monitor.database_trace_enable (waits => true, Binds => true, Instance_name => null ); End;

The following method is used to check whether the setting is successful:

?

1 2 3 4 5

Select instance_name, Waits, Binds From dba_enabled_traces Where trace_type = 'database'

The following PL/SQL statements are used to disable SQL tracking:

?

1 2 3

Begin Dbms_monitor.database_trace_disable (instance_name => null ); End;

Timing information in the trace file

The following statement is used to provide timing information for the trace file:

?

1	Alter session set timed_statistics = true

In general, the default value is true. If no timing information is provided, the trace file is useless. Therefore, before enabling SQL tracking, it is best to confirm that the parameter is set to true.

Obtain the generated trace file

After SQL tracking is enabled, a trace file is generated, and its directory is configured by initializing the user_dump_dest parameter. The value of this parameter can be obtained through the following method:

?

1	Select name, value from v $ parameter where name = 'user _ dump_dest'

However, if you need to locate a specific file, you need to know the name of the trace file. The trace file name is independent of the version and platform. In most common platforms, the naming structure is as follows:

{Instance name }_{ process id}. trc

1) instance name
Initialize the lower-case value of instance_name. You can obtain this value through the instance_name column in the v $ instance view.
2) process name
The lower-case value of the process name that generates the trace file. For VPC processes, use ora. For Shared Server Processes, you can obtain them through the name column in the v $ diapatcher or v $ shared_server view. For parallel subordinate processes, you can use the server_name column of the v $ px_process view. For most background processes, you can use the name column of the v $ bgprocess view.
3) process id
Process tag at the operating system level. This value can be obtained through the spid column in the v $ process view.
Based on this information, you can obtain the trace file name in the following way:

?

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20

Select s. SID, S. SERVER, Lower (case When s. SERVER in ('dicated ', 'shared') then I. INSTANCE_NAME | '_' | nvl (pp. SERVER_NAME, nvl (ss. NAME, 'ora ') |' _ '| P. SPID | '. trc' Else Null End) as trace_file_name From v $ instance I, V $ session s, V $ process p, V $ px_process pp, V $ shared_server ss Where s. PADDR = p. ADDR And s. SID = pp. SID (+) And s. PADDR = ss. PADDR (+) And s. TYPE = 'user' And s. SID = 'your Sid' Order by s. SID

Replace the above 'your Sid' with your session sid to find out the name of the trace file generated by the specified session. The session sid is obtained in the v $ session view, or directly query the sid of the current session:

?

1	Select userenv ('sid ') from dual

Combine the path (user_dump_dest) with the file name to obtain the complete path of the trace file.

Query the trace file generated by the current session is very simple in objective El 11g:

?

1	Select value from v $ diag_info where name = 'default Trace file'

Oracle Performance Analysis 2: Explanation of the trace file

The following is a segment in the trace file, indicating an SQL Execution process. A trace file consists of many such segments:

?

1 2 3 4 5 6 7 8 9 10 11

Parsing in cursor #4 len = 135 dep = 1 uid = 0 oct = 3 lid = 0 tim = 777069789359 hv = 1115215392 ad = '33e7e384' Select/* + index (idl_char $ I _idl_char1) + */piece #, length, piece from idl_char $ where obj # =: 1 and part =: 2 and version =: 3 order by piece # END OF STMT PARSE #4: c = 0, e = 12, p = 0, cr = 0, cu = 0, mis = 0, r = 0, dep = 1, og = 4, tim = 777069789357 -- BINDS #2: EXEC #4: c = 0, e = 14, p = 0, cr = 0, cu = 0, mis = 0, r = 0, dep = 1, og = 4, tim = 777069789415 -- WAIT #2: nam = 'SQL * Net message from client 'ela = 143 driver id = 1413697536 # bytes = 1 p3 = 0 obj #=-1 tim = 775454461373 FETCH #4: c = 0, e = 18, p = 0, cr = 4, cu = 0, mis = 0, r = 1, dep = 1, og = 4, tim = 777069789450 FETCH #4: c = 0, e = 5, p = 0, cr = 1, cu = 0, mis = 0, r = 0, dep = 1, og = 4, tim = 777069789477 STAT #4 id = 1 cnt = 1 pid = 0 pos = 1 obj = 74 op = 'table access by index rowid IDL_CHAR $ (cr = 4 pr = 0 pw = 0 time = 20 us)' STAT #4 id = 2 cnt = 1 pid = 1 pos = 1 obj = 115 op = 'index range scan I _IDL_CHAR1 (cr = 3 pr = 0 pw = 0 time = 12 us)'

It is manually added starting with "--" and may exist in other queries. The meanings of the following key fields are as follows:
1) parsing in cursor and end of stmt contain the SQL statement text;
2) PARSE, EXEC, and FETCH indicate parse, execution, and fetch calls respectively;
3) BINDS indicates the definition and value of the bound variable;
4) WAIT indicates the WAIT events that occur during the processing;
5) STAT indicates the generated execution plan and related statistics.
The following are some more detailed explanations (from: Interpreting Raw SQL _TRACE anddbms_suppstartstart_trace output). Since there are differences in each version of Oracle, these content is for reference only.

-------------------------------------------------------------------------
Parsing in cursor # len = X dep = X uid = X oct = X lid = X tim = X hv = X ad = 'X'
SQL statement
END OF STMT
--------------------------------------------------------------------------
Len: SQL statement Length
Dep: depth of recursive cursor calls
Uid: analyze the SQL user ID
Oct: ORACLE command type
Lid: privileged user ID
Tim: time pumping. Before ORACLE 9i, the unit is only 1/100 seconds; after ORACLE 9i, the unit is 1/1000000 seconds. The timestamp can be used to determine the time interval between two points. The value is taken from the value in v $ timer. The absolute time can be determined by the 'time' difference of two operations.
Hv: SQL HASH ID (corresponding to the HASH_VALUE field in the V $ SQLAREA view and V $ SQLTEXT view)
Ad: sqltext address (corresponding to the ADDRESS field in the V $ SQLAREA view and V $ SQLTEXT view)

--------------------------------------------------------------------------
Parse error # % d: len = % ld dep = % d uid = % ld oct = % d lid = % ld tim = % lu err = % d
SQL statement
--------------------------------------------------------------------------
Len: SQL statement Length
Dep: depth of recursive cursor calls
Uid: analyze the SQL user ID
Oct: ORACLE command type
Tim: time pumping. Same as above
Err: Oracle error code (e.g. ORA-XXXXX)

--------------------------------------------------------------------------
PARSE #: c = 0, e = 0, p = 0, cr = 0, cu = 0, mis = 0, r = 0, dep = 0, og = 4, tim = 0
EXEC #: c = 0, e = 0, p = 0, cr = 0, cu = 0, mis = 0, r = 0, dep = 0, og = 4, tim = 0
FETCH #: c = 0, e = 0, p = 0, cr = 0, cu = 0, mis = 0, r = 0, dep = 0, og = 4, tim = 0
UNMAP #: c = 0, e = 0, p = 0, cr = 0, cu = 0, mis = 0, r = 0, dep = 0, og = 4, tim = 0
--------------------------------------------------------------------------
Operation:
1) PARSE: PARSE SQL
2) EXEC: Execute the SQL statement that has been analyzed
3) FETCH: Obtain records from the cursor
4) UNMAP: If the cursor uses a temporary table, when the cursor is closed, this operation is used to release the temporary table resources (release the lock, delete the status object, and release the temporary segment ). In the reports generated by tkprof, The UNMAP statistics are added to the statistics of the EXECUTE operation.
5) sort unmap: similar to the above, but sorting OS files or TEMP table segments (segment)

C: CPU time (1/100 seconds in Oracle7, 8, and 9)
E: Elapsed time (1/100 seconds in Oracle7, 8, microseconds in Oracle9 and later versions)
P: physical read (Number of physical reads)
Cr: Number of CR (consistent read, consistent read) reads
Cu: Number of reads in the current mode
Mis: Number of cursor missing in cache
R: number of records involved
Dep: recursive call depth (0 = user SQL,> 0 = recursive)
Og: optimizer mode: 1 = All_Rows, 2 = First_Rows, 3 = Rule, 4 = Choose
Tim: Timestamp, used to determine the time between two operations

--------------------------------------------------------------------------
ERROR # % d: err = % d tim = % lu
--------------------------------------------------------------------------
Error display after an execution or tetch error occurs
Err: Oracle error code at the top of the stack (for example: ORA-XXXX)
Tim: Timestamp

--------------------------------------------------------------------------
STAT # Id = N cnt = 0 [pid = 0 pos = 0 obj = 0 op = 'sort aggregat']
--------------------------------------------------------------------------
STAT: Is Execution Plan Statistical Report
: Calculate the applied Cursor
Id: number of the actions in the execution plan tree
Cnt: number of involved rows
Pid: the parent id of this line
Pos: Position in the execution plan
Obj: Row Object id (if this is a basic object)
Op: operations related to rows

--------------------------------------------------------------------------
XCTEND rlbk = % d rd_only = % d
--------------------------------------------------------------------------
XCTEND: indicates the end of the transaction.
Rlbk: 1 indicates rollback, 0 indicates commit
Rd_only: Transaction read-only is 1, write is 0

Note: The following content only exists when WAITS or BINDS appears.

--------------------------------------------------------------------------
BINDS # % d:
Bind 0: dty = 2 mxl = 22 (22) mal = 00 scl = 00 pre = 00 oacflg = 03 oacfl2 = 0 size = 24 offset = 0
Bfp = 02fedb44 bln = 22 avl = 00 flg = 05
Value = 10
--------------------------------------------------------------------------
BIND: cursor binding variable

Bind N: Position of the bound variable
Dty: Data Type
Mxl: Maximum length of the bound variable
Mal: array Length
Scl: Scale)
Pre: Progress (precision)
Oacflg: indicates a specific Identifier of the binding option.
Oacfl2: Continuation of oacflg
Size: Memory allocated for this part
Offset: the offset from the bound cache entry

Bfp: Binding address
Bln: Bind Cache Length
Avl: actual value length (also array length)
Flg: indicates a specific Identifier of the binding status.
Value: the actual value of the bound variable.

--------------------------------------------------------------------------
WAIT # : Nam = "" ela = 0 p1 = 0 p2 = 0 p3 = 0
--------------------------------------------------------------------------
WAIT: WAIT for event information
Nam: name of the waiting event
Ela: time spent on the operation
P1: The parameter p1 provided for the wait event
P2: parameter p2 provided for the wait event
P3: The parameter p3 provided for the wait event

Example (Full Table Scan ):
WAIT #1: nam = "db file scattered read" ela = 5 p1 = 4 p2 = 1435 p3 = 25
WAITing under CURSOR no 1
For "db file scattered read"
Explanation: we are waiting for 0.05 seconds. For a read: file 4, starting block 1435, a total of 25

Example (Index Scan ):
WAIT #1: nam = "db file sequential read" ela = 4 p1 = 4 p2 = 1224 p3 = 1
WAITing under CURSOR no 1
For "db file sequential read"
Explanation: We will wait 0.04 seconds for a single read (p3 = 1), starting from file 4, block 1224

See:

Http://www.2cto.com/database/201408/326439.html