一次ORA-00600問題的排查和分析(下）
繼續昨天對於 ORA-00600問題的排查和分析(上)
http://blog.itpub.net/23718752/viewspace-1696076/
我們發現了一大堆的ORA錯誤。我們首先排除了deadlock造成的ora-00600錯誤。從日誌的分析的整體情況來說，雖然很多錯誤在metalink中都有相關的文章說明，但是提供的方案可執行性還是值得商榷的。畢竟一出現問題就是bug,就需要打補丁，就需要升級，這種處理方式客戶也不會接受。在升級和打補丁之外，我們能夠做些什麼，能夠避免這種問題也是解決問題。除此之外，我們所能做的就是進一步分析了，這時候分析除了深入分析日誌中的內容，還需要結合資料庫的整體情況來分析。
首先前2個ora錯誤都是資料庫層面的問題，第3個錯誤可能看起來更嚴重。所以先來看看這個錯誤。
Archived Log entry 82993 added for thread 1 sequence 82927 ID 0xb8c6d509 dest 1:Wed Jun 10 14:38:53 2015
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_ora_15548.trc (incident=2110436):
ORA-04030: out of process memory when trying to allocate 16328 bytes (koh-kghu sessi,pmucalm coll)
Incident details in: /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/incident/incdir_2110436/PRODB_ora_15548_i2110436.trc
在trace中其實還有更多的明細資訊。簡單做了標註。
那麼這個問題防範措施有哪些呢？
有幾種思路來調整。但是最終都是調整隱含引數了。
第一種方案是調整下面兩個隱含引數。
_use_realfree_heap=TRUE
_realfree_heap_pagesize_hint = 262144
根據專案的使用情況，建議的隱含引數調整如下，但是問題的處理不緊急，等問題解決之後可以後期進行跟進。
_kghdsidx_count 1
_optimizer_extended_cursor_sharing none
_optimizer_extended_cursor_sharing_rel none
所以這個ora的錯誤分析就告一段落，可以看出，這個錯誤主要是人為因素導致的，可以完全避免這種大批次的查詢。在備庫就可以達到同樣的目的。
再來看看第一個和第二個錯誤。
第二個錯誤是ora-600錯誤，涉及的sql語句是核心層的sql語句，在其它專案都在使用，而且這個問題從錯誤日誌的情況來看，之前還沒有碰到過，所以儘管是一個bug,但是不是一個經常出現的問題。
ORA-00600: internal error code, arguments: [srsnext_3], [], [], [], [], [], [], [], [], [], [], []
我們來分析第一個問題，如果觀察仔細，會發現和第三個錯誤還是有一些相關性的。都有parallel的相關錯誤。
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_p135_15651.trc (incident=2116204):
ORA-07445: exception encountered: core dump [kxfpqrclb()+71] [SIGSEGV] [ADDR:0x210] [PC:0x193F4DF] [Address not mapped to object] []
ORA-10382: parallel query server interrupt (reset)
所以這個時候單純在core dump的日誌中從目前的情況來看還是很難分析出很多資訊了。既然錯誤資訊和parallel都有一些關聯，我們來驗證一下是不是確實由parallel導致了這些問題。
首先parallel的設定在這個環境是180，即最多能夠啟用180個並行。
再來看看錯誤資訊就會發現。是在並行號為135的程式報出的錯誤。
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_p135_15651.trc (incident=2116204):
在早晨的那個時間段，這個並行使用還是很高的。雖然時間已經過去了，但是還是能夠透過ash發現不少資訊的。
這個時候如果有額外的補充資訊就會事半功倍了。
簡單列出一些關鍵的資訊。可以看出在那個時間段裡，還是出現了很多的並行。我把session sid的資訊給過濾了。
USERNAME OSUSER MACHINE PROGRAM DEGREE SERVER# REQ_DEGREE SQL_ID
--------------- --------------- -------------------- ------------------------------ -
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P099) 8 3 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P100) 8 4 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P101) 8 5 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P102) 8 6 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P103) 8 7 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P104) 8 8 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P105) 8 1 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P106) 8 2 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P107) 8 3 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P108) 8 4 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P109) 8 5 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P110) 8 6 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P111) 8 7 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P112) 8 8 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P113) 8 8 8 g2k7z17gdtpdw
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P115) 8 1 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P116) 8 2 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P117) 8 3 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P118) 8 4 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P119) 8 5 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P120) 8 6 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P153) 5 1 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P121) 8 7 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P123) 8 8 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P127) 4 2 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P128) 4 3 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P129) 4 4 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P130) 2 1 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P163) 5 3 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P131) 2 2 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P132) 4 1 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P133) 2 1 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P167) 5 4 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P134) 4 2 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P135) 2 2 8 a9jjv2z3kptdd
我把相關的sql_id進行了整理，發現竟然sql語句都是類似的。比如下面兩個sql語句。其實差別就在於標黃的部分，但是sql_id完全不同。
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------
SELECT /*+ PARALLEL(8) */ MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_ID, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE
, ACT.ACT_PATH_ID FROM CSM_ACT_RSN ACT, (SELECT MM.ENTITY_ID, ET.ENTITY_TYPE_ID, ET.ENTITY_TYPE
_CODE, MM.MEMO_DATE, MT.MEMO_TYPE_ID FROM MO1_ENTITY_TYPE ET, MO1_MEMO_TYPE MT, MO1_MEMO MM
WHERE MM.ENTITY_TYPE_ID = ET.ENTITY_TYPE_ID AND MM.MEMO_TYPE_ID = MT.MEMO_TYPE_ID
AND MM.MEMO_ID BETWEEN :1 AND :2 AND MM.ENTITY_ID IN (8108188) AND ET.ENTITY_TYP
E_ID IN (2, 4, 6)) MEMO WHERE ACT.MEMO_TYPE=MEMO.MEMO_TYPE_ID AND ((MEMO.ENTITY_TYPE_ID = 2 AND AC
T.ACT_PATH_ID = 117) OR (MEMO.ENTITY_TYPE_ID = 4 AND ACT.ACT_PATH_ID = 126) OR (MEMO.E
NTITY_TYPE_ID = 6 AND ACT.ACT_PATH_ID IN (78, 84, 93))) GROUP BY MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_I
D, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE, ACT.ACT_PATH_ID
6cw70dcdtwu7p
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------
SELECT /*+ PARALLEL(8) */ MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_ID, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE
, ACT.ACT_PATH_ID FROM CSM_ACT_RSN ACT, (SELECT MM.ENTITY_ID, ET.ENTITY_TYPE_ID, ET.ENTITY_TYPE
_CODE, MM.MEMO_DATE, MT.MEMO_TYPE_ID FROM MO1_ENTITY_TYPE ET, MO1_MEMO_TYPE MT, MO1_MEMO MM
WHERE MM.ENTITY_TYPE_ID = ET.ENTITY_TYPE_ID AND MM.MEMO_TYPE_ID = MT.MEMO_TYPE_ID
AND MM.MEMO_ID BETWEEN :1 AND :2 AND MM.ENTITY_ID IN (7341630) AND ET.ENTITY_TYP
E_ID IN (2, 4, 6)) MEMO WHERE ACT.MEMO_TYPE=MEMO.MEMO_TYPE_ID AND ((MEMO.ENTITY_TYPE_ID = 2 AND AC
T.ACT_PATH_ID = 117) OR (MEMO.ENTITY_TYPE_ID = 4 AND ACT.ACT_PATH_ID = 126) OR (MEMO.E
NTITY_TYPE_ID = 6 AND ACT.ACT_PATH_ID IN (78, 84, 93))) GROUP BY MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_I
D, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE, ACT.ACT_PATH_ID
透過這個我們可以分析出，還是存在繫結變數相關的潛在問題，這些類似的查詢在做大量的並行，這個和預期是明顯不同的。所以這個問題傳送給開發同事去檢視進行進一步確認。
可以看出大量的並行都是由某一個客戶端發出的，和預期有很大的不同。
這是一個問題，另外一個問題就是有一些並行是透過開發人員制定的，這個就有些不合規範了。
怎麼證明呢，我抓取了ora-00600發生的時間內的一個ash報告，是一個2分鐘的報告。
在有限的幾個查詢中就看到了ora-00600發生的時候，有兩個查詢在做手工指定的並行，
透過這個問題我們可以看出，問題基本可以斷定在並行的使用上，一個就是某個客戶端在使用大量的並行查詢，導致核心模組的sql在使用並行時出現ora-00600問題，同時有部分開發人員也在客戶端進行一些並行查詢，也是一個側面的因素。
而關於客戶端並行使用不當可以從第一個和第三個ora錯誤得到一些相關的資訊。
http://blog.itpub.net/23718752/viewspace-1696076/
我們發現了一大堆的ORA錯誤。我們首先排除了deadlock造成的ora-00600錯誤。從日誌的分析的整體情況來說，雖然很多錯誤在metalink中都有相關的文章說明，但是提供的方案可執行性還是值得商榷的。畢竟一出現問題就是bug,就需要打補丁，就需要升級，這種處理方式客戶也不會接受。在升級和打補丁之外，我們能夠做些什麼，能夠避免這種問題也是解決問題。除此之外，我們所能做的就是進一步分析了，這時候分析除了深入分析日誌中的內容，還需要結合資料庫的整體情況來分析。
首先前2個ora錯誤都是資料庫層面的問題，第3個錯誤可能看起來更嚴重。所以先來看看這個錯誤。
Archived Log entry 82993 added for thread 1 sequence 82927 ID 0xb8c6d509 dest 1:Wed Jun 10 14:38:53 2015
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_ora_15548.trc (incident=2110436):
ORA-04030: out of process memory when trying to allocate 16328 bytes (koh-kghu sessi,pmucalm coll)
Incident details in: /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/incident/incdir_2110436/PRODB_ora_15548_i2110436.trc
在trace中其實還有更多的明細資訊。簡單做了標註。
less /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/incident/incdir_2110436/PRODB_ora_15548_i2110436.trc
*** 2015-06-10 14:38:53.798
*** SESSION ID:(10891.46647) 2015-06-10 14:38:53.798
*** CLIENT ID:() 2015-06-10 14:38:53.798
*** SERVICE NAME:(SYS$USERS) 2015-06-10 14:38:53.798
*** MODULE NAME:(PL/SQL Developer) 2015-06-10 14:38:53.798
*** ACTION NAME:(SQL Window - Script_Find_Customer_XXXX_As_SOC_V2.sql) 2015-06-10 14:38:53.798
Dump continued from file: /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_ora_15548.trc
ORA-04030: out of process memory when trying to allocate 16328 bytes (koh-kghu sessi,pmucalm coll)
========= Dump for incident 2110436 (ORA 4030) ========
----- Beginning of Customized Incident Dump(s) -----
=======================================
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------
91% 3719 MB, 238851 chunks: "pl/sql vc2 " PL/SQL
koh-kghu sessi ds=0x2ba75b6e1a48 dsprt=0x2ba75b6b40d0
9% 355 MB, 22799 chunks: "pmucalm coll " PL/SQL
koh-kghu sessi ds=0x2ba75b6e1a48 dsprt=0x2ba75b6b40d0
0% 1121 KB, 7 chunks: "free memory "
pga heap ds=0xb7f4bc0 dsprt=(nil)
0% 745 KB, 28 chunks: "permanent memory "
pga heap ds=0xb7f4bc0 dsprt=(nil)
0% 388 KB, 1 chunk : "free memory "
KSFD vec heap ds=0xb800980 dsprt=0xb7f4bc0
0% 125 KB, 2 chunks: "free memory "
top call heap ds=0xb7fa3e0 dsprt=(nil)
0% 63 KB, 1 chunk : "create partial row " SQL
kxs-heap-w ds=0x2ba75b6d4248 dsprt=0x2ba75b6b40d0
0% 58 KB, 36 chunks: "free memory "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
0% 52 KB, 13 chunks: "kxsFrame4kPage "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
0% 50 KB, 5 chunks: "permanent memory "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
=======================================
PRIVATE MEMORY SUMMARY FOR THIS PROCESS
---------------------------------------
******************************************************
PRIVATE HEAP SUMMARY DUMP
4090 MB total:
4088 MB commented, 746 KB permanent
1247 KB free (0 KB in empty extents),
4087 MB, 1 heap: "session heap "
------------------------------------------------------
Summary of subheaps at depth 1
4085 MB total:
4085 MB commented, 69 KB permanent
457 KB free (0 KB in empty extents),
4084 MB, 9 heaps: "koh-kghu sessi " 21 KB free held
------------------------------------------------------
Summary of subheaps at depth 2
4074 MB total:
4074 MB commented, 32 KB permanent
8 KB free (0 KB in empty extents),
3719 MB, 238851 chunks: "pl/sql vc2 "
=========================================
REAL-FREE ALLOCATOR DUMP FOR THIS PROCESS
-----------------------------------------
......
2ba85b544000-2ba85b554000 rwxp 00000000 00:11 198613 /dev/zero
2ba85b554000-2ba85c9d4000 rwxp ffb79000 00:11 198613 /dev/zero
7fffbada1000-7fffbade1000 rwxp 7ffffffbe000 00:00 0 [stack]
7fffbadfd000-7fffbae00000 r-xp 7fffbadfd000 00:00 0 [vdso]
ffffffffff600000-ffffffffffe00000 ---p 00000000 00:00 0 [vsyscall]
******************* End of process map dump ************
其實上面的資訊可以看到，對於程式都有4G的限制，從最後的日誌可以看到，每個程式僅僅有 65536 個 memory map 條目。
這個引數和作業系統層面是有關聯的。
> cat /proc/sys/vm/max_map_count
65536
更重要的是發現是客戶端的一個程式在執行sql指令碼，而且是透過PL/SQL Developer來執行的。
這個時候耐心看看日誌其實還有一些明細資訊。在trace日誌的最後有下面一段內容,用黃色標註出來了。
Begin OCI Call Context Dump
End OCI Call Context Dump
Begin Process state dump.
ttcdrvdmplocation: msg-0 ln-0 reporting 0
hstflg: 0x40202d91
hstcflg: 0x00000000
hstpro: 6
hstccs: (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=172.16.12.119)(PORT=1548))(CONNECT_DATA=(SID=PRODB)(CID=(PROGRAM=C:\Program Files\PLSQL Developer\plsqldev.exe)(HOST=XXXX_CP15-NICHAXXX)(USER=Nichaddsf))))
--- dump of hsttti ---
00B80AE10 00 01 01 0C 0E 09 0B 0F 01 0A 03 03 01 00 00 0A [................]
00B80AE20 00 00 00 00 00 00 00 01 01 01 01 01 01 01 01 01 [................]
00B80AE30 06 06 00 00 00 00 00 07 03 03 00 00 00 00 00 00 [................]
透過日誌就可以看出這個問題是由於客戶端透過plsql dev執行一個指令碼導致程式佔用超過4G的限制，所以丟擲了ORA-04030的錯誤。*** 2015-06-10 14:38:53.798
*** SESSION ID:(10891.46647) 2015-06-10 14:38:53.798
*** CLIENT ID:() 2015-06-10 14:38:53.798
*** SERVICE NAME:(SYS$USERS) 2015-06-10 14:38:53.798
*** MODULE NAME:(PL/SQL Developer) 2015-06-10 14:38:53.798
*** ACTION NAME:(SQL Window - Script_Find_Customer_XXXX_As_SOC_V2.sql) 2015-06-10 14:38:53.798
Dump continued from file: /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_ora_15548.trc
ORA-04030: out of process memory when trying to allocate 16328 bytes (koh-kghu sessi,pmucalm coll)
========= Dump for incident 2110436 (ORA 4030) ========
----- Beginning of Customized Incident Dump(s) -----
=======================================
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------
91% 3719 MB, 238851 chunks: "pl/sql vc2 " PL/SQL
koh-kghu sessi ds=0x2ba75b6e1a48 dsprt=0x2ba75b6b40d0
9% 355 MB, 22799 chunks: "pmucalm coll " PL/SQL
koh-kghu sessi ds=0x2ba75b6e1a48 dsprt=0x2ba75b6b40d0
0% 1121 KB, 7 chunks: "free memory "
pga heap ds=0xb7f4bc0 dsprt=(nil)
0% 745 KB, 28 chunks: "permanent memory "
pga heap ds=0xb7f4bc0 dsprt=(nil)
0% 388 KB, 1 chunk : "free memory "
KSFD vec heap ds=0xb800980 dsprt=0xb7f4bc0
0% 125 KB, 2 chunks: "free memory "
top call heap ds=0xb7fa3e0 dsprt=(nil)
0% 63 KB, 1 chunk : "create partial row " SQL
kxs-heap-w ds=0x2ba75b6d4248 dsprt=0x2ba75b6b40d0
0% 58 KB, 36 chunks: "free memory "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
0% 52 KB, 13 chunks: "kxsFrame4kPage "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
0% 50 KB, 5 chunks: "permanent memory "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
=======================================
PRIVATE MEMORY SUMMARY FOR THIS PROCESS
---------------------------------------
******************************************************
PRIVATE HEAP SUMMARY DUMP
4090 MB total:
4088 MB commented, 746 KB permanent
1247 KB free (0 KB in empty extents),
4087 MB, 1 heap: "session heap "
------------------------------------------------------
Summary of subheaps at depth 1
4085 MB total:
4085 MB commented, 69 KB permanent
457 KB free (0 KB in empty extents),
4084 MB, 9 heaps: "koh-kghu sessi " 21 KB free held
------------------------------------------------------
Summary of subheaps at depth 2
4074 MB total:
4074 MB commented, 32 KB permanent
8 KB free (0 KB in empty extents),
3719 MB, 238851 chunks: "pl/sql vc2 "
=========================================
REAL-FREE ALLOCATOR DUMP FOR THIS PROCESS
-----------------------------------------
......
2ba85b544000-2ba85b554000 rwxp 00000000 00:11 198613 /dev/zero
2ba85b554000-2ba85c9d4000 rwxp ffb79000 00:11 198613 /dev/zero
7fffbada1000-7fffbade1000 rwxp 7ffffffbe000 00:00 0 [stack]
7fffbadfd000-7fffbae00000 r-xp 7fffbadfd000 00:00 0 [vdso]
ffffffffff600000-ffffffffffe00000 ---p 00000000 00:00 0 [vsyscall]
******************* End of process map dump ************
其實上面的資訊可以看到，對於程式都有4G的限制，從最後的日誌可以看到，每個程式僅僅有 65536 個 memory map 條目。
這個引數和作業系統層面是有關聯的。
> cat /proc/sys/vm/max_map_count
65536
更重要的是發現是客戶端的一個程式在執行sql指令碼，而且是透過PL/SQL Developer來執行的。
這個時候耐心看看日誌其實還有一些明細資訊。在trace日誌的最後有下面一段內容,用黃色標註出來了。
Begin OCI Call Context Dump
End OCI Call Context Dump
Begin Process state dump.
ttcdrvdmplocation: msg-0 ln-0 reporting 0
hstflg: 0x40202d91
hstcflg: 0x00000000
hstpro: 6
hstccs: (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=172.16.12.119)(PORT=1548))(CONNECT_DATA=(SID=PRODB)(CID=(PROGRAM=C:\Program Files\PLSQL Developer\plsqldev.exe)(HOST=XXXX_CP15-NICHAXXX)(USER=Nichaddsf))))
--- dump of hsttti ---
00B80AE10 00 01 01 0C 0E 09 0B 0F 01 0A 03 03 01 00 00 0A [................]
00B80AE20 00 00 00 00 00 00 00 01 01 01 01 01 01 01 01 01 [................]
00B80AE30 06 06 00 00 00 00 00 07 03 03 00 00 00 00 00 00 [................]
那麼這個問題防範措施有哪些呢？
有幾種思路來調整。但是最終都是調整隱含引數了。
第一種方案是調整下面兩個隱含引數。
_use_realfree_heap=TRUE
_realfree_heap_pagesize_hint = 262144
根據專案的使用情況，建議的隱含引數調整如下，但是問題的處理不緊急，等問題解決之後可以後期進行跟進。
_kghdsidx_count 1
_optimizer_extended_cursor_sharing none
_optimizer_extended_cursor_sharing_rel none
所以這個ora的錯誤分析就告一段落，可以看出，這個錯誤主要是人為因素導致的，可以完全避免這種大批次的查詢。在備庫就可以達到同樣的目的。
再來看看第一個和第二個錯誤。
第二個錯誤是ora-600錯誤，涉及的sql語句是核心層的sql語句，在其它專案都在使用，而且這個問題從錯誤日誌的情況來看，之前還沒有碰到過，所以儘管是一個bug,但是不是一個經常出現的問題。
ORA-00600: internal error code, arguments: [srsnext_3], [], [], [], [], [], [], [], [], [], [], []
我們來分析第一個問題，如果觀察仔細，會發現和第三個錯誤還是有一些相關性的。都有parallel的相關錯誤。
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_p135_15651.trc (incident=2116204):
ORA-07445: exception encountered: core dump [kxfpqrclb()+71] [SIGSEGV] [ADDR:0x210] [PC:0x193F4DF] [Address not mapped to object] []
ORA-10382: parallel query server interrupt (reset)
所以這個時候單純在core dump的日誌中從目前的情況來看還是很難分析出很多資訊了。既然錯誤資訊和parallel都有一些關聯，我們來驗證一下是不是確實由parallel導致了這些問題。
首先parallel的設定在這個環境是180，即最多能夠啟用180個並行。
再來看看錯誤資訊就會發現。是在並行號為135的程式報出的錯誤。
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_p135_15651.trc (incident=2116204):
在早晨的那個時間段，這個並行使用還是很高的。雖然時間已經過去了，但是還是能夠透過ash發現不少資訊的。
這個時候如果有額外的補充資訊就會事半功倍了。
簡單列出一些關鍵的資訊。可以看出在那個時間段裡，還是出現了很多的並行。我把session sid的資訊給過濾了。
USERNAME OSUSER MACHINE PROGRAM DEGREE SERVER# REQ_DEGREE SQL_ID
--------------- --------------- -------------------- ------------------------------ -
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P099) 8 3 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P100) 8 4 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P101) 8 5 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P102) 8 6 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P103) 8 7 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P104) 8 8 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P105) 8 1 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P106) 8 2 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P107) 8 3 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P108) 8 4 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P109) 8 5 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P110) 8 6 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P111) 8 7 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P112) 8 8 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P113) 8 8 8 g2k7z17gdtpdw
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P115) 8 1 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P116) 8 2 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P117) 8 3 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P118) 8 4 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P119) 8 5 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P120) 8 6 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P153) 5 1 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P121) 8 7 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P123) 8 8 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P127) 4 2 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P128) 4 3 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P129) 4 4 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P130) 2 1 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P163) 5 3 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P131) 2 2 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P132) 4 1 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P133) 2 1 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P167) 5 4 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P134) 4 2 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P135) 2 2 8 a9jjv2z3kptdd
可以在那個時間段裡，看到還是有很多的並行執行。而且奇怪的是很多並行都來自於pwrk01，這個和預期有很大的差距。
我把相關的sql_id進行了整理，發現竟然sql語句都是類似的。比如下面兩個sql語句。其實差別就在於標黃的部分，但是sql_id完全不同。
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------
SELECT /*+ PARALLEL(8) */ MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_ID, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE
, ACT.ACT_PATH_ID FROM CSM_ACT_RSN ACT, (SELECT MM.ENTITY_ID, ET.ENTITY_TYPE_ID, ET.ENTITY_TYPE
_CODE, MM.MEMO_DATE, MT.MEMO_TYPE_ID FROM MO1_ENTITY_TYPE ET, MO1_MEMO_TYPE MT, MO1_MEMO MM
WHERE MM.ENTITY_TYPE_ID = ET.ENTITY_TYPE_ID AND MM.MEMO_TYPE_ID = MT.MEMO_TYPE_ID
AND MM.MEMO_ID BETWEEN :1 AND :2 AND MM.ENTITY_ID IN (8108188) AND ET.ENTITY_TYP
E_ID IN (2, 4, 6)) MEMO WHERE ACT.MEMO_TYPE=MEMO.MEMO_TYPE_ID AND ((MEMO.ENTITY_TYPE_ID = 2 AND AC
T.ACT_PATH_ID = 117) OR (MEMO.ENTITY_TYPE_ID = 4 AND ACT.ACT_PATH_ID = 126) OR (MEMO.E
NTITY_TYPE_ID = 6 AND ACT.ACT_PATH_ID IN (78, 84, 93))) GROUP BY MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_I
D, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE, ACT.ACT_PATH_ID
6cw70dcdtwu7p
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------
SELECT /*+ PARALLEL(8) */ MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_ID, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE
, ACT.ACT_PATH_ID FROM CSM_ACT_RSN ACT, (SELECT MM.ENTITY_ID, ET.ENTITY_TYPE_ID, ET.ENTITY_TYPE
_CODE, MM.MEMO_DATE, MT.MEMO_TYPE_ID FROM MO1_ENTITY_TYPE ET, MO1_MEMO_TYPE MT, MO1_MEMO MM
WHERE MM.ENTITY_TYPE_ID = ET.ENTITY_TYPE_ID AND MM.MEMO_TYPE_ID = MT.MEMO_TYPE_ID
AND MM.MEMO_ID BETWEEN :1 AND :2 AND MM.ENTITY_ID IN (7341630) AND ET.ENTITY_TYP
E_ID IN (2, 4, 6)) MEMO WHERE ACT.MEMO_TYPE=MEMO.MEMO_TYPE_ID AND ((MEMO.ENTITY_TYPE_ID = 2 AND AC
T.ACT_PATH_ID = 117) OR (MEMO.ENTITY_TYPE_ID = 4 AND ACT.ACT_PATH_ID = 126) OR (MEMO.E
NTITY_TYPE_ID = 6 AND ACT.ACT_PATH_ID IN (78, 84, 93))) GROUP BY MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_I
D, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE, ACT.ACT_PATH_ID
透過這個我們可以分析出，還是存在繫結變數相關的潛在問題，這些類似的查詢在做大量的並行，這個和預期是明顯不同的。所以這個問題傳送給開發同事去檢視進行進一步確認。
可以看出大量的並行都是由某一個客戶端發出的，和預期有很大的不同。
這是一個問題，另外一個問題就是有一些並行是透過開發人員制定的，這個就有些不合規範了。
怎麼證明呢，我抓取了ora-00600發生的時間內的一個ash報告，是一個2分鐘的報告。
在有限的幾個查詢中就看到了ora-00600發生的時候，有兩個查詢在做手工指定的並行，
| 49jupn8xsj51y | 2518757642 | 1 | 5.65 | TABLE ACCESS - FULL | 5.41 | direct path read | 4.18 | select /*+ PARALLEL(b 8)*/ --c... |
| 7f2wq2wxvnxc5 | 1689491771 | 1 | 5.65 | TABLE ACCESS - FULL | 5.59 | direct path read | 3.88 | select /*+ PARALLEL(b 8)*/ b.s... |
透過這個問題我們可以看出，問題基本可以斷定在並行的使用上，一個就是某個客戶端在使用大量的並行查詢，導致核心模組的sql在使用並行時出現ora-00600問題，同時有部分開發人員也在客戶端進行一些並行查詢，也是一個側面的因素。
而關於客戶端並行使用不當可以從第一個和第三個ora錯誤得到一些相關的資訊。
來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/23718752/viewspace-1697132/，如需轉載，請註明出處，否則將追究法律責任。
相關文章
- 一次ORA-00600問題的排查和分析(上）
- 關於SQLRecoverableException問題的排查和分析SQLException
- 記一次oom問題排查OOM
- 記錄一次問題排查
- 一次容器MySQL的效能問題排查MySql
- 記一次排查CPU高的問題
- 記一次 Laravel MethodNotAllowedHttpException 問題排查LaravelHTTPException
- 一次快取效能問題排查快取
- 記一次線上FGC問題排查GC
- 記一次OOM問題排查過程OOM
- 一次線上問題的排查解決過程
- 一次線上CPU高的問題排查實踐
- 一次線上問題排查所引發的思考
- 【問題排查篇】一次業務問題對 ES 的 cardinality 原理探究
- 記一次線上websocket返回400問題排查Web
- 記一次 MySQL 資料庫問題排查MySql資料庫
- 一次ygc越來越慢的問題排查過程GC
- 記一次線上崩潰問題的排查過程
- 記一次棧溢位異常問題的排查
- 從一次問題排查聊聊問什麼要懂原理
- 記一次記憶體溢位問題的排查、分析過程及解決思路記憶體溢位
- 記一次 Kafka 重啟失敗問題排查Kafka
- Arthas常用功能及一次線上問題排查
- 一次IOS通知推送問題排查全過程iOS
- 記一次線上報錯日誌問題排查
- 一次資料庫響應緩慢的問題排查資料庫
- 線上問題排查：記一次 Redis Cluster Pipeline 導致的死鎖問題Redis
- 記一次協助排查許可權問題的經歷
- 測不準原理？記一次Guava佇列問題的排查Guava佇列
- 一次資料庫無法登陸的問題及排查資料庫
- 一次資料庫無法登陸的"問題"及排查資料庫
- 一次郵件傳送協議SMTP問題排查協議
- job處理緩慢的效能問題排查與分析
- Java線上問題排查神器Arthas實戰分析Java
- 記一次SparkStreaming不產生新的batchJob的問題排查SparkBAT
- Dev 日誌 | 一次 Segmentation Fault 和 GCC Illegal Instruction 編譯問題排查devSegmentationGCStruct編譯
- java問題排查Java
- JVM 問題排查JVM