Trouble Shooting Jp

トラブルに対するトレースファイルの取得

トラブルを解決するためトレースファイルがよく必要とされる。
取得方法は

該当セッション自身、一般のエラー
ALTER SESSION SET SQL_TRACE=ON;
 
-- 問題のSQL文を実行する
...
 
ALTER SESSION SET SQL_TRACE=OFF;
該当セッション自身、高度のエラー(ラッチ、待機など情報が必要)
ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';
 
-- 問題のSQL文を実行する
...
 
ALTER SESSION SET EVENTS '10046 trace name context off';

レベルの詳細は下記のとおり。

レベル 内容
LEVEL 1 SQL_TRACE機能と同等
LEVEL 4 LEVEL 1の情報に追加して、バインド変数情報が出力される
LEVEL 8 LEVEL 1の情報に追加して、待機イベント情報が出力される
LEVEL 12 LEVEL 1の情報に追加して、バインド変数情報、待機イベント情報が出力される
アプリケーションに組み込む場合

場合によって、直接問題文の発行する前に手で発行できないことがあるため、
アプリケーション、プロシージャに組み込むことができる。

execute 'ALTER SESSION SET EVENTS ''10046 trace name context forever, level 12'' ';
 
-- 問題のSQL文を実行する
...
 
execute 'ALTER SESSION SET EVENTS ''10046 trace name context off'' ';
他のセッションのトレースファイルの取得
--セッションのSIDSERIAL#の取得
SQL> SELECT sid,serial#,username,program,machine,status,last_call_et FROM v$session
  2  WHERE username='SCOTT';
 
  SID    SERIAL# USERNAME     PROGRAM                           MACHINE      STATUS   LAST_CALL_ET
----- ---------- ------------ --------------------------------- ------------ -------- ------------
   10          2 SCOTT        sqlplus@linuxtest (TNS V1-V3)     linux006     INACTIVE            2
 
--セッションのトレース
EXECUTE DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(10,12,TRUE);
 
-- 問題のSQL文を実行する
...
 
EXECUTE DBMS_SYSTEM.SET_SQL_TRACE_IN_SESSION(10,12,FALSE);
 
--セッションに対してレベルを指定してトレース
EXECUTE DBMS_SYSTEM.SET_EV(10,2,10046,12,'');
 
-- 問題のSQL文を実行する
...
 
EXECUTE DBMS_SYSTEM.SET_EV(10,2,10046,0,'');
トレースファイルの特定
トレースファイルの特定

http://www.builder.com.cn/2007/0910/497699.shtml
http://www.eygle.com/archives/2007/09/11g_tracefile_name.html

