12c 程式跟蹤檔案異常

wei-xh發表於2015-09-09
12C下程式產生不了跟蹤檔案的異常，記錄一下，大家可以看看。

12.1.0.2下跟蹤程式產生不了跟蹤檔案，這個不是絕對發生，目前測試了幾十次，只有一次產生了跟蹤檔案，這個規律還沒去仔細找，MOS上也沒發現相關BUG。

11GR2的情況：
建立一個連線，獲取到SPID
select sid from v$mystat where rownum<2;

       SID
----------
       156

sys@QDATA>@spid
Enter value for 1: 156

'KILL-9'||SPID
----------------------------------------------------------------
kill -9 24612

跟蹤這個程式：

strace -p 24612

getrusage(RUSAGE_SELF, {ru_utime={0, 248962}, ru_stime={0, 225965}, ...}) = 0
times({tms_utime=24, tms_stime=22, tms_cutime=0, tms_cstime=0}) = 438088152
getrusage(RUSAGE_SELF, {ru_utime={0, 248962}, ru_stime={0, 225965}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 248962}, ru_stime={0, 225965}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 248962}, ru_stime={0, 225965}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 249962}, ru_stime={0, 225965}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 249962}, ru_stime={0, 225965}, ...}) = 0
getrusage(RUSAGE_SELF, {ru_utime={0, 249962}, ru_stime={0, 225965}, ...}) = 0
times({tms_utime=24, tms_stime=22, tms_cutime=0, tms_cstime=0}) = 438088152
由於還沒開始執行跟蹤，所以沒什麼有意義的輸出。

開啟10053跟蹤，並且執行一些SQL，檢視程式strace的輸出

lseek(15, 0, SEEK_CUR)                  = 291837
write(15, "\n*** 2015-09-09 10:03:19.130\n", 29) = 29
write(16, "3?q5x63~0T\n", 11)           = 11
lseek(15, 0, SEEK_CUR)                  = 291866
write(15, "Registered qb: SEL$1 0xd2066938 "..., 40) = 40
write(16, "2?p08kdMam1~0e\n", 15)       = 15
write(15, "\n", 1)                      = 1
lseek(15, 0, SEEK_CUR)                  = 291907
write(15, "---------------------\nQUERY BLOC"..., 66) = 66
write(16, "1Is6c4$qksqbDumpSig*SQL_Costing*"..., 62) = 62
write(15, "  signature (): qb_name=SEL$1 nb"..., 44) = 44
write(15, "\n", 1)                      = 1
write(15, "    fro(0): flg=5 objn=3369 hint"..., 50) = 50
write(15, "\n", 1)                      = 1
lseek(15, 0, SEEK_CUR)                  = 292069
write(15, "\n", 1)                      = 1
write(16, "HI00W1$04g1W11\n", 15)       = 15
write(15, "Registered qb: SEL$2 0xd2062680 "..., 40) = 40
write(15, "\n", 1)                      = 1
lseek(15, 0, SEEK_CUR)                  = 292111
write(15, "---------------------\nQUERY BLOC"..., 66) = 66

上面的輸出顯示程式一直在向15,16號檔案裡寫入內容

繼續檢視程式開啟了哪些檔案
cd  /proc/24612/fd
#ls -l
total 0
lr-x------ 1 root root 64 Sep  9 10:05 0 -> /dev/null
l-wx------ 1 root root 64 Sep  9 10:05 1 -> /dev/null
lr-x------ 1 root root 64 Sep  9 10:05 10 -> /opt/oracle/products/11.2.0/rdbms/mesg/oraus.msb
lrwx------ 1 root root 64 Sep  9 10:05 11 -> socket:[73142061]
l-wx------ 1 root root 64 Sep  9 10:05 12 -> pipe:[73142010]
lrwx------ 1 root root 64 Sep  9 10:05 13 -> socket:[73142062]
lrwx------ 1 root root 64 Sep  9 10:05 14 -> /opt/oracle/admin/qdata/adump/qdata1_ora_24612_20150909100544275796143795.aud
l-wx------ 1 root root 64 Sep  9 10:06 15 -> /opt/oracle/diag/rdbms/qdata/qdata1/trace/qdata1_ora_24612.trc
l-wx------ 1 root root 64 Sep  9 10:06 16 -> /opt/oracle/diag/rdbms/qdata/qdata1/trace/qdata1_ora_24612.trm
l-wx------ 1 root root 64 Sep  9 10:05 2 -> /dev/null
lr-x------ 1 root root 64 Sep  9 10:05 3 -> /dev/null
lrwx------ 1 root root 64 Sep  9 10:05 4 -> socket:[73142058]

上面的輸出是軟連結，15,16號就是程式開啟、寫入的trace檔案


12C下同樣的跟蹤過程，產生不了trace檔案

sys@QC>conn test/test @10.10.20.31/pdb1
Connected.
test@PDB1>select sid from v$mystat where rownum<2;

       SID
----------
       567

test@PDB1>@spid
Enter value for 1: 567

