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

Some students have been responding to Maclean that they want to do a 10046 SQL trace course. Just these days we will talk about it when we are free.

Why do we use 10046 trace?

10046 trace helps us parse the running status of one or more SQL and PL/SQL statements, including wait events encountered in the three phases of Parse/Fetch/Execute, consumed physical and logical reads, CPU time, execution plan, and so on.

That is, 10046 reveals the operation of one or more SQL, which is a good auxiliary tool for point-to-point SQL tuning, especially when there is no ASH before 10g. But the whole system tuning is not what 10046 is good at, 10046 is the nail lifter for performance tuning, and AWR is the hammer for performance tuning.

10046 can also help us to analyze the internal working principle of some DDL maintenance commands, the slowness of RMAN, Data Pump Expdp/Impdp and other tools, which is a necessary product for home travel to study the principle of oracle database.

The difference between 10046 and SQL TRACE?

10046 provides more control options and more detailed content output than SQL_TRACE parameters. Generally, Maclean only uses 10046 instead of sql_trace.

The difference between 10046 and 10053?

10053 is the most commonly used Oracle optimizer optimizer tracking trace. 10053 can be used as an auxiliary tool for analyzing why the optimizer chose an execution plan and the reasons for it, but does not tell us how the execution plan works.

10046 does not explain the work of the optimizer optimizer, but it also describes the wait events encountered during the SQL parsing parse phase and the resources consumed, such as CPU, as well as the metrics of the Execute execution and Fetch phases.

In short, 10046 tells us how the SQL (execution plan) works, and 10053 tells us why the optimizer chose an execution plan for this SQL.

LEVEL of 10046 TRACE:

Different Level corresponds to different tracking levels.

1 enable the standard SQL_TRACE feature (default) contains SQL statements, response time, service time, number of rows processed, number of physical reads and writes, execution plan, and other additional information. The condition for the execution plan to be written to trace in version 10.2 is that only if the relevant cursor has been closed and the associated execution statistics are the sum of all execution times. In version 11.1, the execution plan is written to trace only after the first execution of each cursor. The execution statistics are only related to this first execution. 4 trace8 with more bound variables than level 1 has more wait events than level 1, especially for the latch free wait event indicated in 9i. It is also useful for analyzing full table scans and index scans. 12 has more binding variables and wait events 16 than level 1 to generate STAT information for each execution in 11g. Only after 11.1 can 32 generate less execution plan 64 than level 1. Compared with level 1, execution plan information may be generated after the first execution. The condition is that a cursor takes a minute longer to run on the premise of the previous execution. Only in 11.2.0.2 Level 28 (4 + 8 + 16) is available for enabling level 4, level 8, level 16level 68 (64 + 4) for both level 64 and level 4.

The setting method is as follows:

Session level: alter session set events' 10046 trace name context forever,level X'

System level: alter system set events' 10046 trace name context forever,level X'

Set for a process other than this session, if you know its SPID operating system process number

Oradebug setospid SPID

Oradebug event 10046 trace name context forever, level X

For example:

