重启数据库的一场闹剧(r5笔记第68天)
重启数据库的一场闹剧(r5笔记第68天)
在几周前，某个测试环境在尝试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方式不一定能释放系统进程资源，这个时候在判断没有回滚事务的前提下， 可以采用手工清理系统进程号的方式来完成。 至于启库的闹剧还是完全可以避免的，还是协调的时候出了点问题。