同事对rac集群生成性能报告时发现rac集群有一个实例没有生成awr快照，另一个实例快照正常。下面是具体处理步骤。
1号实例没有生成awr快照
SQL> select SNAP_ID,END_INTERVAL_TIME,instance_number from dba_hist_snapshot where instance_number=1; no rows selected
2号实快照正常
SQL> set long 200 SQL> set linesize 200 SQL> select * from ( select SNAP_ID,END_INTERVAL_TIME,instance_number from dba_hist_snapshot where instance_number=2 order by SNAP_ID desc) where rownum < =10; SNAP_ID END_INTERVAL_TIME INSTANCE_NUMBER ---------- --------------------------------------------------------------------------- --------------- 24405 17-AUG-19 07.00.47.595 PM 2 24404 17-AUG-19 06.00.42.150 PM 2 24403 17-AUG-19 05.00.37.041 PM 2 24402 17-AUG-19 04.00.31.774 PM 2 24401 17-AUG-19 03.00.26.414 PM 2 24400 17-AUG-19 02.00.21.176 PM 2 24399 17-AUG-19 01.00.16.316 PM 2 24398 17-AUG-19 12.00.10.997 PM 2 24397 17-AUG-19 11.00.05.446 AM 2 24396 17-AUG-19 10.00.59.801 AM 2 10 rows selected.
mmon进程与awr快照相关，mmnl与ash相关，如是查看两个实例的mmon与mmnl进程
2号实例
[root@db2 ~]# ps -ef | grep mmon root 128329 127956 0 18:11 pts/2 00:00:00 grep mmon oracle 201527 1 0 2018 ? 17:17:11 ora_mmon_RLZY2 [root@db2 ~]# ps -ef | grep mmnl root 131772 127956 0 18:17 pts/2 00:00:00 grep mmnl oracle 201531 1 0 2018 ? 1-06:06:24 ora_mmnl_RLZY2
1号实例
[root@db1 ~]# ps -ef | grep mmon root 239020 238963 0 18:52 pts/2 00:00:00 grep mmon [root@db1 ~]# ps -ef | grep mmnl root 239052 238963 0 18:52 pts/2 00:00:00 grep mmnl
可以看到1号实例没有mmon与mmnl进程了。
如是查看1号实例的mmon进程的跟踪文件
[root@db1 trace]# ls -lrt *mmon*.trc -rw-r----- 1 oracle asmadmin 1351052 Jan 19 2018 RLZY1_mmon_20073.trc -rw-r----- 1 oracle asmadmin 173031 Jan 22 2018 RLZY1_mmon_49119.trc [root@db1 trace]# more RLZY1_mmon_49119.trc Trace file /u01/app/oracle/diag/rdbms/rlzy/RLZY1/trace/RLZY1_mmon_49119.trc Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production With the Partitioning, Real Application Clusters, Automatic Storage Management, OLAP, Data Mining and Real Application Testing options ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_1 System name: Linux Node name: db1 Release: 3.8.13-68.3.4.el6uek.x86_64 Version: #2 SMP Tue Jul 14 15:03:36 PDT 2015 Machine: x86_64 Instance name: RLZY1 Redo thread mounted by this instance: 1 Oracle process number: 36 Unix process pid: 49119, image: oracle@db1 (MMON) *** 2018-01-19 13:55:20.030 *** SESSION ID:(1369.1) 2018-01-19 13:55:20.030 *** CLIENT ID:() 2018-01-19 13:55:20.030 *** SERVICE NAME:() 2018-01-19 13:55:20.030 *** MODULE NAME:() 2018-01-19 13:55:20.030 *** ACTION NAME:() 2018-01-19 13:55:20.030 minact-scn slave-status: grec-scn:0x0000.00000000 gmin-scn:0x0000.00000000 gcalc-scn:0x0000.00000000 *** 2018-01-19 14:00:20.643 minact-scn master-status: grec-scn:0x0e0e.55ad96ef gmin-scn:0x0e0e.55abf256 gcalc-scn:0x0e0e.55ac2a0a .......... KEBM: MMON action policy violation. 'Block Cleanout Optim, Undo Segment Scan' viol=1; err=12751 minact-scn master-status: grec-scn:0x0e0e.5f0ebf8c gmin-scn:0x0e0e.5f0eac2e gcalc-scn:0x0e0e.5f0ead91 DDE rules only execution for: ORA 12751 *** 2018-01-22 07:06:04.060 ----- START Event Driven Actions Dump ---- ---- END Event Driven Actions Dump ---- ----- START DDE Actions Dump ----- Executing SYNC actions Executing ASYNC actions ----- START DDE Action: 'ORA_12751_DUMP' (Sync) ----- Runtime exceeded 300 seconds Time limit violation detected at: ksedsts()+465< -kspol_12751_dump()+145<-dbgdaExecuteAction()+1065<-dbgerRunAction()+109<-dbgerRunActions()+4134<-dbgexPhaseII()+1873<-dbgexProcessError()+2680<-dbgeExecuteForError()+88<-dbgePostErrorKGE()+2136<-dbkePostKGE_kgsf()+71<-kge selv()+276<-ksesecl0()+162 <-ksucin()+147<-kcbzwb()+2727<-kcbgtcr()+31325<-ktucloUsMinScn()+539<-ktucloUsegScan()+992<-ksb_run_managed_action()+384<-ksbcti()+2490<-ksbabs()+1735<-kebm_mmon_main()+209<-ksbrdp()+1045<-opirip()+623<-opidrv()+603<-sou2o()+103<-opimai _real()+250<-ssthrdmain()+265 <-main()+201<-__libc_start_main()+253Current Wait Stack: 0: waiting for 'gc buffer busy acquire' file#=0x5, block#=0x278, class#=0x49 wait_id=255378 seq_num=59358 snap_id=1 wait times: snap=5 min 5 sec, exc=5 min 5 sec, total=5 min 5 sec wait times: max=infinite, heur=5 min 5 sec wait counts: calls=358 os=358 in_wait=1 iflags=0x15a2 There is at least one session blocking this session. Dumping 1 direct blocker(s): inst: 1, sid: 990, ser: 1 Dumping final blocker: inst: 1, sid: 990, ser: 1 Wait State: fixed_waits=0 flags=0x22 boundary=(nil)/-1 Session Wait History: elapsed time of 0.000061 sec since current wait 0: waited for 'gc cr block 2-way' =0x5, =0x258, =0x47 wait_id=255377 seq_num=59357 snap_id=1 wait times: snap=0.000478 sec, exc=0.000478 sec, total=0.000478 sec wait times: max=infinite wait counts: calls=1 os=1 occurred after 0.000122 sec of elapsed time 1: waited for 'gc cr block 2-way' =0x5, =0x228, =0x45 wait_id=255376 seq_num=59356 snap_id=1 wait times: snap=0.000741 sec, exc=0.000741 sec, total=0.000741 sec wait times: max=infinite wait counts: calls=1 os=1 occurred after 0.000120 sec of elapsed time 2: waited for 'gc cr block 2-way' =0x5, =0x138, =0x43 wait_id=255375 seq_num=59355 snap_id=1 wait times: snap=0.000528 sec, exc=0.000528 sec, total=0.000528 sec wait times: max=infinite wait counts: calls=1 os=1 occurred after 0.000111 sec of elapsed time 3: waited for 'gc cr block 2-way' =0x5, =0xb8, =0x41 wait_id=255374 seq_num=59354 snap_id=1 wait times: snap=0.000583 sec, exc=0.000583 sec, total=0.000583 sec wait times: max=infinite wait counts: calls=1 os=1 occurred after 0.000139 sec of elapsed time 4: waited for 'gc cr block 2-way' =0x5, =0x110, =0x37 wait_id=255373 seq_num=59353 snap_id=1 wait times: snap=0.000541 sec, exc=0.000541 sec, total=0.000541 sec wait times: max=infinite wait counts: calls=1 os=1 occurred after 0.000110 sec of elapsed time 5: waited for 'gc cr block 2-way' =0x5, =0x100, =0x35 wait_id=255372 seq_num=59352 snap_id=1 wait times: snap=0.000629 sec, exc=0.000629 sec, total=0.000629 sec wait times: max=infinite wait counts: calls=1 os=1 occurred after 0.000158 sec of elapsed time 6: waited for 'gc cr block 2-way' =0x5, =0xf0, =0x33 wait_id=255371 seq_num=59351 snap_id=1 wait times: snap=0.000617 sec, exc=0.000617 sec, total=0.000617 sec wait times: max=infinite wait counts: calls=1 os=1 occurred after 0.000128 sec of elapsed time 7: waited for 'gc cr block 2-way' =0x5, =0xe0, =0x31 wait_id=255370 seq_num=59350 snap_id=1 wait times: snap=0.000561 sec, exc=0.000561 sec, total=0.000561 sec wait times: max=infinite wait counts: calls=1 os=1 occurred after 0.000124 sec of elapsed time 8: waited for 'gc cr block 2-way' =0x5, =0xd0, =0x2f wait_id=255369 seq_num=59349 snap_id=1 wait times: snap=0.000565 sec, exc=0.000565 sec, total=0.000565 sec wait times: max=infinite wait counts: calls=1 os=1 occurred after 0.000128 sec of elapsed time 9: waited for 'gc cr block 2-way' =0x5, =0xc0, =0x2d wait_id=255368 seq_num=59348 snap_id=1 wait times: snap=0.000555 sec, exc=0.000555 sec, total=0.000555 sec wait times: max=infinite wait counts: calls=1 os=1 occurred after 0.000125 sec of elapsed time Sampled Session History of session 1369 serial 1 --------------------------------------------------- The sampled session history is constructed by sampling the target session every 1 second. The sampling process captures at each sample if the session is in a non-idle wait, an idle wait, or not in a wait. If the session is in a non-idle wait then one interval is shown for all the samples the session was in the same non-idle wait. If the session is in an idle wait or not in a wait for consecutive samples then one interval is shown for all the consecutive samples. Though we display these consecutive samples in a single interval the session may NOT be continuously idle or not in a wait (the sampling process does not know). The history is displayed in reverse chronological order. sample interval: 1 sec, max history 120 sec --------------------------------------------------- [121 samples, 07:04:03 - 07:06:03] waited for 'gc buffer busy acquire', seq_num: 59358 p1: 'file#'=0x5 p2: 'block#'=0x278 p3: 'class#'=0x49 time_waited: >= 120 sec (still in wait) --------------------------------------------------- Sampled Session History Summary: longest_non_idle_wait: 'gc buffer busy acquire' [121 samples, 07:04:03 - 07:06:03] time_waited: >= 120 sec (still in wait) --------------------------------------------------- ----- END DDE Action: 'ORA_12751_DUMP' (SUCCESS, 1 csec) ----- ----- END DDE Actions Dump (total 1 csec) ----- KEBM: MMON action policy violation. 'Block Cleanout Optim, Undo Segment Scan' viol=1; err=12751 minact-scn master-status: grec-scn:0x0e0e.5f0ec4ce gmin-scn:0x0e0e.5f0eac2e gcalc-scn:0x0e0e.5f0ead91 *** 2018-01-22 07:11:11.071 DDE rules only execution for: ORA 12751 ----- START Event Driven Actions Dump ---- ---- END Event Driven Actions Dump ----
ORA12751的错误原因是陈旧的SYS对象统计数据会导致生成次优执行计划，从而使AWR自动刷新从操作的语句运行更长时间和超时。
解决方法就是收集新的SYS对象统计信息，为优化器提供更好的统计信息，并生成更高效的执行计划
SQL> EXEC DBMS_STATS.GATHER_FIXED_OBJECTS_STATS;
PL/SQL procedure successfully completed.
SQL> EXEC DBMS_STATS.GATHER_SCHEMA_STATS ('SYS');
PL/SQL procedure successfully completed.
下面就是重启mmon和mmnl进程
SQL> alter system enable restricted session; System altered. SQL> alter system disable restricted session; System altered.
查看alert日志可以看到mmon和mmnl进程已经重启了
Sat Aug 17 19:18:22 2019 Starting background process MMON Sat Aug 17 19:18:22 2019 Starting background process MMNL MMON started with pid=399, OS id=10373 Sat Aug 17 19:18:22 2019 MMNL started with pid=405, OS id=10375 ALTER SYSTEM enable restricted session; Sat Aug 17 19:18:25 2019 Some DDE async actions failed or were cancelled Sat Aug 17 19:18:25 2019 Sweep [inc][48021]: completed Sweep [inc][48011]: completed Sweep [inc][48002]: completed Sweep [inc][35010]: completed Sweep [inc][34706]: completed Sweep [inc][34242]: completed Sweep [inc][33546]: completed Sweep [inc][33394]: completed Sweep [inc2][48021]: completed Sweep [inc2][48011]: completed Sweep [inc2][48002]: completed Sweep [inc2][35010]: completed Sweep [inc2][34706]: completed Sweep [inc2][34242]: completed Sweep [inc2][33546]: completed Sweep [inc2][33394]: completed minact-scn: Inst 1 is a slave inc#:30 mmon proc-id:10373 status:0x2 minact-scn status: grec-scn:0x0e0e.61cb2e9c gmin-scn:0x0e0e.5f0eac2e gcalc-scn:0x0e0e.5f0ead91 Sat Aug 17 19:18:29 2019 db_recovery_file_dest_size of 10240 MB is 20.87% used. This is a user-specified limit on the amount of space that will be used by this database for recovery-related files, and does not reflect the amount of space available in the underlying filesystem or ASM diskgroup. Sat Aug 17 19:18:42 2019 ALTER SYSTEM disable restricted session;
再查看1号实例的mmon与mmnl进程状态
[root@db1 ~]# ps -ef | grep mmnl oracle 10375 1 0 19:18 ? 00:00:00 ora_mmnl_RLZY1 root 10611 238963 0 19:18 pts/2 00:00:00 grep mmnl [root@db1 ~]# ps -ef | grep mmon oracle 10373 1 7 19:18 ? 00:00:02 ora_mmon_RLZY1 root 10630 238963 0 19:18 pts/2 00:00:00 grep mmon
过了两个小时去查看1号实例已经生成了两条快照信息
SQL> set long 200 SQL> set linesize 200 SQL> select * from ( select SNAP_ID,END_INTERVAL_TIME,instance_number from dba_hist_snapshot where instance_number=1 order by SNAP_ID desc) where rownum < =10; SNAP_ID END_INTERVAL_TIME INSTANCE_NUMBER ---------- --------------------------------------------------------------------------- --------------- 24407 17-AUG-19 09.00.58.595 PM 1 24406 17-AUG-19 08.00.40.244 PM 1
到此问题解决了。
