トレースは、Oracleデータベースのチューニングにとって重要な部分です。これは、すべての問題ステートメント、セッションの低速実行の原因となる待機イベントをキャプチャするのに役立ちます。
Oracleデータベースには、ローカルセッション、他のユーザーセッションをトレースし、トレースをフォーマットして読み取り可能にするための最も迅速な方法が多数用意されています
SQLトレース、Oracleデータベースの10046イベント、およびtrcsess、tkprofユーティリティをオンにする方法を見てみましょう
目次
SQLトレース、100046イベント
ローカルセッションでトレースする場合は、SQLトレースをオンにする手順は次のとおりです。
Normal trace alter session set sql_trace = true; -- To put trace on alter session set sql_trace = false; -- To put trace off Full level with wait event And bind trace alter session set events = ‘10046 trace name context forever, level 12’; To put tracing off alter session set events = ‘10046 trace name context off’; Same as Normal trace exec DBMS_SESSION.set_sql_trace(sql_trace => TRUE); exec DBMS_SESSION.set_sql_trace(sql_trace => FALSE);
実行中の他のセッションでトレースする場合の手順は次のとおりです
Normal trace execute dbms_system.set_sql_trace_in_session (‘sid’,’serial’,true); -- To put tracing on execute dbms_system.set_sql_trace_in_session (‘sid’,’serial’,true); -- To put tracing off Full level with wait event And bind trace execute dbms_system.set_ev(‘sid’,’serial’,10046,12,’’); To put trace off execute dbms_system.set_ev(‘sid’,’serial’,10046,0,’’);を実行します。
上記のさまざまなステートメントで12.0を使用していることを確認したはずです。これらはトレースレベルです。OracleTracingにはトレースレベルがあります。有効な値は次のとおりです
| 0 | トレースなし。 sql_traceをオフにするようなものです。 |
| 2 | 通常のsql_traceと同等 実行パス、行数、最小のフラットファイルを提供します 利点 実行パスを提供します 行数を提供します 最小のフラットファイルを生成します 短所 実行時にSQLに提供された値がわからない クエリの統計が低いが実行時間が長い場合、どのイベントが長い待機を引き起こしたかわからない |
| 4 | 2と同じですが、バインド変数値が追加されています 利点 実行パスを提供します 行数を提供します ステートメントが実行された値を確認できます 短所 繰り返しますが、実行時間が長く、統計が少ない場合、このタイプのトレースで理由を判断するのは困難です。 バインド変数情報を保存する必要があるため、通常のトレースよりも大きなフラットファイルが生成されます。 |
| 8 | 2と同じですが、待機イベントが追加されています。 通常のトレースと、SQLが完了するのを待機したデータベース操作のタイミング。例：ディスクアクセスのタイミング。 利点 実行パスを提供します 行数を提供します SQLに関連するすべてのイベントのタイミングを通知できます。 短所 トレースファイルは、Oracleがトレースファイルに書き込む必要のあるすべての情報のために簡単に最大になる可能性があり、トレースファイルでは部分的な情報しか利用できません。 バインド変数情報は利用できません |
| 12 | 2と同じですが、バインド変数値と待機イベントの両方があります。 待機情報とバインド情報の両方を含む通常のトレース。最も完全な情報が含まれ、最大のトレースファイルが生成されます。 実行パスを提供します 行数を提供します SQLに関連するすべてのイベントのタイミングを通知できます。 どの値を通知できますかSQLは 利点で実行されました 実行パスを提供します 行数を提供します SQLに関連するすべてのイベントのタイミングを通知できます。 SQLが実行された値を通知できます 短所 Oracleがトレースファイルに書き込む必要のあるすべての情報が原因で、トレースファイルが簡単に最大化する可能性があります。トレースファイルでは、部分的な情報しか使用できません。 |
トレースを行う方法は他にもあります。これらの一部を次に示します
（1）ORADEBUG
これにはsysdbaとしてのログインが必要です
oradebug setospid 1111 -- Debug session with the specified Oracle process id oradebug setorapid 1111 --- Debug session with the specified OS process oradebug event 10046 trace name context forever, level 4; oradebug event 10046 trace name context off; --- This disable the trace oradebug close_trace --- This closes the trace file Oradebug TRACEFILE_NAME;
（2）Oracle 10gでは、DBMS_MONITORパッケージを使用してSQLトレースオプションが拡張されました
EXECUTE dbms_monitor.session_trace_enable
Which is similar
ALTER SESSION SET EVENTS '10046 trace name context forever, level 2';
EXECUTE dbms_monitor.session_trace_enable (binds=>true);
Which is similar
ALTER SESSION SET EVENTS '10046 trace name context forever, level 4';
EXECUTE dbms_monitor.session_trace_enable (waits=>true);
Which is similar
ALTER SESSION SET EVENTS '10046 trace name context forever, level 8';
EXECUTE dbms_monitor.session_trace_enable('sid','serial#')
Which is similar
execute dbms_system.set_ev(‘sid’,’serial’,10046,2,’’);
EXECUTE dbms_monitor.session_trace_enable ('sid','serial#',binds=>true);
Which is similar
execute dbms_system.set_ev(‘sid’,’serial’,10046,4,’’);
EXECUTE dbms_monitor.session_trace_enable ('sid','serial#',waits=>true);
Which is similar
execute dbms_system.set_ev(‘sid’,’serial’,10046,8,’’); dbms_monitorで利用できる他の多くの機能があります。クライアント識別子と複数の方法に基づいてトレースを有効にできます
トレースファイルを識別する方法
セッションのspidを使用してトレースファイルを識別できます。また、トレースファイルには、トレースファイルの先頭にsid、serial＃のペアが含まれます。
以下のクエリを使用して、ローカルセッションのトレースファイルを見つけることができます
select c.value || '/' || d.instance_name ||'_ora_' || a.spid || '.trc' trace
from v$process a, v$session b, v$parameter c, v$instance d
where a.addr = b.paddr
and b.audsid = userenv('sessionid')
and c.name = 'user_dump_dest'
/
トレース識別子と呼ばれるトレースファイルを識別する別の簡単な方法があります
alter session set tracefile_identifer=’ORAC’; This is identifier
トレースファイルの例
Trace file /app/oracle/TEST/diag/rdbms/test/TEST/trace/TEST_ora_13025_IDEN.trc Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production With the Partitioning, Real Application Clusters, OLAP, Data Mining and Real Application Testing options ORACLE_HOME = /app/oracle/TEST/11.2.0/db System name: SunOS12 Node name: sun12Release: 5.10Version: Generic_144488-11 Machine: sun4u Instance name: TEST Redo thread mounted by this instance: 1 Oracle process number: 202 Unix process pid: 13025, image: [email protected] SunOS12 *** 2013-10-21 12:28:56.461 *** SESSION ID:(3875.17341) 2013-10-21 12:28:56.461*** CLIENT ID:() 2013-10-21 12:28:56.461 *** SERVICE NAME:(TEST) 2013-10-21 12:28:56.461 *** MODULE NAME:([email protected](TNS V1-V3)) 2013-10-21 12:28:56.461 *** ACTION NAME:() 2013-10-21 12:28:56.461 CLOSE #4:c=0,e=11,dep=1,type=1,tim=8866891135825 ===================== PARSING IN CURSOR #5 len=356 dep=1 uid=173 oct=3 lid=173 tim=8866891136821 hv=2468783182 ad='4c70e4398' sqlid='0wmwsjy9kd92f'SELECT PROFILE_OPTION_ID, APPLICATION_ID, SITE_ENABLED_FLAG , APP_ENABLED_FLAG , RESP_ENABLED_FLAG , USER_ENABLED_FLAG, ORG_ENABLED_FLAG , SERVER_ENABLED_FLAG, SERVERRESP_ENABLED_FLAG, HIERARCHY_TYPE, USER_CHANGEABLE_FLAG FROM FND_PROFILE_OPTIONS WHERE PROFILE_OPTION_NAME = :B1 AND START_DATE_ACTIVE <= SYSDATE AND NVL(END_DATE_ACTIVE, SYSDATE) >= SYSDATEEND OF STMT BINDS #5: Bind#0 oacdty=01 mxl=128(80) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1206001 frm=01 csi=871 siz=128 off=0 kxsbbbfp=ffffffff7d677b48 bln=128 avl=21 flg=0 value="PER_BUSINESS_GROUP_ID" EXEC #5:c=0,e=1474,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1374985481,tim=8866891138224 FETCH #5:c=0,e=61,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=1,plh=1374985481,tim=8866891138429 CLOSE #5:c=0,e=5,dep=1,type=3,tim=8866891138503 ===================== PARSING IN CURSOR #4 len=230 dep=1 uid=173 oct=3 lid=173 tim=8866891138634 hv=3575592451 ad='3aeea3da0' sqlid='55dc767ajydh3' SELECT PROFILE_OPTION_VALUE FROM FND_PROFILE_OPTION_VALUES WHERE PROFILE_OPTION_ID = :B4 AND APPLICATION_ID = :B3 AND LEVEL_ID = 10003 AND LEVEL_VALUE = :B2 AND LEVEL_VALUE_APPLICATION_ID = :B1 AND PROFILE_OPTION_VALUE IS NOT NULL END OF STMT BINDS #4: Bind#0 oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1206001 frm=00 csi=00 siz=96 off=0 kxsbbbfp=ffffffff7d677b68 bln=22 avl=03 flg=05 value=1204 Bind#1 oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=24 kxsbbbfp=ffffffff7d677b80 bln=22 avl=02 flg=01 value=800 Bind#2 oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=48 kxsbbbfp=ffffffff7d677b98 bln=22 avl=04 flg=01 value=50334 Bind#3 oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=72 kxsbbbfp=ffffffff7d677bb0 bln=22 avl=01 flg=01 value=0 EXEC #4:c=0,e=377,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=2802907561,tim=8866891138978 FETCH #4:c=0,e=26,p=0,cr=3,cu=0,mis=0,r=0,dep=1,og=1,plh=2802907561,tim=8866891139050 CLOSE #4:c=0,e=2,dep=1,type=3,tim=8866891139116 ===================== PARSING IN CURSOR #5 len=191 dep=1 uid=173 oct=3 lid=173 tim=8866891139308 hv=303338305 ad='3bedf0e48' sqlid='7qs7fx89194u1' SELECT PROFILE_OPTION_VALUE FROM FND_PROFILE_OPTION_VALUES WHERE PROFILE_OPTION_ID = :B4 AND APPLICATION_ID = :B3 AND LEVEL_ID = :B2 AND LEVEL_VALUE = :B1 AND PROFILE_OPTION_VALUE IS NOT NULL END OF STMT BINDS #5: Bind#0 oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1206001 frm=00 csi=00 siz=96 off=0 kxsbbbfp=ffffffff7d673b78 bln=22 avl=03 flg=05 value=1204 Bind#1 oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=24 kxsbbbfp=ffffffff7d673b90 bln=22 avl=02 flg=01 value=800 Bind#2 oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00 oacflg=03 fl2=1206001 frm=00 csi=00 siz=0 off=48 kxsbbbfp=ffffffff7d673ba8 bln=22 avl=04 flg=01 value=10001
Oracleでトレースが有効になっているかどうかを確認する方法
DBMS_MONITORパッケージを使用してトレースを有効にしている場合は、以下のクエリを使用してトレースが有効になっているかどうかを確認できます
set lines 180 col module for a45 col sql_trace_waits for a20 col sql_trace_binds for a20 col sql_trace for a20 select username,module,sid,sql_trace,sql_trace_waits,sql_trace_binds from v$session where sql_trace='ENABLED' /
他の方法で有効になっている場合、確認する唯一の方法は、トレースの場所を調べて、最近のトレースファイルを見つけ、その中のsidとserial＃を見つけてから、v$sessionをクエリしてセッションで、必要に応じてトレースを無効にできます
Oracletkprofユーティリティ
上記の方法で取得したトレースファイルは生の形式であり、tkprofユーティリティ（Transient Kernel PROFileユーティリティ）を使用してより読みやすい形式に変換できます
tkprof Usage: tkprof tracefile outputfile [explain= ] [table= ] [print= ] [insert= ] [sys= ] [sort= ] table=schema.tablename Use 'schema.tablename' with 'explain=' option. explain=user/password Connect to ORACLE and issue EXPLAIN PLAN. print=integer List only the first 'integer' SQL statements. aggregate=yes|no insert=filename List SQL statements and data inside INSERT statements. sys=no TKPROF does not list SQL statements run as user SYS. record=filename Record non-recursive statements found in the trace file. waits=yes|no Record summary for any wait events found in the trace file. sort=option Set of zero or more of the following sort options: prscnt number of times parse was called prscpu CPU time parsing prsela elapsed time parsing prsdsk number of disk reads during parse prsqry number of buffers for consistent read during parseprscu number of buffers for current read during parseprsmis number of misses in library cache during parseexecnt number of execute was called execpu CPU time spent executing exeela elapsed time executing exedsk number of disk reads during execute exeqry number of buffers for consistent read during execute execu number of buffers for current read during execute exerow number of rows processed during execute exemis number of library cache misses during execute fchcnt number of times fetch was called fchcpu cpu time spent fetching fchela elapsed time fetching fchdsk number of disk reads during fetch fchqry number of buffers for consistent read during fetch fchcu number of buffers for current read during fetch fchrow number of rows fetched userid userid of user that parsed the cursor
いくつかの例
tkprof file.trc file.txt sys=no explain=userid/password sort=prsela,exeela,fchela tkprof file.trc file.txt sys=no explain=userid/password sort=prsela,exeela,fchela tkprof file.trc file.txt sys=no tkprof file.trc file.txt sys=no explain=userid/password sort=prsela,exeela,fchela This print 10 sql only tkprof .trc elaps.prf sys=no explain=apps/ sort=(prsela,exeela,fchela) print=10 This print all the sql tkprof .trc elaps.prf sys=no explain=apps/apps sort=prsela,exeela,fchela
tkprofファイルのコンテンツ例
TKPROF: Release 11.2.0.4.0 - Production on Tue Jan 17 14:12:41 2013 Copyright (c) 1982, 2007, Oracle. All rights reserved. Trace file: TEST_ora_15941.trc Sort options: execpu fchcpu ******************************************************************************** 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 ******************************************************************************** SQL ID: 6w82ggrtysx Plan Hash: 2325776775 SELECT FUNCTION_NAME FROM FND_USER_DESKTOP_OBJECTS WHERE USER_ID = :b1 AND APPLICATION_ID = :b2 AND RESPONSIBILITY_ID = :b3 AND TYPE = 'FUNCTION' AND ROWNUM <= 10 ORDER BY SEQUENCE 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 0 0 Fetch 2 0.00 0.00 0 4 0 1 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 4 0.00 0.00 0 4 0 1 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 173 (APPS) Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 1 1 1 SORT ORDER BY (cr=4 pr=0 pw=0 time=0 us cost=6 size=41 card=1) 1 1 1 COUNT STOPKEY (cr=4 pr=0 pw=0 time=0 us) 1 1 1 TABLE ACCESS BY INDEX ROWID FND_USER_DESKTOP_OBJECTS (cr=4 pr=0 pw=0 time=0 us cost=5 size=41 card=1) 1 1 1 INDEX RANGE SCAN FND_USER_DESKTOP_OBJECTS_N1 (cr=3 pr=0 pw=0 time=0 us cost=3 size=0 card=3)(object id 33596) Rows Execution Plan ------- --------------------------------------------------- 0 SELECT STATEMENT MODE: ALL_ROWS 1 SORT (ORDER BY) 1 COUNT (STOPKEY) 1 TABLE ACCESS MODE: ANALYZED (BY INDEX ROWID) OF 'FND_USER_DESKTOP_OBJECTS' (TABLE) 1 INDEX MODE: ANALYZED (RANGE SCAN) OF 'FND_USER_DESKTOP_OBJECTS_N1' (INDEX) Elapsed times include waiting on following events: Event waited on Times Max. Wait Total Waited ---------------------------------------- Waited ---------- ------------ SQL*Net message to client 5 0.00 0.00 SQL*Net message from client 5 0.00 0.00******************************************************************************** SQL ID: 276ut2ywqux Plan Hash: 3856112528 select object_name, icon_name from fnd_desktop_objects 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 0 0 Fetch 3 0.00 0.00 0 6 0 47 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 5 0.00 0.00 0 6 0 47 Misses in library cache during parse: 0 Optimizer mode: ALL_ROWS Parsing user id: 173 (APPS) Number of plan statistics captured: 1 Rows (1st) Rows (avg) Rows (max) Row Source Operation ---------- ---------- ---------- --------------------------------------------------- 47 47 47 TABLE ACCESS FULL FND_DESKTOP_OBJECTS (cr=6 pr=0 pw=0 time=0 us cost=2 size=1175 card=47) Rows Execution Plan ------- --------------------------------------------------- 0 SELECT STATEMENT MODE: ALL_ROWS 47 TABLE ACCESS MODE: ANALYZED (FULL) OF 'FND_DESKTOP_OBJECTS' (TABLE)
Oracle trcsess ユーティリティ
共有サーバーセッションを使用する場合、多くのプロセスが関係します。ユーザーセッションに関連するトレースは、さまざまなプロセスに属するさまざまなトレースファイルに分散しています。これにより、セッションのライフサイクルの全体像を把握することが困難になります。
trcsessユーティリティは、いくつかの基準に基づいて、選択したトレースファイルからのトレース出力を統合します
trcsess [output=output_file_name] [session=session_id] [clientid=client_id] [service=service_name] [action=action_name] [module=module_name] [trace_files] trcsess output=main.trc service=TEST *trc
統合トレースファイルが生成されたら、そのファイルでtkprofを実行できます。
詳細情報
11g以降では、sql_traceもイベントであり、イベント構文で設定できます。
SQL> oradebug doc event name sql_trace sql_trace: event for sql trace Usage ------- sql_trace wait < false | true >, bind < false | true >, plan_stat < never | first_execution | all_executions | adaptive >, level <ub4>
したがって、次のように使用して、バインド情報を要求するSQL_TRACEを有効にすることができます。
alter session set events 'sql_trace bind=true';
または、情報をバインドして待機します（コンマで区切られていることに注意してください）：
alter session set events 'sql_trace bind=true, wait=true';
フィルタを含めると、それ以降のトレースをSQL_IDのセットに制限できます。例：
alter session set events 'sql_trace [sql: sql_id=g3yc1js3g2689 | sql_id=7ujay4u33g337]bind=true, wait=true';
10046 EVENTレベル:(新しいsql_trace値は[..]に含まれています）
これらはビット値であるため、さまざまな組み合わせを取得するために組み合わせることができます
1 –標準のSQL_TRACE機能を有効にします（デフォルト）
4 –レベル1としてプラストレースバインド値[bind =true]
8 –レベル1PLUSトレースが待機するとき[wait=true]
これは、ラッチ待機などを見つけるのに特に役立ちます。
全表スキャンやインデックススキャンを見つけるためにも使用できます。
11g以降、これらの追加のビットレベルが使用可能になります。
16 –実行ごとにSTATラインダンプを生成します[plan_stat =all_executions]
32 –実行統計をダンプしない[plan_stat =never]
11.2.0.2以降、この追加のビットレベルが使用可能になります。
64 –STATラインの適応ダンプ。 [plan_stat =adaptive]
これはSQLが約1分以上かかった場合にSTAT情報をダンプし、それによって
より高価なSQLとそのようなSQLのさまざまな実行に関する情報を提供します。
例：一般的なイベントレベルは12で、これには標準のSQL_TRACE出力、バインド、待機、および
デフォルトのSTATライントレースが含まれます。
注：
STATダンプは11gで修正され、すべての実行で集約されるのではなく、実行後にダンプされるようになりました。これは、カーソルが閉じられていないためにSTAT情報がダンプされない場合に対処するために行われました。
これで、実行後にSTAT情報をキャプチャすることが保証されます。 STATラインをより細かく制御するには、上記のビットレベルを参照してください。
また読む
v $ active_session_history
Oracleでの計画の説明
sqlTuningAdvisor