天下文章一大抄,网上10046的文章很多,由于平时优化接触少,用的也不怎么熟练,一些小研究,全当笔记。
10046的分析级别:
level 1:跟踪sql语句,包括解析、执行、提取、提交和回滚等。
level 4:包括变量的详细信息
level 8:包括等待事件
level 12:包括绑定变量与等待事件
其中,level 1相当于打开了sql_trace
一、开启和关闭10046
session 级别:alter session set events ’10046 trace name context forever,level X’;
system 级别 : alter system set events ’10046 trace name context forever,level X’;
关闭:alter session set events ‘10046 trace name context off’;
针对非本会话的 某一个进程设置,如果你知道他的SPID 操作系统进程号
oradebug setospid SPID;
SELECT P.SPID sPID, S.SID SID, S.USERNAME, P.PROGRAM, S.STATUS
FROM V$PROCESS P, V$SESSION S
WHERE P.ADDR = S.PADDR
AND S.USERNAME IS NOT NULL;
oradebug event 10046 trace name context forever, level X;
oradebug event 10046 trace name context off ;
下面是我自己做的一个测试:
/u01/admin/brentt/udump/brentt_ora_3257.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - 64bit Production
With the Partitioning, OLAP and Data Mining options
ORACLE_HOME = /u01/oracle
System name: Linux
Node name: ora01
Release: 2.6.32-200.13.1.el5uek
Version: #1 SMP Wed Jul 27 21:02:33 EDT 2011
Machine: x86_64
Instance name: brentt
Redo thread mounted by this instance: 1
Oracle process number: 13
Unix process pid: 3257, image: oracle@ora01 (TNS V1-V3)
*** 2014-06-25 23:39:01.327
*** ACTION NAME:() 2014-06-25 23:39:01.325
*** MODULE NAME:(SQL*Plus) 2014-06-25 23:39:01.325
*** SERVICE NAME:(SYS$USERS) 2014-06-25 23:39:01.325
*** SESSION ID:(159.5) 2014-06-25 23:39:01.325
Received ORADEBUG command 'event 10046 trace name context forever, level 12' from process Unix process pid: 3285, image:
*** 2014-06-25 23:40:12.616
WAIT #0: nam='SQL*Net message from client' ela= 262547485 driver id=1650815232 #bytes=1 p3=0 obj#=11735 tim=1370811340445621
=====================
PARSING IN CURSOR #2 len=34 dep=0 uid=31 oct=6 lid=31 tim=1370811340449809 hv=187184471 ad='6df499b0'
update t1 set id=1000 where id =10
END OF STMT
PARSE #2:c=3000,e=3636,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1370811340449776
BINDS #2:
WAIT #2: nam='enq: TX - row lock contention' ela= 2930718 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811343424894
WAIT #2: nam='enq: TX - row lock contention' ela= 2930412 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811346355507
WAIT #2: nam='enq: TX - row lock contention' ela= 2930281 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811349286138
*** 2014-06-25 23:40:24.670
WAIT #2: nam='enq: TX - row lock contention' ela= 2930520 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811352216895
WAIT #2: nam='enq: TX - row lock contention' ela= 2930691 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811355147895
WAIT #2: nam='enq: TX - row lock contention' ela= 2930881 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811358079144
WAIT #2: nam='enq: TX - row lock contention' ela= 2930293 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811361009814
*** 2014-06-25 23:40:36.675
WAIT #2: nam='enq: TX - row lock contention' ela= 2930428 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811363940472
WAIT #2: nam='enq: TX - row lock contention' ela= 2930255 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811366871177
WAIT #2: nam='enq: TX - row lock contention' ela= 2930473 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811369801838
WAIT #2: nam='enq: TX - row lock contention' ela= 2930309 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811372732490
*** 2014-06-25 23:40:48.679
WAIT #2: nam='enq: TX - row lock contention' ela= 2930475 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811375663138
WAIT #2: nam='enq: TX - row lock contention' ela= 927336 name|mode=1415053318 usn<<16 | slot=393219 sequence=2567 obj#=11735 tim=1370811376590757
EXEC #2:c=3000,e=36141257,p=0,cr=9,cu=4,mis=0,r=1,dep=0,og=1,tim=1370811376591287
WAIT #2: nam='SQL*Net message to client' ela= 22 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811376628194
WAIT #2: nam='SQL*Net message from client' ela= 778 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811376629151
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE T1 (cr=9 pr=0 pw=0 time=36101949 us)'
STAT #2 id=2 cnt=1 pid=1 pos=1 obj=11735 op='TABLE ACCESS FULL T1 (cr=8 pr=0 pw=0 time=455 us)'
WAIT #0: nam='SQL*Net message to client' ela= 783 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811376632324
WAIT #0: nam='SQL*Net message from client' ela= 2890969 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811379523447
=====================
PARSING IN CURSOR #3 len=6 dep=0 uid=31 oct=44 lid=31 tim=1370811379524495 hv=3480936638 ad='0'
commit
END OF STMT
PARSE #3:c=1000,e=695,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1370811379524466
XCTEND rlbk=0, rd_only=0
EXEC #3:c=1000,e=3802,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,tim=1370811379528506
WAIT #3: nam='SQL*Net message to client' ela= 20 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811379528734
WAIT #3: nam='SQL*Net message from client' ela= 779 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811379529631
WAIT #0: nam='SQL*Net message to client' ela= 20 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811379530751
*** 2014-06-25 23:45:07.414
WAIT #0: nam='SQL*Net message from client' ela= 248803722 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811628334761
=====================
PARSING IN CURSOR #1 len=33 dep=0 uid=31 oct=6 lid=31 tim=1370811628339229 hv=1766660651 ad='6df17858'
update t1 set id=10 where id=1000
END OF STMT
PARSE #1:c=2999,e=4157,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1370811628339199
BINDS #1:
WAIT #1: nam='enq: TX - row lock contention' ela= 2930683 name|mode=1415053318 usn<<16 | slot=589825 sequence=2572 obj#=11735 tim=1370811631272538
WAIT #1: nam='enq: TX - row lock contention' ela= 2930481 name|mode=1415053318 usn<<16 | slot=589825 sequence=2572 obj#=11735 tim=1370811634203274
WAIT #1: nam='enq: TX - row lock contention' ela= 2930275 name|mode=1415053318 usn<<16 | slot=589825 sequence=2572 obj#=11735 tim=1370811637133848
*** 2014-06-25 23:45:19.426
WAIT #1: nam='enq: TX - row lock contention' ela= 2930418 name|mode=1415053318 usn<<16 | slot=589825 sequence=2572 obj#=11735 tim=1370811640064473
WAIT #1: nam='enq: TX - row lock contention' ela= 2930362 name|mode=1415053318 usn<<16 | slot=589825 sequence=2572 obj#=11735 tim=1370811642995140
WAIT #1: nam='enq: TX - row lock contention' ela= 2931285 name|mode=1415053318 usn<<16 | slot=589825 sequence=2572 obj#=11735 tim=1370811645926591
WAIT #1: nam='enq: TX - row lock contention' ela= 2930608 name|mode=1415053318 usn<<16 | slot=589825 sequence=2572 obj#=11735 tim=1370811648857455
*** 2014-06-25 23:45:31.431
WAIT #1: nam='enq: TX - row lock contention' ela= 2930437 name|mode=1415053318 usn<<16 | slot=589825 sequence=2572 obj#=11735 tim=1370811651788065
WAIT #1: nam='enq: TX - row lock contention' ela= 2930388 name|mode=1415053318 usn<<16 | slot=589825 sequence=2572 obj#=11735 tim=1370811654718755
WAIT #1: nam='enq: TX - row lock contention' ela= 2930449 name|mode=1415053318 usn<<16 | slot=589825 sequence=2572 obj#=11735 tim=1370811657649374
WAIT #1: nam='enq: TX - row lock contention' ela= 1889366 name|mode=1415053318 usn<<16 | slot=589825 sequence=2572 obj#=11735 tim=1370811659539054
EXEC #1:c=2000,e=31198772,p=0,cr=11,cu=4,mis=0,r=1,dep=0,og=1,tim=1370811659539456
WAIT #1: nam='SQL*Net message to client' ela= 21 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811659539862
WAIT #1: nam='SQL*Net message from client' ela= 425 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811659540435
STAT #1 id=1 cnt=0 pid=0 pos=1 obj=0 op='UPDATE T1 (cr=11 pr=0 pw=0 time=31198499 us)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=11735 op='TABLE ACCESS FULL T1 (cr=10 pr=0 pw=0 time=684 us)'
WAIT #0: nam='SQL*Net message to client' ela= 436 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811659545116
*** 2014-06-25 23:46:17.147
WAIT #0: nam='SQL*Net message from client' ela= 36888022 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811696433511
PARSE #2:c=0,e=75,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1370811696433919
XCTEND rlbk=0, rd_only=0
EXEC #2:c=1000,e=450,p=0,cr=0,cu=1,mis=0,r=0,dep=0,og=0,tim=1370811696434442
WAIT #2: nam='log file sync' ela= 1293 buffer#=1220 p2=0 p3=0 obj#=-1 tim=1370811696435870
WAIT #2: nam='SQL*Net message to client' ela= 59 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811696436100
WAIT #2: nam='SQL*Net message from client' ela= 3898 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811696440517
WAIT #0: nam='SQL*Net message to client' ela= 20 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1370811696440949
PARSING IN CURSOR #2 len=34 dep=0 uid=31 oct=6 lid=31 tim=1370811340449809 hv=187184471 ad='6df499b0'
update t1 set id=1000 where id =10
END OF STMT
len表示sql语句的长度
dep表示sql语句递归深度,0表示不是递归SQL,如果DEP>0则说明是递归SQL
uid表示的USER_ID
lid表示用户权限id,好像和uid一致
SQL> select username from dba_users where user_id=31;
USERNAME
------------------------------
TEST
OCT表示Oracle中命令分类的类型 可以通过 V$SQL.COMMAND_TYPE获得对应关系,6表示update
SQL> select command_type,command_name from V$SQLCOMMAND;
time表示时间戳
HV表示sql语句的hash value
AD表示SQLTEXT的地址,来源于 V$SQLAREA.ADDRESS
==========================================================
PARSE #2:c=3000,e=3636,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=1370811340449776
OG=1 OG 代表optimizer_mode ,具体对应关系见下表
0 游标不可见 或 优化器环境未合理创建
1 – ALL_ROWS
2 - FIRST_ROWS
3 – RULE
4 – CHOOSE
c表示cpu time 单位us
e表示elapse time 单位us
p表示物理读的数目
CR表示一致性读引起的buffer get
CU当前读current read 引起的buffer get 数目
mis表示硬解析的次数
==========
PARSE 是SQL运行的第一个阶段,解析SQL
EXEC 是SQL运行的第二个阶段,运行已经解析过的语句
FETCH 从游标中 fetch数据行
TKPROF: Release 10.2.0.1.0 - Production on Wed Jun 25 23:47:52 2014
Copyright (c) 1982, 2005, Oracle. All rights reserved.
Trace file: brentt_ora_3257.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
********************************************************************************
update t1 set id=1000
where
id =10
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 2 0.00 0.00 0 0 0 0
Execute 2 0.00 36.14 0 9 5 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 4 0.00 36.14 0 9 5 1
Misses in library cache during parse: 1
Parsing user id: 31
Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE T1 (cr=9 pr=0 pw=0 time=36101949 us)
1 TABLE ACCESS FULL T1 (cr=8 pr=0 pw=0 time=455 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
enq: TX - row lock contention 13 2.93 36.09 --表示等待了13此,最大一次等待了2.93秒,总共等待了36.09秒
SQL*Net message to client 2 0.00 0.00
SQL*Net message from client 2 0.00 0.00
log file sync 1 0.00 0.00
********************************************************************************
commit
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 0.00 0 0 1 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 0.00 0 0 1 0
Misses in library cache during parse: 0
Parsing user id: 31
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
update t1 set id=10
where
id=1000
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 1 0.00 31.19 0 11 4 1
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 2 0.00 31.20 0 11 4 1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 31
Rows Row Source Operation
------- ---------------------------------------------------
0 UPDATE T1 (cr=11 pr=0 pw=0 time=31198499 us)
1 TABLE ACCESS FULL T1 (cr=10 pr=0 pw=0 time=684 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
enq: TX - row lock contention 11 2.93 31.19
SQL*Net message to client 1 0.00 0.00
SQL*Net message from client 1 0.00 0.00
********************************************************************************
OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 4 0.00 0.00 0 0 0 0
Execute 4 0.00 67.34 0 20 10 2
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 8 0.01 67.35 0 20 10 2
Misses in library cache during parse: 2
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message from client 8 262.54 551.13
enq: TX - row lock contention 24 2.93 67.28
SQL*Net message to client 8 0.00 0.00
log file sync 1 0.00 0.00
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 0 0.00 0.00 0 0 0 0
Execute 0 0.00 0.00 0 0 0 0
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 0 0.00 0.00 0 0 0 0
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: brentt_ora_3257.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.
3 unique SQL statements in trace file.
97 lines in trace file.
355 elapsed seconds in trace file.