在幾周前，某個測試環境在嘗試impdp匯入dump的時候報了錯誤，有個DBA立馬做了kill session的操作，但是持續了5個小時，session狀態還是KILLED,於是他們就在等待session被pmon回收。結果又等了幾個小時，還是KILLED狀態。
最後兩撥DBA在交接的時候把這個問題就說明了一下，另外一個DBA繼續嘗試impdp就報了下面的錯誤。

Connected to: Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

ORA-31626: job does not exist

ORA-31637: cannot create job XXXXXX for user xxxxxx

ORA-06512: at "SYS.DBMS_SYS_ERROR", line 95

ORA-06512: at "SYS.KUPV$FT_INT", line 798

ORA-31635: unable to establish job resource synchronization
看起來還是很微妙的。
等到我受到郵件的時候，客戶已經在抱怨了，我連入了環境，想看個究竟。那個session還是KILLED狀態。
SQL> select sid,serial#,status,machine,username from v$session where status='KILLED';
SID SERIAL# STATUS MACHINE USERNAME
---------- ---------- -------- ---------------------------------------------------------------- ------------------------------
4182 18078 KILLED gpnuatndb01 XXXXX07

因為已經做了kill操作，對應的程式已經不好定位了。所以作為一個小教訓，自己會在kill session的時候嘗試也找到對應的程式號。
從日誌來看，其實沒有相關的session和出問題的這個使用者有關。
SELECT s.username,
s.sid,
s.serial#,
t.used_ublk,
t.used_urec,
rs.segment_name,
r.rssize,
r.status
FROM v$transaction t,
v$session s,
v$rollstat r,
dba_rollback_segs rs
WHERE s.saddr = t.ses_addr
AND t.xidusn = r.usn
AND rs.segment_id = t.xidusn
ORDER BY t.used_ublk DESC;