[oracle@vrh8 ~] $ps-ef | grep LOCAL oracle 12421 12420 0 Aug21? 00:00:00 oracleG10R25 (DESCRIPTION= (LOCAL=YES) (ADDRESS= (PROTOCOL=beq)) oracle 12522 12521 0 Aug21? 00:00:00 oracleG10R25 (DESCRIPTION= (LOCAL=YES) (ADDRESS= (PROTOCOL=beq)) oracle 12533 10 Aug21? 00:00:00 oracleG10R25 (LOCAL=NO) oracle 15354 15353 0 Aug21? 00:00:08 oracleG10R25 (DESCRIPTION= (LOCAL=YES) (ADDRESS= (PROTOCOL=beq)) oracle 15419 15418 0 Aug21? 00:00:11 oracleG10R25 (DESCRIPTION= (LOCAL=YES) (ADDRESS= (PROTOCOL=beq)) ) oracle 16219 16218 0 Aug21? 00:00:00 oracleG10R25 (DESCRIPTION= (LOCAL=YES) (ADDRESS= (PROTOCOL=beq) oracle 17098 17097 0 03:12-00:00:00 oracleG10R25 (DESCRIPTION= (LOCAL=YES) (ADDRESS= (PROTOCOL=beq) to track 17098 this process SQL > oradebug event 10046 trace name context forever Level 28 Statement processed. The query to navigate from sid to SPID or ORAPID is as follows: SQL > select distinct sid from SQL > select spid,pid from v$Process where addr= (select paddr from v$session where sid=141); SPID PID-- 17196 24 select spid,pid from v$Process where addr= (select paddr from v$session where sid=&SID) if you only know ORA's PID, you can also oradebug setorapid 24; oradebug event 10046 trace name context forever, level 28

10046 trace sample parsing

Here we introduce a 10046 example of a full table scan and parse the TRACE information in this example:

PARSING IN CURSOR # 20 len=44 dep=0 uid=0 ct=3 lid=0 tim=1344883874047619 hv=2241892608 ad='a7902a08' select count (*) from fullscan where wner=:v END OF STMT PARSE # 20 PARSING IN CURSOR # 20 (*) from fullscan where wner=:v END OF STMT PARSE # 20 from fullscan where wner=:v END OF STMT PARSE # 20 PARSING IN CURSOR # 2000 len=198 dep=1 uid=0 ct=3 lid=0 tim=1344883874048534 hv=4125641360 ad='a7ab9fc0' select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1 1087 len=198 dep=1 uid=0 ct=3 lid=0 tim=1344883874048534 hv=4125641360 ad='a7ab9fc0' select obj#,type#,ctime,mtime,stime,status,dataobj#,flags,oid$, spare1, spare2 from obj$ where owner#=:1 and name=:2 and namespace=:3 and remoteowner is null and linkna me is null and subname is null END OF STMT PARSE # 26:c=0 Kkscoacd Bind#0 acdty=02 mxl=22 531 mxlc=00 mal=00 scl=00 pre=00 acflg=08 fl2=0001 frm=00 csi=00 siz=24 ff=0 kxsbbbfp=7f9ccfec6bd8 bln=22 avl=01 flg=05 value=0 Bind#1 acdty=01 mxl=32 (08) mxlc=00 mal=00 scl=00 pre=00 acflg=18 fl2=0001 frm=01 csi=873 siz=32 ff=0 kxsbbbfp=7f9ccfec6ba0 bln=32 avl=08 flg=05 value= "FULLSCAN" askmaclean.com Bind#2 acdty=02 mxl=22 (22) mxlc=00 mal=00 scl=00 pre=00 acflg=08 fl2=0001 frm=00 csi=00 siz=24 ff=0 kxsbbbfp=7f9ccfec6b70 bln=24 avl=02 flg=05 value=1 EXEC # 26 Vista 1998 Encyclopedia 1506 pamphlet 0pju 0cany 0cquni 1506 pamphlet 0pju 0cany 0pc0cany 0lmlle 0ZOB0LING 0LING 0LING 0LING 0MIRETHING 0MIREOPERATION 0MIAND 0LING 0LINGOBUBG 4 Tim=1344883874050177 WAIT # 26: nam='db file sequential read' ela= 26 file#=1 block#=58007 blocks=1 obj#=37 tim=1344883874050345 WAIT # 26: nam='db file sequential read' ela= 19 file#=1 block#=58966 blocks=1 obj#=18 tim=1344883874050452 PARSING IN CURSOR # 25 len=493 dep=1 uid=0 ct=3 lid=0 tim=1344883874051980 hv=2584065658 ad='a7a9ef68' select t.filewriting pctused$ .initransret.maxtransret.rowcntret.blkcntret mpcnt,t.avgspc,t.chncnt,t.avgrln,t.analyzetime,t.samplesize,t.cols,t.property,nvl (t.degreere1), nvl (t.instancesreport1), t.avgspcsancflbret.flbcntnotet.kernelcolsrednvl (t.trigflag, 0), nvl (t.spare1Power0), nvl (t.spare2par0), t.spare4 camera t.spare6mts.cachedblkmt ts.logicalread from tab$ t Tab_stats$ ts where t. Objure =: 1 and t.objure = ts.obj# (+) END OF STMT PARSE # 25 ts.obj# (+) 25VOBJY # 25VOBJULY: 1 and T.objac = 1 OBJBJY =: 1 BINDS # 25: kkscoacd Bind#0 acdty=02 mxl=22 (22) OBJ # 25 Cruise 3000Power2757 Lines pamphlet 0crackers 0Cuppets 0MIQULY 1MICROLOGRAPHY 0PROPERATION 1MICROLOGRAPHY 1MICOPERATION Tim=1344883874054930 WAIT # 25: nam='db file sequential read' ela= 21 file#=1 block#=48756 blocks=1 obj#=3 tim=1344883874055059 WAIT # 25: nam='db file sequential read' ela= 18 file#=1 block#=51327 blocks=1 obj#=4 tim=1344883874055149 FETCH # 25 nam='db file sequential read' ela= 18 file#=1 block#=51327 blocks=1 obj#=4 tim=1344883874055149 FETCH # 25 Flux 538 pendant 2 crackers 5 pendant 5 cuttings 0 Mishi 0 journal 1 depended 1 coach 4 Tim=1344883874055512 STAT # 25 id=1 cnt=1 pid=0 pos=1 bj=0 p='MERGE JOIN OUTER (cr=5 pr=2 pw=0 time=565 us) 'STAT # 25 id=2 cnt=1 pid=1 pos=1 bj=4 p='TABLE ACCESS CLUSTER TAB$ (cr=3 pr=2 pw=0 time=228 us)' STAT # 25 id=3 cnt=1 pid=2 pos=1 bj=3 p='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=1 pw=0 time=115 us) 'STAT # 25 id=4 cnt=0 pid=1 pos=2 bj=0 p='BUFFER SORT (cr=2 pr=0 pw=0 time=251 us)' STAT # 25 id=5 cnt=0 pid=4 pos=1 bj=709 p='TABLE ACCESS BY INDEX ROWID TAB_STATS$ (cr=2 pr=0 pw=0 time=207 us) 'STAT # 25 id=6 Cnt=0 pid=5 pos=1 bj=710 p='INDEX UNIQUE SCAN I_TAB_STATS$_OBJ# (cr=2 pr=0 pw=0 time=33 us)'. BINDS # 20: kkscoacd Bind#0 acdty=96 mxl=2000 mxlc=00 mal=00 scl=00 pre=00 acflg=03 fl2=1000000 frm=01 csi=873 siz=2000 ff=0 kxsbbbfp=7f9ccfec6420 bln=2000 avl=50 flg=05 value= "MACLEAN" EXEC # 20 MACLEAN 20996 people 21249, pendant 7, crushing 19, cuttings 0, misunderstanding 1, raster 1, depict 0, depict 0, ogony 1 Tim=1344883874068951 WAIT # 20: nam='SQL*Net message to client' ela= 6 driver id=1650815232 # bytes=1 p3room0 obj#=36 tim=1344883874069011 WAIT # 20: nam='db file sequential read' ela= 23 file#=1 block#=80385 blocks=1 obj#=96551 tim=1344883874069159 WAIT # 20: nam='db file scattered read' ela= 42 file#=1 block#=80386 blocks=7 obj#=96551 tim=1344883874069383 WAIT # 20: nam='db file scattered read' ela= 41 file#=1 block#=82313 blocks=8 obj#=96551 tim=1344883874069543 WAIT # 20: nam='db file scattered read' ela= 30 file#=1 block#=82321 blocks=8 obj#=96551 Tim=1344883874069678 WAIT # 20: nam='db file scattered read' ela= 38 file#=1 block#=82329 blocks=8 obj#=96551 tim=1344883874069949 WAIT # 20: nam='db file scattered read' ela= 848 file#=1 block#=82337 blocks=8 obj#=96551 tim=1344883874070846 WAIT # 20: nam='db file scattered read' ela= 63 file#=1 block#=82345 blocks=8 obj#=96551 tim=1344883874071042 WAIT # 20: nam='db file scattered read' ela= 37 file#=1 block#=92593 blocks=8 obj#=96551 tim=1344883874071190 WAIT # 20: nam='db file scattered read' ela= 73 file#=1 block#=92601 blocks=8 obj#=96551 tim=1344883874071393 FETCH # 20:c=18997 Nam='SQL*Net message from client' ela= 18234 nam='SQL*Net message from client' ela= driver id=1650815232 # bytes=1 p3dic0 obj#=96551 tim=1344883874087675 FETCH # 20 Variety 0MIZOLING 0MICOLOGRAPHY 0MIREBENTOREGRAPHY 0CHERALY 0DEFLIZOGRAPHY 0 Tim=1344883874087715 WAIT # 20: nam='SQL*Net message to client' ela= 3 driver id=1650815232 # bytes=1 p3 room0 obj#=96551 tim=1344883874087744 * 2013-08-22 04 bytes=1 44 bytes=1 59.527 WAIT # 20: nam='SQL*Net message from client' ela= 12169104 driver id=1650815232 # bytes=1 p3hyd0 obj#=96551 tim=1344883886256887 STAT # 20 id=1 cnt=1 pid=0 pos=1 bj=0 p='SORT AGGREGATE (cr=1143 pr=1139 pw=0 time=18243 us) 'STAT # 20 id=2 cnt=0 pid=1 pos=1 bj=96551 p='TABLE ACCESS FULL FULLSCAN (cr=1143 pr=1139 pw=0 time=18200 us)' WAIT # 0: nam='SQL*Net message to client' ela= 8 driver id=1650815232 # bytes=1 p3400 obj#=96551 tim=1344883886257193 WAIT # 0: nam='SQL*Net message from client' ela= 455225 driver id=1650815232 # bytes=1 p3400obj#=96551 tim=1344883886712468 WAIT # 0: nam='SQL*Net message to client' ela= 0 driver id=1650815232 # bytes=1 p3400obj#=96551 tim=1344883886712594

PARSING IN CURSOR # 20 len=44dep=0 uid=0 ct=3 lid=0 tim=1344883874047619 hv=2241892608 ad='a7902a08'

Select count (*) from fullscan where wner=:v

END OF STMT

PARSE # 20 Vera cantilever 2000, epistemology 1087, pamphlet, crania, crania, cuttle0, mismatch 1, depopulation, ogony, timeliness, 1344883874047610

PARSING IN CURSOR # 20, where # 20 is the cursor, this cursor is very important, and the following FETCH, WAIT, EXECUTE, and PARSE are all connected with the previous SQL through this cursor.

Note you can see that after the execution of PARSING IN CURSOR # 20, PARSE # 20 does not follow the run of # 20 cursors, but follows the operation of # 25 and # 26 cursors. Take a closer look at # 25 and # 26 they are system recursive recursive SQL. These recursive SQL are triggered by the user's SQL. Generally speaking, look up some data dictionary base tables such as obj$, tab$, etc. In general, recursive SQL runs with very little resources and time.

LEN=44 refers to the length of the SQL

OCT=3 Oracle command type refers to the type of command classification in Oracle that can be obtained through V$SQL.COMMAND_TYPE.

The V$SQLCOMMAND view is provided in 11g to see the complete comparison list, http://www.askmaclean.com/archives/vsqlcommand-sql-opcodes-and-names.html

LID=0 permission user ID Privilege user id.

TIM timestamp is a timestamp. Before 9i, the unit of this indicator is 1max 100s, or 10ms. After 9i, the unit is 1 microsecond of 1000000. This timestamp can be used to judge the time difference between two points in trace. The value of this TIm comes from the V$TIMER view, which is used for internal timing in Oracle.

DEP=0 represents the recursive recursive depth of the SQL, because the recursive SQL may cause the next layer of recursive SQL, if DEP=0, it is not recursive SQL, if DEP > 0, it is recursive SQL.

UID=0 UID, that is, USERID, is used to indicate who is parsing the cursor. If it is 0, it is a SYS user. The corresponding user name and UID can be obtained through the following query:

Select user#,name from user$

OG=1 OG stands for optimizer_mode. The corresponding relationship is shown in the table below.

0 cursor is not visible or the optimizer environment does not reasonably create 1-ALL_ROWS2-FIRST_ROWS3-RULE4-CHOOSE

Mis=0 this metric indicates that miss has not occurred in library cache, so we do not need hard parsing but use soft parsing or better for this resolution. Hard parsing is expensive in Oracle. Note that since cursors can be age out at any stage, including the PARSE/EXECUTE/FETCH phase, mis metrics are printed at these stages. If mis > 0, hard parsing may have occurred.

HV represents the hash value of this SQL. When there is no SQL_ID before 10g, it mainly depends on HASH VALUE to locate a SQL.

The address of AD for SQLTEXT comes from V$SQLAREA.ADDRESS.

Err stands for Oracle error code such as ORA-1555

PARSE is the first stage of SQL operation, parsing SQL

EXEC is the second phase of SQL running, running statements that have been parsed

FETCH fetch data rows from cursors

UNMAP is that when a cursor uses a temporary table, if the cursor is closed, UNMAP is used to release the resources related to the temporary table, including releasing locks and releasing temporary segments.

C is an important indicator, which represents the CPU time slice consumed in this step, and the unit after 9i is microsecond.

E Elapsed Time, which represents the natural time consumed by this step. The unit after 9i is microsecond.

There is a problem here, for example, in our example, PARSE # 20 ghetto 2000 relegated 1087 CPU_TIME > Elapsed time

Theoretically, it should be Elapsed Time = CPU TIME + WAIT TIME (time to wait for events), but because CPU TIME and Elapsed time use different clock clocks, it is possible that CPU TIME > Elapsed time when both are short, or for CPU-sensitive operations.

The related BUG are:

Bug 4161114: IN V$SQL, CPU_TIME > ELAPSED_TIMEBug 7603849: CPU_TIME > ELAPSED_TIME FOR CERTAIN SQL'S IN V$SQLBug 7580277: ELAPSED_TIME SHOWING 0 FOR CERTAIN SQL'S IN V$SQLBug 8243074: INCORRECT ELAPSED_TIME IN V$SQL

The problem may be fixed in 12c

P number of physical reads

Number of buffer get caused by CRCR consistent read

The number of buffer get caused by CU currently reading current read

Number of rows processed by r

CLOSE # [CURSOR]: centering% u eBay% u dep=%d type=%u tim=%u = = "an example of cursor closing

CLOSE cursor closes

The type of operation that type closes the cursor

0 the cursor has never been cached and executed less than 3 times, also known as hard close1 the cursor has never been cached but executed at least 3 times. If there is a free slot in session cached cursor, put the cursor into session cached cursor2. The cursor has never been cached but executed at least 3 times. The condition that the cursor is placed into session cached cursor is that the old cache age out drops 3 and the cursor is already in the cache, then it will go again.

STAT # [CURSOR] id=N cnt=0 [pid=0 pos=0 bj=0 p='SORT AGGREGATE']

STAT related line responses explain statistics of the execution plan [CURSOR] cursor number id number of rows of the execution plan starting from 1 cnt the number of rows of the data source pid the parent IDpos of the data source in the execution plan obj corresponding to the object idop= data source of the data source access operations, such as FULL SCAN

Above 11g, the following information is also provided:

STAT # 2 id=1 cnt=26 pid=0 pos=1 bj=0 p='HASH GROUP BY (cr=1143 pr=1139 pw=0 time=61372 us)'

STAT # 2 id=2 cnt=77276 pid=1 pos=1 bj=96551 p='TABLE ACCESS FULL FULLSCAN (cr=1143 pr=1139 pw=0 time=927821 us)'

CR represents the number of consistent reads PR represents the number of physical reads pw represents the number of physical writes time units are microsecond, the time-consuming cost of this step, the optimizer cost of this operation, the size of the data source evaluated by size, in bytes card evaluation optimizer cardinality Cardinality.

XCTEND rlbk=0, rd_only=1

XCTEND A sign for the end of a transaction rlbk if 1 indicates a rollback operation, 0 indicates that the rollback operation will not be rolled, that is, commit commits rd_only if 1 represents a transaction read-only, if 0 indicates that the data has changed.

Bind variable

BINDS # 20:

Kkscoacd

Bind#0

Oacdty=96 mxl=2000 (150) mxlc=00 mal=00 scl=00 pre=00

Oacflg=03 fl2=1000000 frm=01 csi=873 siz=2000 ff=0

Kxsbbbfp=7f9ccfec6420 bln=2000 avl=50 flg=05

Value= "MACLEAN

BINDS # 20: indicates that the binding variable is for cursor 20. Kkscoacd is the descriptor related to the binding variable bind # 0 description is the zero variable oacdty data type 96 is the special flag bit of ANSI fixed charoacflg representing the binding option the memory size allocated by size for this memory chunk the maximum length of the mxl binding variable the length of the actual value flg represents the binding state value= "the actual binding value of the MACLEAN

If you see a message like "bind 6: (No oacdef for this bind)", it means that the bound data was not defined at the time of trace. This may be because the cursor is not bound to a variable at the time of trace.

WAIT # 20: nam='db file scattered read' ela= 42 file#=1 block#=80386 blocks=7 obj#=96551 tim=1344883874069383

WAIT # 20 waits for the relevant wait event of cursor 20 Nam the name of the event to wait for. Its P1, P2, P3 can refer to the view V$EVENT_NAME, and the time spent waiting for the event ela can also be observed from V$SESSION and ASH. The unit is microsecondp1,p2,p3 's three description parameters for the event, see V$EVENT_NAME.

In the above example, for db file scattered read, P1 is the file number, P2 is the starting block number, and p3 is the number of blocks read, that is, db file scattered read reads 7 blocks at a time from the 80386 block of file 1.

Note that the WAIT line information that appears in 10046 is a finished wait event, while the current wait does not appear in the trace until the current wait is over. You can get the current waiting information through trace such as systemstate dump/errorstack.

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.