@H_403_0@1、什么是10046事件 @H_403_0@ 10046事件是Oracle提供的一个用于分析性能的工具,它能帮助我们解析一条/多条sql、PL/sql语句的运行状态,这些状态包括 :Parse/Fetch/Execute三个阶段中遇到的等待事件、消耗的物理和逻辑读、cpu时间、执行计划等等。 @H_403_0@2、10046事件的Level @H_403_0@不同的Level对应不同的跟踪级别
- @H_403_0@1 启用标准的sql_TRACE功能(默认)包含了sql语句、响应时间、服务时间、处理的行数,物理读和写的数目、执行计划以及其他一些额外信息。到版本10.2中执行计划写入到trace的条件是仅当相关游标已经关闭时,且与之相关的执行统计信息是所有执行次数的总和数据。到版本11.1中仅在每次游标的第一次执行后将执行计划写入到trace,执行统计信息仅仅和这第一次执行相关
- @H_403_0@4 比level 1时多出绑定变量的trace
- @H_403_0@8 比level 1多出等待事件,特别对于9i中指出latchfree等待事件很有用,对于分析全表扫描和索引扫描也很有用
- @H_403_0@12 比level 1多出绑定变量和等待事件
@H_403_0@5、获取10046事件生成的trace文件 @H_403_0@a.对于11g及以上的版本,使用如下语句可以轻松得到 @H_403_0@select value from v$diag_info where name='Default Trace File'; @H_403_0@b.对于10g及以前的版本中需要使用如下sql
SELECTD.VALUE||''||LOWER(RTRIM(I.INSTANCE,CHR(0)))||'_ora_'|| P.SPID||'.trc'TRACE_FILE_NAME FROM(SELECTP.SPID FROMSYS.V$MYSTATM,SYS.V$SESSIONS,SYS.V$PROCESSP WHEREM.STATISTIC#=1 ANDS.SID=M.SID ANDP.ADDR=S.PADDR)P,(SELECTT.INSTANCE FROMSYS.V$THREADT,SYS.V$PARAMETERV WHEREV.NAME='thread' AND(V.VALUE=0ORT.THREAD#=TO_NUMBER(V.VALUE)))I,(SELECTVALUEFROMSYS.V$PARAMETERWHERENAME='user_dump_dest')D;@H_403_0@c.如果使用oradebug命令则使用相对应的oradebug tracefile_name即可得到trace文件 @H_403_0@6、格式化trace文件 @H_403_0@10046事件所产生的原始trace文件习惯称之为裸trace文件(raw trace),Oracle记录在裸trace文件中的内容一眼看上去并不是那么观,也不是那么容易看懂。为了�trace文件能够以一种更直观、更容易懂的方式展现出来,Oracle提供了tkprof命令,这个命令是Oracle自带的,可以用它来翻译�trace文件。 @H_403_0@tkprof的语法如下:
[oracle@rhel610046]$tkprof Usage:tkproftracefileoutputfile[explain=][table=] [print=][insert=][sys=][sort=] table=schema.tablenameUse'schema.tablename'with'explain='option. explain=user/passwordConnecttoORACLEandissueEXPLAINPLAN. print=integerListonlythefirst'integer'sqlstatements. aggregate=yes|no insert=filenameListsqlstatementsanddatainsideINSERTstatements. sys=noTKPROFdoesnotlistsqlstatementsrunasuserSYS. record=filenameRecordnon-recursivestatementsfoundinthetracefile. waits=yes|noRecordsummaryforanywaiteventsfoundinthetracefile. sort=optionSetofzeroormoreofthefollowingsortoptions: prscntnumberoftimesparsewascalled prscpucputimeparsing prselaelapsedtimeparsing prsdsknumberofdiskreadsduringparse prsqrynumberofbuffersforconsistentreadduringparse prscunumberofbuffersforcurrentreadduringparse prsmisnumberofmissesinlibrarycacheduringparse execntnumberofexecutewascalled execpucputimespentexecuting exeelaelapsedtimeexecuting exedsknumberofdiskreadsduringexecute exeqrynumberofbuffersforconsistentreadduringexecute execunumberofbuffersforcurrentreadduringexecute exerownumberofrowsprocessedduringexecute exemisnumberoflibrarycachemissesduringexecute fchcntnumberoftimesfetchwascalled fchcpucputimespentfetching fchelaelapsedtimefetching fchdsknumberofdiskreadsduringfetch fchqrynumberofbuffersforconsistentreadduringfetch fchcunumberofbuffersforcurrentreadduringfetch fchrownumberofrowsfetched useriduseridofuserthatparsedthecursor@H_403_0@7、简单示例,数据库版本11.2.0.4
zx@ORCL>altersessionsetevents'10046tracenamecontextforever,level12'; Sessionaltered. zx@ORCL>select*fromscott.emp; EMPNOENAME JOB MGRHIREDATE SALCOMMDEPTNO ------------------------------------------------------------------------------------------------------------------------------ 7369SMITH CLERK 79021980-12-1700:00:00 800 20 7499ALLEN SALESMAN 76981981-02-2000:00:00 1600300 30 ...... 14rowsselected. zx@ORCL>altersessionsetevents'10046tracenamecontextoff'; Sessionaltered. zx@ORCL>selectvaluefromv$diag_infowherename='DefaultTraceFile'; VALUE ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ /u02/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3239.trc zx@ORCL>! [oracle@rhel6trace]$tkprof/u02/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3239.trc10046.trc TKPROF:Release11.2.0.4.0-DevelopmentonThuFeb1621:38:572017 Copyright(c)1982,2011,Oracleand/oritsaffiliates.Allrightsreserved. [oracle@rhel6trace]$cat10046.trc TKPROF:Release11.2.0.4.0-DevelopmentonThuFeb1621:38:572017 Copyright(c)1982,Oracleand/oritsaffiliates.Allrightsreserved. Tracefile:/u02/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_3239.trc Sortoptions:default ******************************************************************************** count=numberoftimesOCIprocedurewasexecuted cpu=cputimeinsecondsexecuting elapsed=elapsedtimeinsecondsexecuting disk=numberofphysicalreadsofbuffersfromdisk query=numberofbuffersgottenforconsistentread current=numberofbuffersgottenincurrentmode(usuallyforupdate) rows=numberofrowsprocessedbythefetchorexecutecall ******************************************************************************** ......省略部分内容 ******************************************************************************** sqlID:ggqns3c1jz86cPlanHash:3956160932 select* from scott.emp callcountcpuelapseddiskquerycurrentrows ----------------------------------------------------------------------- Parse10.000.000000 Execute10.000.000000 Fetch20.000.0007014 ----------------------------------------------------------------------- total40.000.0007014 Missesinlibrarycacheduringparse:0 Optimizermode:ALL_ROWS Parsinguserid:SYS Numberofplanstatisticscaptured:1 Rows(1st)Rows(avg)Rows(max)RowSourceOperation --------------------------------------------------------------------------------- 141414TABLEACCESSFULLEMP(cr=7pr=0pw=0time=81uscost=3size=532card=14) Elapsedtimesincludewaitingonfollowingevents: EventwaitedonTimesMax.WaitTotalWaited ----------------------------------------Waited---------------------- sql*Netmessagetoclient20.000.00 sql*Netmessagefromclient20.000.00 ******************************************************************************** ......省略部分内容@H_403_0@参考文档:https://blogs.oracle.com/askmaclean/entry/maclean教你读oracle_10046_sql_trace @H_403_0@MOS文档EVENT: 10046 "enable sql statement tracing (including binds/waits)" (文档 ID 21154.1) @H_403_0@How To Collect 10046 Trace (sql_TRACE) Diagnostics for Performance Issues (文档 ID 376442.1) @H_403_0@官方文档:http://docs.oracle.com/cd/E11882_01/server.112/e41573/sqltrace.htm#PFGRF94981