USERNAME SID SERIAL# USED_UBLK USED_UREC SEGMENT_NAME RSSIZE STATUS
------------------------------ ---------- ---------- ---------- ---------- ------------------------------ ---------- ---------------
11485 16129 16 266 _SYSSMU38_1987388439$ 2220032 ONLINE
ABPDB10 7912 46179 2 14 _SYSSMU83_1638092214$ 2220032 ONLINE
ABPAPP6 10393 35829 2 14 _SYSSMU68_660871585$ 2220032 ONLINE
ABPAPP22 15633 21311 1 14 _SYSSMU16_3995703066$ 2220032 ONLINE
ABPAPP2 11388 34725 1 2 _SYSSMU22_455640068$ 2220032 ONLINE
ABPAPP22 7838 44651 1 2 _SYSSMU31_2604536652$ 2220032 ONLINE
ABPAPP6 9473 16735 1 2 _SYSSMU33_1095900139$ 2220032 ONLINE
CHIDB7 9953 59583 1 14 _SYSSMU35_3472989533$ 67231744 ONLINE
ABPAPP8 12508 55865 1 2 _SYSSMU36_1444610389$ 2220032 ONLINE
ABPAPP22 7277 46993 1 2 _SYSSMU37_1673962577$ 2220032 ONLINE
ABPAPP22 7878 40061 1 2 _SYSSMU41_4063564024$ 2220032 ONLINE
ABPAPP2 7302 58443 1 2 _SYSSMU40_1843747856$ 2220032 ONLINE
ABPAPP2 12519 28683 1 2 _SYSSMU45_779001323$ 2220032 ONLINE
ABPAPP2 8380 65241 1 14 _SYSSMU47_1833818776$ 2220032 ONLINE
ABPAPP8 9973 44481 1 2 _SYSSMU52_429211313$ 2220032 ONLINE
所以從這個角度來看，其實後臺並沒有在持續回滾，應該是系統級的程式還沒有釋放導致了資料庫端標記為了KILLED,但是沒有實際採取行動。
檢視alert日誌也沒有什麼特別之處。
但是過了一會，突然發現多出來很多的日誌，最關鍵的是資料庫怎麼突然down了，日誌和pmon也有一定的關係。
Archived Log entry 1037518 added for thread 1 sequence 1037564 ID 0xd5242bc1 dest 1:
Tue May 26 10:41:25 2015
PMON failed to acquire latch, see PMON dump
Tue May 26 10:42:26 2015
PMON failed to acquire latch, see PMON dump
Tue May 26 10:44:06 2015
PMON failed to acquire latch, see PMON dump
Tue May 26 10:45:06 2015
PMON failed to acquire latch, see PMON dump
Tue May 26 10:46:46 2015
PMON failed to acquire latch, see PMON dump
Tue May 26 10:47:12 2015
Thread 1 cannot allocate new log, sequence 1037566
Checkpoint not complete
Current log# 3 seq# 1037565 mem# 0: /oravl02/oradata/UATDB1/redo_g3_m1.dbf
Current log# 3 seq# 1037565 mem# 1: /oravl03/oradata/UATDB1/redo_g3_m2.dbf
Tue May 26 10:47:13 2015
Completed checkpoint up to RBA [0xfd4fb.2.10], SCN: 13552283008295
Beginning log switch checkpoint up to RBA [0xfd4fe.2.10], SCN: 13552283030199
Thread 1 advanced to log sequence 1037566 (LGWR switch)
Current log# 4 seq# 1037566 mem# 0: /oravl02/oradata/UATDB1/redo_g4_m1.dbf
Current log# 4 seq# 1037566 mem# 1: /oravl03/oradata/UATDB1/redo_g4_m2.dbf
Tue May 26 10:47:13 2015
Archived Log entry 1037519 added for thread 1 sequence 1037565 ID 0xd5242bc1 dest 1:
Tue May 26 10:47:46 2015
PMON failed to acquire latch, see PMON dump
Tue May 26 10:48:05 2015
Shutting down instance (immediate)
Stopping background process SMCO
Shutting down instance: further logons disabled
Tue May 26 10:48:06 2015
Completed checkpoint up to RBA [0xfd4fe.2.10], SCN: 13552283030199
Completed checkpoint up to RBA [0xfd4fd.2.10], SCN: 13552283023016
Completed checkpoint up to RBA [0xfd4fc.2.10], SCN: 13552283015563
Stopping background process QMNC
Tue May 26 10:49:16 2015
PMON failed to acquire latch, see PMON dump
Tue May 26 10:50:16 2015
PMON failed to acquire latch, see PMON dump
因為當時是早班時間，也沒多想，正在琢磨是不是什麼bug導致的當機，簡單收集完資訊，就是儘快把資料庫給啟動起來。
啟動的時候也報錯了。當時就有些凌亂了。
SQL> startup mount
ORACLE instance started.
Total System Global Area 1.2727E+10 bytes
Fixed Size 2280384 bytes
Variable Size 1.0855E+10 bytes
Database Buffers 1577058304 bytes
Redo Buffers 292958208 bytes
Database mounted.
SQL> alter database open;
alter database open
*
ERROR at line 1:
ORA-01092: ORACLE instance terminated. Disconnection forced
ORA-00450: background process 'QMNC' did not start
ORA-00443: background process "QMNC" did not start
Process ID: 47857
Session ID: 10341 Serial number: 3

趕緊去檢視日誌，有些疑惑的是，資料庫怎麼啟動起來了。我用sqlplus反覆嘗試都沒有問題。真是奇怪。
對於這種問題還是相信日誌，我去找對應時間點的日誌，從日誌來看
資料庫似乎是使用了shutdown immediate的方式停掉的。有可能是人為的。

Tue May 26 10:48:05 2015

Shutting down instance (immediate)

Stopping background process SMCO

我傳送了封郵件抄給組內去確認，還沒有得到訊息。
然後繼續檢視日誌，看到後面又啟動了兩次，一次啟動失敗，一次啟動成功，但是我只啟動了一次啊。
最後得到確認，是另外一個遠在菲律賓的dba啟動的，但是事先沒有傳送郵件。這樣問題就清楚了，但是也算是大清早的一場鬧劇。2個人同時在啟動資料庫，最後也沒有造成什麼影響，可見oracle還是很健壯的，對於啟庫的併發都考慮了。：）
這個案例帶給我們的其實就是在清理session的時候，最好還是先繫結一下系統級操作程式，然後再清除，這樣也會給自己帶來很多便利，清除完成後，做一個確認檢查，可能session透過kill方式不一定能釋放系統程式資源，這個時候在判斷沒有回滾事務的前提下，
可以採用手工清理系統程式號的方式來完成。
至於啟庫的鬧劇還是完全可以避免的，還是協調的時候出了點問題。

重啟資料庫的一場鬧劇

相關文章