Shulou(Shulou.com)06/02 Report--

"[SQL_TRACE] SQL optimization and performance diagnosis helper" http://space.itpub.net/519536/viewspace-616240 simply mentioned the use of TKPROF tools to format SQL_TRACE output information, and did not make a clear description of the output, through this small text, show the charm of TKPROF formatting trace files, here only give a specific description of the meaning of the output information, do not show the real performance diagnosis cases.

1. We will use a more advanced trace command (10046) to demonstrate this time than the SQL_TRACE feature we used last time. Let's first enable the "advanced" 10046 event to generate a trace file to be formatted

1) Connect to normal user sec

Sys@ora10g > conn sec/sec

Connected.

2) set the timed_statistics parameter to true first, so that the TKPROF tool can provide more meaningful information and facilitate performance diagnosis.

Sec@ora10g > alter session set timed_statistics=true

Session altered.

3) where the "advanced" lies, we enable 10046 level 12 to track the current session.

(1) here, the explanatory references of 10046 level are given:

Level 1 to enable the standard SQL_TRACE facility (same as SQL_TRACE=TRUE)

Equivalent to standard SQL_TRACE=TRUE

Level 4 to enable SQL_TRACE and also capture bind variable values in the trace file

Enable SQL_TRACE and capture binding variables in the trace file

Level 8 to enable SQL_TRACE and also capture wait events into the trace file

Enable SQL_TRACE and capture wait events in the trace file

Level 12 to enable standard SQL_TRACE and also capture bind variables and wait events

Enable SQL_TRACE and capture binding variables and wait events in the trace file (the most capable of capturing information).

(2) enable tracing of level 12 for the current session:

Sec@ora10g > alter session set events' 10046 trace name context forever, level 12'

Session altered.

(3) [add] if you want to use this advanced method to track other sessions, you can use the following SQL statement to enable and close:

On: execute dbms_system.set_ev (sid,serial#,10046,12,'')

Off: execute dbms_system.set_ev (sid,serial#,10046,0,'')

Examples are as follows:

a. Get information about sid and serial#

Sys@ora10g > select sid, serial# from v$session

b. open

Sys@ora10g > execute dbms_system.set_ev (543, 1306, 10046, 12, and 12)

c. Close

Sys@ora10g > execute dbms_system.set_ev (543, 1306, 10046, 0, and 0)

4) run a specific SQL statement in this session, and the experimental table t used here contains 100 million pieces of data. The execution of the SQL statement will be carefully recorded in the trace file.

Sec@ora10g > select count (*) from t

COUNT (*)

-

100000000

5) turn off tracking for the current session

Sec@ora10g > alter session set events' 10046 trace name context off'

Session altered.

two。 Find the newly generated trace file in the udump directory (there are many ways to get the generated trace file quickly, choose the one that suits you, OK), format it with TKPROF, and then print all the output, and then do a "anatomical sparrow" for each output item:)

Ora10g@secDB / oracle/app/oracle/admin/ora10g/udump$ tkprof ora10g_ora_21213.trc ora10g_ora_21213.prf

TKPROF: Release 10.2.0.3.0-Production on Wed Oct 21 10:04:40 2009

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

Ora10g@secDB / oracle/app/oracle/admin/ora10g/udump$ cat ora10g_ora_21213.prf

TKPROF: Release 10.2.0.3.0-Production on Wed Oct 21 10:05:43 2009

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

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

*

BEGIN DBMS_OUTPUT.GET_LINES (: LINES,: NUMLINES); END

Call count cpu elapsed disk query current rows

--

Parse 2 0.00 0.00 00 00

Execute 2 0.00 0.00 00 0 2

Fetch 0 0.00 0.00 00 00

--

Total 4 0.00 0.00 00 0 2

Misses in library cache during parse: 0

Optimizer mode: ALL_ROWS

Parsing user id: 51

Elapsed times include waiting on following events:

Event waited on Times Max. Wait Total Waited

-- Waited--

SQL*Net message to client 2 0.00 0.00

SQL*Net message from client 2 5.60 7.74

*

Select count (*)

From

T

Call count cpu elapsed disk query current rows

--

Parse 1 0.00 0.00 00 00

Execute 1 0.00 0.00 00 00

Fetch 2 10.94 10.68 222186 222957 0 1

