Use 10046 to view the execution plan and read the trace file, 10046 trace

Source: Internet
Author: User

Use 10046 to view the execution plan and read the trace file, 10046 trace
There are many ways to view the SQL Execution Plan. 10046 events are one of them. different from other SQL Execution plans, when we encounter complicated SQL statements, we can track SQL statements through 10046 to obtain the logical reads of each step in the execution plan, physical read and time spent. this fine-grained tracking is particularly useful for analyzing SQL Performance.

Generally, follow these steps to use the 10046 event to obtain the SQL Execution Plan:
1. Activate the current session 10046 event
2. Execute SQL statements in the current session
3. Close the current session 10046 event

After the preceding steps are completed, a trace file is automatically generated. in oracle 11g, trace files are generally stored in the $ ORACLE_BASE/diag/rdbms/{database_name}/$ ORACLE_SID/trace directory. if you use oradebug to Activate tracking 10046, you can use oradebug tracefile_name to obtain the complete path of the generated trace file.

NAME                                 TYPE        VALUE------------------------------------ ----------- ------------------------------background_dump_dest                 string      g:\app\davidd\diag\rdbms\david                                                 \david\trace

The oradebug activation tracking 10046 event just mentioned. I think most DBAs will use. oradebug as a powerful and useful tool. Using oradebug help, we will see a lot of features.
SQL> oradebug helpHELP           [command]                 Describe one or all commandsSETMYPID                                 Debug current processSETOSPID       <ospid>                   Set OS pid of process to debugSETORAPID      <orapid> ['force']        Set Oracle pid of process to debugSETORAPNAME    <orapname>                Set Oracle process name to debugSHORT_STACK                              Get abridged OS stackCURRENT_SQL                              Get current SQLDUMP           <dump_name> <lvl> [addr]  Invoke named dumpDUMPSGA        [bytes]                   Dump fixed SGADUMPLIST                                 Print a list of available dumpsEVENT          <text>                    Set trace event in processSESSION_EVENT  <text>                    Set trace event in sessionDUMPVAR        <p|s|uga> <name> [level]  Print/dump a fixed PGA/SGA/UGA variableDUMPTYPE       <address> <type> <count>  Print/dump an address with type infoSETVAR         <p|s|uga> <name> <value>  Modify a fixed PGA/SGA/UGA variablePEEK           <addr> <len> [level]      Print/Dump memoryPOKE           <addr> <len> <value>      Modify memoryWAKEUP         <orapid>                  Wake up Oracle processSUSPEND                                  Suspend executionRESUME                                   Resume executionFLUSH                                    Flush pending writes to trace fileCLOSE_TRACE                              Close trace fileTRACEFILE_NAME                           Get name of trace fileLKDEBUG                                  Invoke global enqueue service debuggerNSDBX                                    Invoke CGS name-service debugger-G             <Inst-List | def | all>   Parallel oradebug command prefix-R             <Inst-List | def | all>   Parallel oradebug prefix (return outputSETINST        <instance# .. | all>      Set instance list in double quotesSGATOFILE      <SGA dump dir>            Dump SGA to file; dirname in double quotesDMPCOWSGA      <SGA dump dir>  Dump & map SGA as COW; dirname in double quotesMAPCOWSGA      <SGA dump dir>            Map SGA as COW; dirname in double quotesHANGANALYZE    [level] [syslevel]        Analyze system hangFFBEGIN                                  Flash Freeze the InstanceFFDEREGISTER                             FF deregister instance from clusterFFTERMINST                               Call exit and terminate instanceFFRESUMEINST                             Resume the flash frozen instanceFFSTATUS                                 Flash freeze status of instanceSKDSTTPCS      <ifname>  <ofname>        Helps translate PCs to namesWATCH          <address> <len> <self|exist|all|target>  Watch a region of memoryDELETE         <local|global|target> watchpoint <id>    Delete a watchpointSHOW           <local|global|target> watchpoints        Show  watchpointsDIRECT_ACCESS  <set/enable/disable command | select query> Fixed table accessCORE                                     Dump core without crashing processIPC                                      Dump ipc informationUNLIMIT                                  Unlimit the size of the trace filePROCSTAT                                 Dump process statisticsCALL           <func> [arg1] ... [argn]  Invoke function with arguments



Use the oradebug tracking 10046 command as follows:
SQL> oradebug setmypidStatement processed. // activate the 10046 event SQL> oradebug event 10046 trace name context forever, level 12; Statement processed. SQL> select/* + leading (t3) use_merge (t4) */* 2 from t3, t4 3 where t3.id = t4.t3 _ id and t3.n = 1100; 10 rows selected. // close the 10046 event SQL> oradebug event 10046 trace name context off; Statement processed in the current session. // use oradebug tracefile_name to directly view the location of the generated trace file SQL> oradebug tracefile_name; g: \ app \ david D \ diag \ rdbms \ david \ trace \ david _ora_2176.trc

10046 of the information collected is classified into the following levels:

Level 0 Disables SQL tracing, which is equivalent to SQL _TRACE = FALSE.
Level 1 Standard SQL trace, equivalent to SQL _TRACE = TRUE
Level 4 Add variable binding information based on level 1.
Level 8 Add wait event information based on level 1
Level 12 Add variable binding and wait event information based on level 1.



Analyze and read trace files

Now let's open g: \ app \ david D \ diag \ rdbms \ david \ trace \ david _ora_2176.trc to check the contents of the generated trace file.

<pre name="code" class="sql"><pre name="code" class="sql"><pre name="code" class="sql"><pre name="code" class="sql" style="font-size:14px;">PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'select /*+ leading(t3) use_merge(t4) */ *from t3, t4where t3.id = t4.t3_id and t3.n = 1100END OF STMTPARSE #22:c=0,e=10777,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3831111046,tim=900460923319EXEC #22:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3831111046,tim=900460923482WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512FETCH #22:c=15625,e=23922,p=0,cr=119,cu=0,mis=0,r=1,dep=0,og=1,plh=3831111046,tim=900460947462WAIT #22: nam='SQL*Net message from client' ela= 221 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460947755WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460947803FETCH #22:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=9,dep=0,og=1,plh=3831111046,tim=900460947864STAT #22 id=1 cnt=10 pid=0 pos=1 obj=0 op='MERGE JOIN  (cr=119 pr=0 pw=0 time=28 us cost=193 size=1280 card=10)'STAT #22 id=2 cnt=1 pid=1 pos=1 obj=0 op='SORT JOIN (cr=15 pr=0 pw=0 time=0 us cost=6 size=63 card=1)'STAT #22 id=3 cnt=1 pid=2 pos=1 obj=83550 op='TABLE ACCESS FULL T3 (cr=15 pr=0 pw=0 time=0 us cost=5 size=63 card=1)'STAT #22 id=4 cnt=10 pid=1 pos=2 obj=0 op='SORT JOIN (cr=104 pr=0 pw=0 time=11 us cost=187 size=650000 card=10000)'STAT #22 id=5 cnt=10000 pid=4 pos=1 obj=83552 op='TABLE ACCESS FULL T4 (cr=104 pr=0 pw=0 time=8603 us cost=29 size=650000 card=10000)'

From the preceding trace file, we can see that the SQL statement has gone through several processes, namely parse (parsing)-> exec (execution)-> fetch (obtaining data from the cursor, the first sentence describes the general information about the SQL statements currently being tracked, such as the game number, SQL statement length, and recursive depth:

PARSING IN CURSOR #22 len=92 dep=0 uid=0 oct=3 lid=0 tim=900460923321 hv=1624778336 ad='34671d90' sqlid='g0rdyg9hdh9m0'

Cursor Cursor number
Len SQL statement Length
Dep SQL statement recursion depth
Uid User id
Oct Oracle command type
Lid Privilege user id
Tim Timestamp, timestamp
Hv Hash id
Ad SQL address, used in v $ sqltext
Sqlid SQL id

Next, the following statement describes the specific execution process of the SQL statement and performance indicators such as the CPU consumption time of each step.

PARSE #22:c=0,e=10777,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=3831111046,tim=900460923319EXEC #22:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3831111046,tim=900460923482FETCH #22:c=15625,e=23922,p=0,cr=119,cu=0,mis=0,r=1,dep=0,og=1,plh=3831111046,tim=900460947462

C CPU consumption time
E Elapsed time
P Number of physical reads
Cr Number of buffers retrieved for CR reads logical read data blocks
Cu Number of buffers retrieved in current mode (data block read in current mode)
Mis Cursor missed in the cache library, number of times of hard Parsing
R Number of rows processed by rows processed
Dep Recursive depth
Og Optimizer mode [1: all_rows, 2: first_rows, 3: rule, 4: choose]
Plh Plan hash value
Tim Timestamp

And wait events during execution

WAIT #22: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=-1 tim=900460923512
Nam An event that we waited for wait event
Ela Time consumed by this operation
P3 Block number
Trm Timestamp


The execution plan of the cursor is displayed.

STAT #22 id=1 cnt=10 pid=0 pos=1 obj=0 op='MERGE JOIN  (cr=119 pr=0 pw=0 time=28 us cost=193 size=1280 card=10)'STAT #22 id=2 cnt=1 pid=1 pos=1 obj=0 op='SORT JOIN (cr=15 pr=0 pw=0 time=0 us cost=6 size=63 card=1)'STAT #22 id=3 cnt=1 pid=2 pos=1 obj=83550 op='TABLE ACCESS FULL T3 (cr=15 pr=0 pw=0 time=0 us cost=5 size=63 card=1)'STAT #22 id=4 cnt=10 pid=1 pos=2 obj=0 op='SORT JOIN (cr=104 pr=0 pw=0 time=11 us cost=187 size=650000 card=10000)'STAT #22 id=5 cnt=10000 pid=4 pos=1 obj=83552 op='TABLE ACCESS FULL T4 (cr=104 pr=0 pw=0 time=8603 us cost=29 size=650000 card=10000

Cnt Number of rows returned by the current row Source
Pid Parent id of this row source parent node id of the current row source
Pos Position in explain plan position of the Execution plan
Obj Object id of row source (if this is a base object)
Op The row source access operation

For example, the number of logical reads consumed by performing the merge join operation is 119, the number of physical reads is 0, the time consumed is 28 us, and the cost of cost is 193. 10 records are returned.



Use the tkprof command to translate the trace file


We can also use the tkprof command to translate the trace file to obtain a trace summary report file that is easy to understand.

C:\Documents and Settings\davidd> tkprof g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trc d:\trace.trcTKPROF: Release 11.2.0.1.0 - Development on Thu Dec 18 18:51:44 2014Copyright (c) 1982, 2009, Oracle and/or its affiliates.  All rights reserved.

The summary report of the trace file translated by tkprof is as follows:
Trace file: g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trcSort options: default********************************************************************************count    = number of times OCI procedure was executedcpu      = cpu time in seconds executing elapsed  = elapsed time in seconds executingdisk     = number of physical reads of buffers from diskquery    = number of buffers gotten for consistent readcurrent  = number of buffers gotten in current mode (usually for update)rows     = number of rows processed by the fetch or execute call********************************************************************************select /*+ leading(t3) use_merge(t4) */ *from t3, t4where t3.id = t4.t3_id and t3.n = 1100call     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        2      0.00       0.00          0        119          0          10------- ------  -------- ---------- ---------- ---------- ----------  ----------total        4      0.00       0.00          0        119          0          10Misses in library cache during parse: 1Optimizer mode: ALL_ROWSParsing user id: SYSRows     Row Source Operation-------  ---------------------------------------------------     10  MERGE JOIN  (cr=119 pr=0 pw=0 time=0 us cost=193 size=1280 card=10)      1   SORT JOIN (cr=15 pr=0 pw=0 time=0 us cost=6 size=63 card=1)      1    TABLE ACCESS FULL T3 (cr=15 pr=0 pw=0 time=0 us cost=5 size=63 card=1)     10   SORT JOIN (cr=104 pr=0 pw=0 time=0 us cost=187 size=650000 card=10000)  10000    TABLE ACCESS FULL T4 (cr=104 pr=0 pw=0 time=8733 us cost=29 size=650000 card=10000)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       20.23         20.23********************************************************************************OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        1      0.00       0.00          0          0          0           0Execute      1      0.00       0.00          0          0          0           0Fetch        2      0.00       0.00          0        119          0          10------- ------  -------- ---------- ---------- ---------- ----------  ----------total        4      0.00       0.00          0        119          0          10Misses in library cache during parse: 1Elapsed 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       20.23         30.20OVERALL TOTALS FOR ALL RECURSIVE STATEMENTScall     count       cpu    elapsed       disk      query    current        rows------- ------  -------- ---------- ---------- ---------- ----------  ----------Parse        0      0.00       0.00          0          0          0           0Execute      0      0.00       0.00          0          0          0           0Fetch        0      0.00       0.00          0          0          0           0------- ------  -------- ---------- ---------- ---------- ----------  ----------total        0      0.00       0.00          0          0          0           0Misses in library cache during parse: 0    1  user  SQL statements in session.    0  internal SQL statements in session.    1  SQL statements in session.********************************************************************************Trace file: g:\app\davidd\diag\rdbms\david\david\trace\david_ora_2176.trcTrace file compatibility: 11.1.0.7Sort options: default       1  session in tracefile.       1  user  SQL statements in trace file.       0  internal SQL statements in trace file.       1  SQL statements in trace file.       1  unique SQL statements in trace file.     122  lines in trace file.       0  elapsed seconds in trace file.

Where, Misses in library cache during parse: 1This indicates that the database cache loses the cursor during parsing, that is, a hard parsing occurs.



Reference: http://www.eygle.com/archives/2005/10/aeearaw_traceia.html

Related Article

Contact Us

The content source of this page is from Internet, which doesn't represent Alibaba Cloud's opinion; products and services mentioned on that page don't have any relationship with Alibaba Cloud. If the content of the page makes you feel confusing, please write us an email, we will handle the problem within 5 days after receiving your email.

If you find any instances of plagiarism from the community, please send an email to: info-contact@alibabacloud.com and provide relevant evidence. A staff member will contact you within 5 working days.

A Free Trial That Lets You Build Big!

Start building with 50+ products and up to 12 months usage for Elastic Compute Service

  • Sales Support

    1 on 1 presale consultation

  • After-Sales Support

    24/7 Technical Support 6 Free Tickets per Quarter Faster Response

  • Alibaba Cloud offers highly flexible support services tailored to meet your exact needs.