'KILL-9'||SPID
----------------------------------------------------------------
kill -9 11315

test@PDB1>alter session set events '10053 trace name context forever,level 1';

Session altered.

test@PDB1>select count(*)  from dba_Objects;

  COUNT(*)
----------
     91785

test@PDB1>alter session set events '10053 trace name context off';

Session altered.

上面操作過程中一直用strace觀察程式的輸出：

#strace -p 11315
Process 11315 attached - interrupt to quit
read(20, "\0\0\1V\6\0\0\0\0\0\21i%\376\377\377\377\377\377\377\377\2\0\0\0\0\0\0\0\3\0\0"..., 8208) = 342
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 13997}, ...}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 13997}, ...}) = 0
times(NULL)                             = 443485068
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 13997}, ...}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
times(NULL)                             = 443485068
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
times(NULL)                             = 443485068
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
times(NULL)                             = 443485068
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
times(NULL)                             = 443485068
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
times(NULL)                             = 443485068
times(NULL)                             = 443485068
times(NULL)                             = 443485068
times(NULL)                             = 443485068
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 54991}, ru_stime={0, 14997}, ...}) = 0
mmap(0x7f3d3c7e1000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c7e1000
mmap(0x7f3d3c801000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c801000
mmap(NULL, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0x1e8000) = 0x7f3d3c621000
mmap(0x7f3d3c621000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c621000
mmap(0x7f3d3c641000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c641000
mmap(0x7f3d3c661000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c661000
mmap(0x7f3d3c681000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c681000
mmap(0x7f3d3c6a1000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c6a1000
mmap(0x7f3d3c6c1000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c6c1000
mmap(0x7f3d3c6e1000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c6e1000
mmap(0x7f3d3c701000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c701000
mmap(NULL, 2097152, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0x2e8000) = 0x7f3d3c421000
mmap(0x7f3d3c421000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c421000
mmap(0x7f3d3c441000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c441000
mmap(0x7f3d3c461000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c461000
mmap(0x7f3d3c481000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c481000
mmap(0x7f3d3c4a1000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c4a1000
mmap(0x7f3d3c4c1000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c4c1000
mmap(0x7f3d3c4e1000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c4e1000
mmap(0x7f3d3c501000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c501000
mmap(0x7f3d3c521000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c521000
mmap(0x7f3d3c541000, 131072, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c541000
mmap(0x7f3d3c561000, 65536, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x7f3d3c561000
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 118981}, ru_stime={0, 16997}, ...}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 219966}, ru_stime={0, 16997}, ...}) = 0
getrusage(0x1 /* RUSAGE_??? */, {ru_utime={0, 222966}, ru_stime={0, 16997}, ...}) = 0

沒有產生讀寫檔案的輸出

cd /proc/11315/fd
#ls -l
total 0
lr-x------ 1 root root 64 Sep  9 10:21 0 -> /dev/null
l-wx------ 1 root root 64 Sep  9 10:21 1 -> /dev/null
lrwx------ 1 root root 64 Sep  9 10:21 10 -> socket:[97889794]
lrwx------ 1 root root 64 Sep  9 10:21 11 -> [eventpoll]
l-wx------ 1 root root 64 Sep  9 10:21 2 -> /dev/null
lrwx------ 1 root root 64 Sep  9 10:21 20 -> socket:[97889769]
lr-x------ 1 root root 64 Sep  9 10:21 3 -> /dev/null
lrwx------ 1 root root 64 Sep  9 10:21 4 -> socket:[97889790]
lr-x------ 1 root root 64 Sep  9 10:21 5 -> /proc/11315/fd
lrwx------ 1 root root 64 Sep  9 10:21 6 -> socket:[97889791]
lrwx------ 1 root root 64 Sep  9 10:21 7 -> socket:[97889792]
lr-x------ 1 root root 64 Sep  9 10:21 8 -> /opt/oracle/products/12.1.0/rdbms/mesg/oraus.msb
lrwx------ 1 root root 64 Sep  9 10:21 9 -> socket:[97889793]

也沒有任何有關trace檔案的軟連結，11G以後透過v$process裡的TRACEFILE 都可以看到程式的跟蹤檔案目錄，但是12C裡，這個查詢雖然有結果，但是真實的檔案其實並不存在。

select TRACEFILE from v$process where spid=31740;

/opt/oracle/diag/rdbms/qc/qc_1/trace/qc_1_ora_31740.trc

>more /opt/oracle/diag/rdbms/qc/qc_1/trace/qc_1_ora_31740.trc                                                                                   
/opt/oracle/diag/rdbms/qc/qc_1/trace/qc_1_ora_31740.trc: No such file or directory

沃趣科技高階資料庫專家、專案經理
TEL:18652489962
公司網站：
杭州市濱江區長河街道濱安路1190號3幢智匯領地科技園A區A樓10層1004室（310053）

來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/22034023/viewspace-1795251/，如需轉載，請註明出處，否則將追究法律責任。

相關文章