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

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 SQL-oriented for our analysis.

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 SQL-oriented for our analysis.

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       
 
                     Set OS pid of process to debugSETORAPID      
  
    ['force']        Set Oracle pid of process to debugSETORAPNAME    
   
                    Set Oracle process name to debugSHORT_STACK                              Get abridged OS stackCURRENT_SQL                              Get current SQLDUMP           
     
     
       [addr]  Invoke named dumpDUMPSGA        [bytes]                   Dump fixed SGADUMPLIST                                 Print a list of available dumpsEVENT          
      
        Set trace event in processSESSION_EVENT 
       
         Set trace event in sessionDUMPVAR 
         
         
           [level] Print/dump a fixed PGA/SGA/UGA variableDUMPTYPE 
           
           
             Print/dump an address with type infoSETVAR 
             
              
              
                Modify a fixed PGA/SGA/UGA variablePEEK 
               
                 [level] Print/Dump memoryPOKE 
                 
                 
                   Modify memoryWAKEUP 
                  
                    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 
                   
                     Parallel oradebug command prefix-R 
                    
                      Parallel oradebug prefix (return outputSETINST 
                     
                       Set instance list in double quotesSGATOFILE 
                      
                        Dump SGA to file; dirname in double quotesDMPCOWSGA 
                       
                         Dump & map SGA as COW; dirname in double quotesMAPCOWSGA 
                        
                          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 
                          
                          
                            Helps translate PCs to namesWATCH 
                            
                            
                              Watch a region of memoryDELETE 
                             
                               watchpoint 
                              
                                Delete a watchpointSHOW 
                               
                                 watchpoints Show watchpointsDIRECT_ACCESS 
                                
                                  Fixed table accessCORE Dump core without crashing processIPC Dump ipc informationUNLIMIT Unlimit the size of the trace filePROCSTAT Dump process statisticsCALL 
                                 
                                   [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.

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.