如何收集和查看用来诊断性能问题的Tracev.docx

一、何为trace10046Event 10046是为Oracle session收集扩展的sql_trace信息的标准方法。每逢与遇到SQL相关性能，我们总是需要收集10046的，来查看和诊断问题。因为10046真实的反响的SQL语句执行的时候的真实信息，解析，执行，获取的时间消耗，row source operation的具体情况，具体等待事件，每个时间具体的时间消耗等等。二、Trace文件的位置11gR1以前:如果是用户进程，10046 trace文件会被生成在user_dump_dest下；如果是后台进程，trace文件会被生成在background_dump_dest下。下面的命令可以显示user_dump_dest:  SQL> show parameter user_dump_dest11g R1以后:从11gR1开场，Oracle引入了新的诊断构造，以参数DIAGNOSTIC_DEST控制存放trace文件与core文件的路径。可以用以下命令，获取DIAGNOSTIC_DEST的位置：   SQL> show parameter diagnostic_dest注：下面的某些例子中会设定trace，通过这个设置可以帮助我们更容易的找到生成的trace文件。三、trace10046的使用方法1.基于session/system收集信息：alter session/system set trace'10046' alter session/system set timed_statistics = true;alter session/system set statistics_level=all;alter session/system set max_dump_ = unlimited;alter session/system(慎用) set events '10046 trace name context forever, level 12'- 执行需要被trace的SQL -select * from dual;exit;Alter session/system(慎用) set events '10046 trace name context off'注：1如果session没有被彻底地关闭并且跟踪被停顿了，某些重要的trace信息的可能会丧失。2这里我们将"statistics_level"设置为all，这是因为有可能这个参数在系统级不是默认值"TYPICAL"比方 BASIC。为了收集性能相关问题的信息我们需要翻开某个级别的statistics。我们推荐在 session 级将这个参数设置成 ALL 以便于收集更多的信息，尽管这不是必须的。2. 在system级别指定sql_id收集信息： SQL> alter system set events 'sql_trace sql: 5qcyrymp65fak level=12'关闭 event +：SQL> alter system set events 'sql_trace sql: 5qcyrymp65fak off'注释：event+在system级别指定sql_id,对新起的会话和当前的会话有效， 对其他已经存在的会话无效3. event + 指定某个process的sql_id收集信息：指定检测的会话的spidselect spid from V$process, V$session where audsid=userenv('SESSIONID') and paddr=addr; SQL> oradebug setospid <SPID> SQL> oradebug unlimitSQL> oradebug traceSQL> oradebug event sql_trace sql: 5qcyrymp65fak level=12关闭 event +：SQL> oradebug event sql_trace sql: 5qcyrymp65fak off4. 当不知道SQL_ID时手动执行SQL收集信息：SQL>connect username/passwordSQL>alter session set timed_statistics = true;SQL>alter session set statistics_level=all;SQL>alter session set max_dump_ = unlimited;SQL> select value from v$diag_info where name='Default Trace File' <<<<在11g以上工作SQL> variable a1 <the type of ACCOUNT_TYPE_ID> <<<<<请执行类型SQL> exec :a1 := 123123或'abded' <<<<<<<请设置数值或字符串SQL>alter session set events '10046 trace name context forever, level 12'SQL>UPDATE /*+ RESTRICT_ALL_REF_CONS */ "LBI_ODS"."T_O_CUSTOMER_ACCOUNT" SET "ACCOUNT_TYPE_ID" = :a1 WHERE"ACCOUNT_NO" = 1234565; -执行sql重现问题SQL>alter session set events '10046 trace name context off' 5.使用Trigger设置10046收集信息：Use a Logon TriggerTo start tracing: create or replace trigger user_logon_trg after logon on database begin if USER = 'xxxx' then execute immediate 'Alter session set events ''10046 trace name context forever, level 8''' end if; end; / /* Login a new session as User 'xxxx' and execute your selects to be traced */ To stop tracing: via LogOff Trigger (needs to be created before logging off) create or replace trigger user_logoff_trg before logoff on database begin if USER = 'xxxx' then execute immediate 'Alter session set events ''10046 trace name context off''' end if; end; /的10046收集信息：1 请翻开auto purge的trace begin (service_name=>'SYS$BACKGROUND', module_name=>'MMON_SLAVE', action_name=>'Auto-Purge Slave Action'); end; /2 请至少等待一天，请您明天查看时候auto purge被执行，并产生m00x trace文件包含100463关闭auto purge的trace begin (service_name=>'SYS$BACKGROUND', module_name=>'MMON_SLAVE', action_name=>'Auto-Purge Slave Action'); end; /8.Data pump 10046收集信息：1. enable 10046 trace for DM/DW process alter system set events 'sql_traceprocess: pname=dw | pname=dm level=12'2. Please reproduce the issue, then add "TRACE=480300" in data pump importing command3. Please upload data pump importing log and the generated DM/DW process trace To disable the tracing by issuing: alter system set events 'sql_trace process : pname = dw | pname = dm off' 9.其他方式设置10046：1)DBMS_SUPPORT To start tracing: exec sys.dbms_support.start_trace ; /* execute your selects to be traced */ To stop tracing: exec sys.dbms_support.stop_trace ; Tracing from Another SessionThe examples below demonstrate how to trace session with SID=18 and Serial# =226 obtained from V$SESSION.2)Using "dbms_system.SET_BOOL_PARAM_IN_SESSION"To start tracing: exec sys.dbms_system.SET_BOOL_PARAM_IN_SESSION(18, 226, 'sql_trace', TRUE); /* execute your selects to be traced */ To stop tracing: exec sys.dbms_system.SET_BOOL_PARAM_IN_SESSION(18, 226, 'sql_trace', FALSE);3)Using "dbms_system.set_ev"To start tracing: exec dbms_system.set_ev(18, 226, 10046, 12, ''); To stop tracing: exec dbms_system.set_ev(18, 226, 10046, 0, '');4)Using "dbms_system.set_sql_trace_in_session"To start tracing: exec dbms_system.set_sql_trace_in_session(18,226,TRUE); /* execute your selects to be traced */ To stop tracing: exec dbms_system.set_sql_trace_in_session(18,226,FALSE);5)Using "sys.dbms_monitor"To start tracing: exec sys.dbms_monitor.session_trace_enable(session_id=>18,serial_num=>226, waits=>true, binds=>true); /* execute your selects to be traced */ To stop tracing: exec sys.dbms_monitor.session_trace_disable(session_id=>18,serial_num=>226);6)Using Oradebug (as SYS)To start tracing: oradebug setospid xxxx oradebug event 10046 trace name context forever, level 12; /* In the session being traced execute the selects */ To stop tracing:oradebug event 10046 trace name context off ;四、跟踪一个已经开场的进程如果需要跟踪一个已经存在session，可以用 oradebug连接到session上，并发起10046 trace。首先，用某种方法找到需要被跟踪的session.下面是一个实验的例子:会话1：angel用户conn angel/angel查出会话1的spid即进程idSQL> select spid from v$process where addr in (select paddr from v$session where sid in (select sid from v$mystat where rownum =1);SPID18709SPID 是操作系统的进程标识符os pidPID 是Oracle的进程标识符(ora pid)一旦找到OS PID，就可以用以下命令初始化跟踪：假设需要被跟踪的OSPID是18709。会话2以sysdba的身份登录到SQL*Plus并执行下面的命令：会话2：connect / as sysdbaoradebug setospid 18709这里的18709是进程idoradebug unlimitoradebug event 10046 trace name context forever,level 12会话1：执行查询语句在angel用户下执行查询的语句select * from object where object_id=54530;跟踪过程完成以后，关闭oradebug跟踪：oradebug event 10046 trace name context off查看输出的trace文件的路径oradebug trace!tail -100f 输出的trace文件用tkprof命令对trace文件进展格式化，使得trace文件的可读性更强。oracleoracle1 trace$ cd /oracle/app/oracle/diag/rdbms/rac/rac1/trace/output = trace_object这里输入希望生成的文件名查看生成的trace10046文件tail -200f trace_object.prf五、如何查trace10046文件oracleoracle1 trace$ cat trace_object.prf TKPROF: Release 11.2.0.4.0 - Development on Tue Nov 8 15:47:41 2021Copyright (c) 1982, 2021, Oracle and/or its affiliates. All rights reserved.Sort 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*-下面是对sql递归查询的解析，即系统表查询的消耗比方select表的时候，它会先去查数据字典查询表的构造的消耗比方去system表空间里面的dba_tables查询所要查询的表这一局部的消耗，相当于文件尾部的OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS ，可以对照看一下SQL ID: 1y2dmwsz263gg Plan Hash: 1359689960-下面的复杂sql可以说是系统解析出来的它如何执行的详解，通俗一点就是指它解析出来自己可以识别出来的语言SELECT /* OPT_DYN_SAMP */ /*+ ALL_ROWS IGNORE_WHERE_CLAUSE NO_PARALLEL(SAMPLESUB) opt_param('parallel_execution_enabled', 'false') NO_PARALLEL_INDEX(SAMPLESUB) NO_SQL_TUNE */ NVL(SUM(C1),:"SYS_B_0"), NVL(SUM(C2),:"SYS_B_1") FROM (SELECT /*+ IGNORE_WHERE_CLAUSE NO_PARALLEL("OBJECT") FULL("OBJECT") NO_PARALLEL_INDEX("OBJECT") */ :"SYS_B_2" AS C1, CASE WHEN "OBJECT"."OBJECT_ID"=:"SYS_B_3" THEN :"SYS_B_4" ELSE :"SYS_B_5" END AS C2 FROM "ANGEL"."OBJECT" SAMPLE BLOCK (:"SYS_B_6" , :"SYS_B_7") SEED (:"SYS_B_8") "OBJECT") SAMPLESUBcall 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 1 0.00 0.00 0 65 0 1- - - - - - - -total 3 0.00 0.00 0 65 0 1Misses in library cache during parse: 1-指在library cache解析的次数，相当于上面的parseMisses in library cache during execute: 1-指在library cache执行的次数，相当于上面的Execute Optimizer mode: ALL_ROWSParsing user id: 84 (recursive depth: 1这里指递归的深度是1)Number of plan statistics captured: 1Rows (1st) Rows (avg) Rows (max) Row Source Operation- - - - 1 1 1 SORT AGGREGATE (cr=65 pr=0 pw=0 time=1624 us)cr一致性读 4162 4162 4162 TABLE ACCESS SAMPLE OBJECT (cr=65 pr=0 pw=0 time=256 us cost=19 size=128650 card=5146)*SQL ID: 1vutkh44h5q2z Plan Hash: 4096911683主要看sqlid下面这一段，指非递归的查询消耗不包括查系统表的消耗，相当于trace文件后面的OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS因为主要的消耗是sql本身执行的消耗，关于系统表解析消耗比拟小，但是关于递归的查询系统表等系统有关的解析也要看一下正不正常，有时候一些bug或者特殊情况也会使递归的解析偏大select * from object where object_id=54530-执行的sql语句parse count: 指在library cache解析的次数，相当于下面的parseexecute count：指在library cache执行次数，相当于下面的Executefetch count：是指select返回的次数像insert，update，delete这种dml，返回的次数是0total count：parse count+execute count+fetch count，即总的count消耗次数cpu：消耗的cputimeelapsed：dbtimecputime+wait不包括非空闲等待disk：物理读query：逻辑读rows：返回的行数call count cpu elapsed disk query current rows- - - - - - - -Parse 1 0.00 0.00 0 66 0 0Execute 1 0.00 0.00 0 0 0 0Fetch 2 0.02 0.25 1232 1236 0 1- - - - - - - -total 4 0.03 0.26 1232 1302 0 1Misses in library cache during parse: 1-在library cache中解析的次数Optimizer mode: ALL_ROWSParsing user id: 84 -解析的useridNumber of plan statistics captured: 1在trace的这段时间中只采样到一次执行方案-执行方案Rows (1st) Rows (avg) Rows (max) Row Source Operation- - - - 1 1 1 TABLE ACCESS FULL OBJECT (cr=1236 pr=1232 pw=0 time=206070 us cost=344 size=4140 card=20)-等待事件Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited - Waited - -*OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS-非递归查询，不包括系统表的查询的消耗，即只sql本身的执行消耗call count cpu elapsed disk query current rows- - - - - - - -Parse 1 0.00 0.00 0 66 0 0Execute 1 0.00 0.00 0 0 0 0Fetch 2 0.02 0.25 1232 1236 0 1- - - - - - - -total 4 0.03 0.26 1232 1302 0 1Misses in library cache during parse: 1Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited - Waited - -OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS-递归查询，系统表查询的消耗call 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 1 0.00 0.00 0 65 0 1- - - - - - - -total 3 0.00 0.00 0 65 0 1Misses in library cache during parse: 1Misses in library cache during execute: 1 2 user SQL statements in session. 0 internal SQL statements in session. 2 SQL statements in session.*Sort options: default 1 session in tracefile. 2 user SQL statements in trace file. 0 internal SQL statements in trace file. 2 SQL statements in trace file. 2 unique SQL statements in trace file. 136 lines in trace file. 0 elapsed seconds in trace file.六、总结Trace10046的结果相对来说算比拟准确的，在生产中，假设要比对执行方案的优劣，也可以通过trace10046工具，将两个执行方案不同的一样sql放到同一个trace文件中，利用ue等工具截取出主要的局部进展比对。参考文档：sr参考博客：E6%81%AF%E7%9A%84%E6%94%B6%E9%9B%86