最近在测试生产数据库时发现数据库在open过程很长慢，大概持续20分钟左右，有时持续1-2个小时。日志如下： Fri Nov 23 10:53:51 2018 SMON: enabling tx recovery Database Characterset is AL32UTF8 Fri Nov 23 10:54:02 2018 Decreasing number of real time LMS from 2 to 0 Fri Nov 23 10:54:05 2018 No Resource Manager plan active Fri Nov 23 10:54:47 2018 Starting background process GTX0 Fri Nov 23 10:54:47 2018 GTX0 started with pid=41, OS id=14549130 Starting background process RCBG Fri Nov 23 10:54:48 2018<================== RCBG started with pid=43, OS id=14811234 replication_dependency_tracking turned off (no async multimaster replication found) Fri Nov 23 14:07:01 2018<==================== 从RCBG进程启动到QMNC进程启动之间间隔了180分钟左右，而其他open过程占用一分钟左右。 Starting background process QMNC Fri Nov 23 14:07:01 2018 QMNC started with pid=31, OS id=28246190 Fri Nov 23 14:07:57 2018 Completed: alter database open 。 为了进一步分析 RCBG 到 QMNC 启动慢的原因，做如下日志日志跟踪： 1. 做oracel hanganalyze 数据库启动到mount 状态 在看到alert log打印如下字样时，在另外的sqlplus窗口下收集3次，间隔2~3分钟收集一次： 步骤如下： sqlplus / as sysdba oradebug setmypid oradebug -G all dump systemstate 267 oradebug -G all hanganalyze 2 等2~3分钟 oradebug -G all dump systemstate 267 oradebug -G all hanganalyze 2 等2~3分钟 oradebug -G all dump systemstate 267 oradebug -G all hanganalyze 2 oradebug tracefile_name alter 日志产生如下文件 No Resource Manager plan active Fri Nov 23 15:09:25 2018 Starting background process GTX0 Fri Nov 23 15:09:25 2018 GTX0 started with pid=41, OS id=8585312 Starting background process RCBG Fri Nov 23 15:09:26 2018 RCBG started with pid=43, OS id=18809034 replication_dependency_tracking turned off (no async multimaster replication found) Fri Nov 23 15:39:33 2018 System State dumped to trace file /u01/app/oracle/diag/rdbms/erpdb/ erpdb 1/trace/erpdb 1_diag_31850618.trc 从文件上看oracle 在open过程中等待如下
1. -- Trace File -- Starting Systemstate 1 ......................................... Ass.Awk Version 1.0.31 ~~~~~~~~~~~~~~~~~~~~~~ Source file : symbols1_diag_31850618.trc System State 1 (2018-11-23 15:39:32.932) ~~~~~~~~~~~~~~ ~~~~~~~~~~~~~~~~~~~~~~~ 1: [DEAD] 2: waiting for 'pmon timer' 3: waiting for 'rdbms ipc message' 4: waiting for 'VKTM Logical Idle Wait' 5: waiting for 'rdbms ipc message' 6: 7: waiting for 'rdbms ipc message' 8: waiting for 'PING' 9: waiting for 'rdbms ipc message' 10: waiting for 'DIAG idle wait' 11: waiting for 'rdbms ipc message' 12: waiting for 'ges remote message'<===lmd 13: waiting for 'gcs remote message'<===lms 14: waiting for 'gcs remote message'<===lms 15: waiting for 'rdbms ipc message' 16: waiting for 'GCR sleep' 17: waiting for 'rdbms ipc message' 18: waiting for 'rdbms ipc message' 19: waiting for 'rdbms ipc message' 20: waiting for 'rdbms ipc message' 21: waiting for 'rdbms ipc message' 22: waiting for 'smon timer' 23: waiting for 'rdbms ipc message' 24: waiting for 'rdbms ipc message' 25: waiting for 'ASM background timer' 26: waiting for 'rdbms ipc message' 27: waiting for 'rdbms ipc message' 28: 29: 30: waiting for 'wait for unread message on broadcast channel' 31: waiting for 'class slave wait' 32: waiting for 'rdbms ipc message' 33: waiting for 'rdbms ipc message' 34: waiting for 'db file scattered read' (0x4f,0xa2766,0xb) 35: waiting for 'rdbms ipc reply' (from_process=6)[IPC 6] 37: waiting for 'rdbms ipc message' 38: waiting for 'rdbms ipc message' 39: waiting for 'rdbms ipc message' 40: waiting for 'rdbms ipc message' 41: waiting for 'rdbms ipc message' 43: waiting for 'wait for unread message on broadcast channel'
2. flags2: (0x409) -/-/INC DID: , short-term DID: txn branch: 0x0 edition#: 0 oct: 0, prv: 0, sql: 0x0, psql: 0x0, user: 0/SYS ksuxds FALSE at location: 0 service name: SYS$BACKGROUND Current Wait Stack: 0: waiting for 'gcs remote message' waittime=0x1e, poll=0x0, event=0x0 wait_id=51479 seq_num=51480 snap_id=1 wait times: snap=0.000577 sec, exc=0.000577 sec, total=0.000577 sec wait times: max=0.030000 sec, heur=31 min 42 sec<============== 应该是实例启动到dump时总共等待时间，这儿说明私网gcs消息传输可能有问题。 为了排除私有网卡的问题部署oswatch，从oswatch收集的信息看，网络和资源都没有问题。 2. 为了进一步确定原因 truss -aefdo /tmp/truss.out sqlplus / as sysdba alter database open; 从日志上分析可以看到 14876838: 56950981: 2.0001: kread(9, "01 -\0\006\0\0\0\0\011 i".., 8208) (sleeping...) 21954596: 92471451: 2.0001: kread(0, "\n l t e r d a t a b a".., 4096) (sleeping...) 21954596: 92471451: kread(0, " e x i t\n d a t a b a".., 4096) = 5 21954596: 92471451: 1344.6921: kfcntl(1, F_GETFL, 0x0000000000000008) = 67110914<=== 从它前面的kread读取的终端输入是exit来看应该是已经完成了open执行推出之后的os call了，所以上面的1344.6921秒是不能计入open过程的，排除这个之后来看，主要问题就是aio了， listio64 数目高达123644次，而单次等待从0.0003到0.5271s不等 14876838: 56950981: kpread(24, 0x07000107C5755000, 4096, 0x0000004FBAD2A000, 0x000000000000007D) = 4096 14876838: 56950981: kpread(24, 0x07000107C5E14000, 4096, 0x000000E41E85F000, 0x000000000000007D) = 4096 14876838: 56950981: 0.5271: listio64(0x0000000010000004, 0x000000000FFFFFFF, 0x00000000FFFCC1E0, 0x0000000000000001, 0x0000000000000000, 0x0000000000000000, 0x00000001116E89A0, 0x0000000000000040) = 0x0000000000000000 ， ---Continue--- 有一点还是很奇怪，按理open的时候已经完成了crash recovery了，此时对数据文件只有读没有写了，但为何您这里出来这么多 kpread，还是令人不解。 为什么从RCBG进程启动到QMNC进程启动之间间隔很长时间那，而其他后台进程open过程占用一分钟左右。 从上边的分析，问题又回到了原点。难道是oracle bug， 为了进一步确认问题，在mos搜到如下一篇文章： Procedure to Manually Coalesce All the IOTs / Indexes Associated with Advanced Queueing Tables to Maintain Enqueue / Dequeue Performance; Reduce QMON CPU Usage and Redo Generation ( 文档 ID 271855.1) 为了验证文章的可靠性，通过此文章提供的脚本，进行修复，数据库能正常OPEN,并且很快。日志如下： Database Characterset is AL32UTF8 No Resource Manager plan active Starting background process GTX0 Fri Nov 23 16:39:33 2018 GTX0 started with pid=36, OS id=16056540 Starting background process RCBG Fri Nov 23 16:41:23 2018 RCBG started with pid=37, OS id=26214482 replication_dependency_tracking turned off (no async multimaster replication found) Starting background process QMNC Fri Nov 23 16:42:23 2018 QMNC started with pid=39, OS id=14287094 Fri Nov 23 16:43:33 2018 Completed: ALTER DATABASE OPEN 这个案例的后续是，如果经常使用AQ，数据库可以不定期做碎片整理。