--

Total 4 10.94 10.68 222186 222957 0 1

Misses in library cache during parse: 0

Optimizer mode: ALL_ROWS

Parsing user id: 51

Rows Row Source Operation

1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)

100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us) (object id 45619)

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

Db file scattered read 14249 0.00 1.10

Db file sequential read 59 0.00 0.00

*

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

Call count cpu elapsed disk query current rows

--

Parse 3 0.00 0.00 00 00

Execute 3 0.00 0.00 00 0 2

Fetch 2 10.94 10.68 222186 222957 0 1

--

Total 8 10.94 10.68 222186 222957 0 3

Misses in library cache during parse: 0

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 5.60 7.74

Db file scattered read 14249 0.00 1.10

Db file sequential read 59 0.00 0.00

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

Call count cpu elapsed disk query current rows

--

Parse 0 0.00 0.00 00 00

Execute 0 0.00 0.00 00 00

Fetch 0 0.00 0.00 00 00

--

Total 0 0.00 0.00 00 00

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: ora10g_ora_21213.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.

2 unique SQL statements in trace file.

14392 lines in trace file.

16 elapsed seconds in trace file.

3. For the above TKPROF formatted output, the key content "dissecting Sparrow" officially begins.

1) excerpt from the first part, an overview of the execution of SQL statements

Select count (*)

From

T

Call count cpu elapsed disk query current rows

--

Parse 1 0.00 0.00 00 00

Execute 1 0.00 0.00 00 00

Fetch 2 10.94 10.68 222186 222957 0 1

--

Total 4 10.94 10.68 222186 222957 0 1

The description of count, cpu, elapsed, disk, query, current, and rows in the title information of the statistical table has a brief description at the front end of the trace file, which is repeated here.

Count: the number of times the query was executed at this stage

Cpu: the amount of CPU time, in milliseconds, of the query at this stage

Elapsed: the wall clock time spent at this stage, which is higher than the cpu value, indicating that there is a waiting event

Disk: the number of times the physical Istroke O has been performed

Query: care about the number of times to execute logic Imax O when the block is obtained by consistent retrieval.

Current: the number of logical IDAGO times

Rows: the number of rows processed or affected at this stage.

A repeat of the first column:

Parse: soft compilation and hard compilation times

Execute: what is done in open and execute statements

Fetch: data is displayed in select, but not in update statements.

2) extract the running environment information

Misses in library cache during parse: 0

Optimizer mode: ALL_ROWS

Parsing user id: 51

The "0" in the first line indicates that the query uses soft parsing (soft parse).

The optimization mode is: ALL_ROWS

The user ID on the last line can get the session information at execution time. Obtaining user information can be done through the following SQL statement.

Sys@ora10g > select * from all_users where user_id = 51

USERNAME USER_ID CREATED

SEC 51 2009-10-15 13:04:03

3) excerpt the execution plan information

Rows Row Source Operation

1 SORT AGGREGATE (cr=222957 pr=222186 pw=0 time=10686023 us)

100000000 INDEX FAST FULL SCAN PK_T (cr=222957 pr=222186 pw=0 time=100000562 us) (object id 45619)

Interesting finding: the amount of data in this t table can be obtained from the second row, which shows that the result is 100 million.

Several important parameters that appear above "Anatomy":

Cr=222957-consistent read

Pr=222186-physical read

Pw=0-physical Writing

Time=100000562 us-elapsed time (in subtle 1/1000000 seconds)

4) excerpt waiting events

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

Db file scattered read 14249 0.00 1.10

Db file sequential read 59 0.00 0.00

Through the description of this wait event, we can clearly see what eye-catching wait events occur during the execution of the SQL statement. For example, the "db file scattered read" and "db file sequential read" messages shown above need to be analyzed and studied in depth if such information appears in large quantities in the production environment.

4. Summary

This is the end of the whole process of "dissecting Sparrow". I believe you have an overall understanding of "10046 tracking" and TKPROF formatting. Here is just an example to show the power of trace tracking and TKPROF. What is more important is the specific analysis of the specific problems in the process of fault diagnosis of the production environment. I have to remind you that when using the 10046 level 12 method to trace sessions in a production environment, pre-testing is a necessary step to fully take into account its impact on system performance.

-- The End--

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.