-- under 11g 
-- sql 1
SELECT    a.VALUE || b.symbol || c.instance_name || '_ora_' || d.spid || '.trc' trace_file
  FROM (SELECT VALUE FROM v$parameter WHERE NAME = 'user_dump_dest') a,
       (SELECT SUBSTR (VALUE, -6, 1) symbol FROM v$parameter
         WHERE NAME = 'user_dump_dest') b,
       (SELECT instance_name FROM v$instance) c,
       (SELECT spid FROM v$session s, v$process p, v$mystat m
         WHERE s.paddr = p.addr AND s.SID = m.SID AND m.statistic# = 0) d
;
 
-- sql 2
select
  u_dump.value   || '/'     ||
  db_name.value  || '_ora_' ||
  v$process.spid ||
  nvl2(v$process.traceid,  '_' || v$process.traceid, null )
  || '.trc'  "Trace File"
from
             v$parameter u_dump
  cross join v$parameter db_name
  cross join v$process
        join v$session
          on v$process.addr = v$session.paddr
where
 u_dump.name   = 'user_dump_dest' and
 db_name.name  = 'db_name'        and
 v$session.audsid=sys_context('userenv','sessionid');
 
-- after 11g
-- trace file name of current session
SELECT VALUE FROM V$DIAG_INFO WHERE NAME = 'Default Trace File';
-- trace file name for all processes
select program,TRACEFILE from v$process;

あるいは初期化パラメータのuser_dump_destの指定したフォルダを時間順でみれば、最新のほうに並んでいるはず。

SQL> show parameter user_dump_dest
 
NAME                                 TYPE
------------------------------------ ---------------------------------
VALUE
------------------------------
user_dump_dest                       string
/u01/oracle/app/oracle/admin/sid/udump
 
host
 
[oracle@linuxtest ~]$ cd /u01/oracle/app/oracle/admin/sid/udump
[oracle@ linuxtest udump]$ ls -ltr
 
...
 
-rw-r-----  1 oracle oinstall      2541  8月 21 16:34 dbsid_ora_10101.trc
-rw-r-----  1 oracle oinstall       943  8月 21 16:43 dbsid_ora_14837.trc
-rw-r-----  1 oracle oinstall      1361  8月 21 16:43 dbsid_ora_10773.trc
生トレースファイルの確認

References:
http://www.itpub.net/forum.php?mod=viewthread&tid=1137992
1.Activating/deactivating trace http://www.gplivna.eu/papers/otrace.htm
2.Interpreting Raw SQL_TRACE and DBMS_SUPPORT.START_TRACE output, Metalink Note 39817.1
3.Trace Analyzer TRCANLZR - Interpreting Raw SQL Traces with Binds and/or Waits generated by EVENT 10046 Metalink Note 224270.1

See Also:
Abbreviation In Oracle Trace File

Here is a sample snippet from a trace file.

PARSING IN CURSOR #5 len=222 dep=1 uid=0 oct=3 lid=0 tim=1230889092568518 hv=3598296092 ad='402c848c' sqlid='1a8n1zgb7m90w'
select user#,password,datats#,tempts#,type#,defrole,resource$, ptime,exptime, ltime, astatus, lcount, decode(defschclass,NULL,'DEFAULT_CONSUMER_GROUP',defschclass),spare1,spare4,ext_username,spare2 from user$ where name=:1
END OF STMT
PARSE #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1457651150,tim=1230889092568518
EXEC #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=1457651150,tim=1230889092568518
FETCH #5:c=0,e=0,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=1457651150,tim=1230889092568518
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=22 op='TABLE ACCESS BY INDEX ROWID USER$ (cr=2 pr=0 pw=0 time=0 us)'
STAT #5 id=2 cnt=1 pid=1 pos=1 obj=46 op='INDEX UNIQUE SCAN I_USER1 (cr=1 pr=0 pw=0 time=0 us)'
CLOSE #5:c=0,e=0,dep=1,type=3,tim=1230889092568518

Parsing in cursor:

len =the length of the cursor.
dep =recursive depth of cursor(0-parent,>0-child)
uid =user id
oct =oracle command type no OCI
lid =user id owning the statement e.g. package(libary user id)
tim =the time the parse began
hv =hash valus
ad =sql address of cursor
sqlid=sql id of cursor
END OF STMT=indicate the end of sql STateMenT


c =cpu time
e =elapsed time
p =number of database blocks read (physical)
cr =number of consistent mode blocks read(logical)
cu =number of current mode blocks read(logical)
mis=number of library cache misses
r =number of rows returned
dep=recursive depth of cursor
og =optimizer goal (1=all_rows, 2=first_rows, 3=rule and 4=choose)
plh=plan hash value
tim=


cr =BG(Backgroud) Consistent Read mode
pr =OS Buffer Gets
pw =OS Write Calls

WAIT #5: nam='rdbms ipc reply' ela= 873 from_process=9 timeout=2147483647 p3=0 obj#=64143 tim=1230889212565389
WAIT #5: nam='rdbms ipc reply' ela= 820 from_process=5 timeout=2147483647 p3=0 obj#=64143 tim=1230889212566547
XCTEND rlbk=0, rd_only=1, tim=1230889212602618


nam =event name
ela =elapsed time

next three values after ela are indicate the P1, P2 and P3 variables for each specific event.

XCTEND =Transaction Commit END

rlbk True(1) if and only if the transaction was rolled back.
rd_only True(1) if and only if the transaction changed no data in the database

Hangup when shutdown database

SQL> shutdown immediate;
ORA-24324: service handle not initialized
ORA-24323: value not allowed
ORA-01089: immediate shutdown in progress - no operations are permitted
 
[oracle@fy bdump]$ ps -ef | grep oracle
...
oracle   16885     1  0 Apr06 ?        00:00:36 ora_pmon_prod
oracle   16887     1  0 Apr06 ?        00:00:03 ora_psp0_prod
oracle   16889     1  0 Apr06 ?        00:00:03 ora_mman_prod
oracle   16891     1  0 Apr06 ?        00:00:06 ora_dbw0_prod
oracle   16893     1  0 Apr06 ?        00:00:05 ora_lgwr_prod
oracle   16895     1  0 Apr06 ?        00:00:29 ora_ckpt_prod
oracle   16897     1  0 Apr06 ?        00:00:05 ora_smon_prod
oracle   16899     1  0 Apr06 ?        00:00:00 ora_reco_prod
oracle   17033     1  0 Apr06 ?        00:00:00 ora_arc0_prod
oracle   17035     1  0 Apr06 ?        00:00:01 ora_arc1_prod
...
 
[oracle@fy bdump]$ kill -9 16889
 
[oracle@fy bdump]$ ipcs -m
 
------ Shared Memory Segment --------
Key     shmid      owner  priv     bytes  nattch     status
0x0001ffb8 0          root      666        76         4
0x00025990 32769      root      666        8308       4
0x00027cb9 65538      root      666        132256     1
0x00027cba 98307      root      666        132256     1
0x00027cbb 131076     root      666        132256     1
0x00000000 1376261    oracle    600        196608     2          Object
0x00030317 196614     root      777        512000     4
0x00000000 622600     oracle    600        196608     2          Object
0x00000000 655369     oracle    600        196608     2          Object
0x00000000 688138     oracle    600        196608     2          Object
0x00000000 720907     oracle    600        196608     2          Object
0x00000000 753676     oracle    600        196608     2          Object
0x00000000 1540110    oracle    600        196608     2          Object
0x00000000 1114127    oracle    600        196608     2          Object
 
[oracle@fy bdump]$ ipcrm
[oracle@fy bdump]$ ipcrm --help
usage: ipcrm [ [-q msqid] [-m shmid] [-s semid]
          [-Q msgkey] [-M shmkey] [-S semkey] ... ]
[oracle@fy bdump]$ ipcrm -m 1376261
[oracle@fy bdump]$ ipcrm -m 622600
[oracle@fy bdump]$ ipcrm -m 655369
[oracle@fy bdump]$ ipcrm -m 688138
[oracle@fy bdump]$ ipcrm -m 720907
[oracle@fy bdump]$ ipcrm -m 753676
[oracle@fy bdump]$ ipcrm -m 1540110
[oracle@fy bdump]$ ipcrm -m 1114127
[oracle@fy bdump]$ ipcs -m
 
------ Shared Memory Segment --------
Key     shmid      owner  priv     bytes  nattch     status
0x0001ffb8 0          root      666        76         4
0x00025990 32769      root      666        8308       4
0x00027cb9 65538      root      666        132256     1
0x00027cba 98307      root      666        132256     1
0x00027cbb 131076     root      666        132256     1
0x00000000 1376261    oracle    600        196608     2          Object
0x00030317 196614     root      777        512000     4
0x00000000 622600     oracle    600        196608     2          Object
0x00000000 655369     oracle    600        196608     2          Object
0x00000000 688138     oracle    600        196608     2          Object
0x00000000 720907     oracle    600        196608     2          Object
0x00000000 753676     oracle    600        196608     2          Object
0x00000000 1540110    oracle    600        196608     2          Object
0x00000000 1114127    oracle    600        196608     2          Object
 
[oracle@fy bdump]$ ipcrm -m 1376261
[oracle@fy bdump]$ ipcrm -m 622600
[oracle@fy bdump]$ ipcs -m
 
------ Shared Memory Segment --------
Key     shmid      owner  priv     bytes  nattch     status
0x0001ffb8 0          root      666        76         4
0x00025990 32769      root      666        8308       4
0x00027cb9 65538      root      666        132256     1
0x00027cba 98307      root      666        132256     1
0x00027cbb 131076     root      666        132256     1
0x00000000 1376261    oracle    600        196608     2          Object
0x00030317 196614     root      777        512000     4
0x00000000 622600     oracle    600        196608     2          Object
0x00000000 655369     oracle    600        196608     2          Object
0x00000000 688138     oracle    600        196608     2          Object
0x00000000 720907     oracle    600        196608     2          Object
0x00000000 753676     oracle    600        196608     2          Object
0x00000000 1540110    oracle    600        196608     2          Object
0x00000000 1114127    oracle    600        196608     2          Object