一、 问题分析
在hp-ux上11.2.0.4 RAC，两个节点的节点2上进行恢复数据库操作，数据量大约11T；所需应用的归档日志量大约1.3T，每个归档的大小接近2G，共655个归档日志文件；
客户在8号下午开始进行recover：Recover database until time “to_date(‘2015-12-19 15:40:00′,’yyyy-mm-dd hh24:mi:ss’)”;在9号上班时发现一夜过去，仅应用了13个归档日志文件。
在现场针对该问题进行解决并查找产生原因进行分析。.
如下为本次问题的分析及相关的模拟验证。
1.1 查看备份恢复脚本
首先查看了前面备份、恢复的脚本。备份文件存放在HP DP备份软件带库中，备份恢复脚本与正常恢复没有差异。如下recover脚本内容：
Recover database until time “to_date(‘2015-12-19 15:40:00′,’yyyy-mm-dd hh24:mi:ss’)”;
1.2 查看当前系统的资源使用情况
部分信息如下，系统资源使用情况较为正常。
$>/usr/sbin/kctune|grep filecache
filecache_max 6527386828 5% Imm (auto disabled)
filecache_min 6527386828 5% Imm (auto disabled)
$>sar -u 2 5
HP-UX P2AAAAA2 B.11.31 U ia64 12/29/15
16:36:24 %usr %sys %wio %idle
16:36:26 10 0 0 90
16:36:28 10 0 0 90
16:36:30 10 0 0 90
16:36:32 10 0 0 90
16:36:34 10 0 0 89
Average 10 0 0 90
1.3 查看会话相关等待事件
通过对v$session视图的信息进行查询，当前系统中存在大量并行恢复的进程。当前event大多为parallel recovery slave next change。
col EVENT for a45
col USERNAME for a10
set linesize 180
col PROGRAM for a30
set pagesize 100
select sid,USERNAME,PROGRAM,event,SECONDS_IN_WAIT,WAIT_TIME from v$session;
SID USERNAME PROGRAM EVENT
———- —————————— —————————— ————————————————–
1 SYS sqlplus@P2AAAAA2 (TNS V1-V3) class slave wait
3 SYS oracle@P2AAAAA2 (PR0S) parallel recovery slave next change
10 SYS oracle@P2AAAAA2 (PR0T) parallel recovery slave next change
17 oracle@P2AAAAA2 (PMON) pmon timer
18 SYS oracle@P2AAAAA2 (PR00) parallel recovery read buffer free
20 SYS oracle@P2AAAAA2 (PR0U) parallel recovery slave next change
25 oracle@P2AAAAA2 (PSP0) rdbms ipc message
27 SYS oracle@P2AAAAA2 (PR0V) parallel recovery slave next change
33 oracle@P2AAAAA2 (VKTM) VKTM Logical Idle Wait
34 SYS sqlplus@P2AAAAA2 (TNS V1-V3) SQL*Net message from client
36 SYS oracle@P2AAAAA2 (PR0W) parallel recovery slave next change
41 oracle@P2AAAAA2 (GEN0) rdbms ipc message
42 SYS oracle@P2AAAAA2 (PR01) parallel recovery slave next change
49 oracle@P2AAAAA2 (DIAG) DIAG idle wait
50 SYS oracle@P2AAAAA2 (PR02) parallel recovery slave next change
57 oracle@P2AAAAA2 (DBRM) rdbms ipc message
58 SYS oracle@P2AAAAA2 (PR03) parallel recovery slave next change
65 oracle@P2AAAAA2 (PING) PING
66 SYS oracle@P2AAAAA2 (PR04) parallel recovery slave next change
73 oracle@P2AAAAA2 (ACMS) rdbms ipc message
74 SYS oracle@P2AAAAA2 (PR05) parallel recovery slave next change
81 oracle@P2AAAAA2 (DIA0) DIAG idle wait
82 SYS oracle@P2AAAAA2 (PR06) parallel recovery slave next change
89 oracle@P2AAAAA2 (LMON) rdbms ipc message
90 SYS oracle@P2AAAAA2 (PR07) parallel recovery slave next change
97 oracle@P2AAAAA2 (LMD0) ges remote message
98 SYS oracle@P2AAAAA2 (PR08) parallel recovery slave next change
105 oracle@P2AAAAA2 (RMS0) rdbms ipc message
106 SYS oracle@P2AAAAA2 (PR09) parallel recovery slave next change
113 oracle@P2AAAAA2 (LMHB) GCR sleep
114 SYS oracle@P2AAAAA2 (PR0A) parallel recovery slave next change
121 oracle@P2AAAAA2 (MMAN) rdbms ipc message
122 SYS oracle@P2AAAAA2 (PR0B) parallel recovery slave next change
129 oracle@P2AAAAA2 (DBW0) rdbms ipc message
130 SYS oracle@P2AAAAA2 (PR0C) parallel recovery slave next change
137 oracle@P2AAAAA2 (DBW1) rdbms ipc message
138 SYS oracle@P2AAAAA2 (PR0D) parallel recovery slave next change
145 oracle@P2AAAAA2 (DBW2) rdbms ipc message
146 SYS oracle@P2AAAAA2 (PR0E) parallel recovery slave next change
153 oracle@P2AAAAA2 (DBW3) rdbms ipc message
154 SYS oracle@P2AAAAA2 (PR0F) parallel recovery slave next change
161 oracle@P2AAAAA2 (LGWR) rdbms ipc message
162 SYS oracle@P2AAAAA2 (PR0G) parallel recovery slave next change
169 SYS oracle@P2AAAAA2 (PR0H) parallel recovery slave next change
170 oracle@P2AAAAA2 (CKPT) rdbms ipc message
177 oracle@P2AAAAA2 (SMON) smon timer
178 SYS oracle@P2AAAAA2 (PR0I) parallel recovery slave next change
185 oracle@P2AAAAA2 (RECO) rdbms ipc message
186 SYS oracle@P2AAAAA2 (PR0J) free buffer waits
193 oracle@P2AAAAA2 (RBAL) rdbms ipc message
194 SYS oracle@P2AAAAA2 (PR0K) parallel recovery slave next change
201 oracle@P2AAAAA2 (ASMB) ASM background timer
202 SYS oracle@P2AAAAA2 (PR0L) parallel recovery slave next change
209 oracle@P2AAAAA2 (MMON) rdbms ipc message
211 SYS oracle@P2AAAAA2 (PR0M) parallel recovery slave next change
217 oracle@P2AAAAA2 (MMNL) rdbms ipc message
218 SYS oracle@P2AAAAA2 (PR0N) parallel recovery slave next change
225 SYS oracle@P2AAAAA2 (PR0O) parallel recovery slave next change
233 oracle@P2AAAAA2 (MARK) wait for unread message on broadcast channel
235 SYS oracle@P2AAAAA2 (PR0P) parallel recovery slave next change
241 SYS oracle@P2AAAAA2 (PR0Q) parallel recovery slave next change
249 SYS sqlplus@P2AAAAA2 (TNS V1-V3) SQL*Net message to client
250 SYS oracle@P2AAAAA2 (PR0R) parallel recovery slave next change
63 rows selected.
SQL> select sid,USERNAME,PROGRAM,event from v$session where PROGRAM like ‘%PR%’;
SID USERNAME PROGRAM EVENT
———- —————————— —————————— ————————————————–
3 SYS oracle@P2AAAAA2 (PR0T) parallel recovery slave next change
10 SYS oracle@P2AAAAA2 (PR0U) parallel recovery slave next change
20 SYS oracle@P2AAAAA2 (PR0V) parallel recovery slave next change
27 SYS oracle@P2AAAAA2 (PR0W) parallel recovery slave next change
36 SYS oracle@P2AAAAA2 (PR01) parallel recovery slave next change
42 SYS oracle@P2AAAAA2 (PR02) parallel recovery slave next change
50 SYS oracle@P2AAAAA2 (PR03) parallel recovery slave next change
58 SYS oracle@P2AAAAA2 (PR04) parallel recovery slave next change
66 SYS oracle@P2AAAAA2 (PR05) parallel recovery slave next change
74 SYS oracle@P2AAAAA2 (PR06) parallel recovery slave next change
82 SYS oracle@P2AAAAA2 (PR07) parallel recovery slave next change
90 SYS oracle@P2AAAAA2 (PR08) parallel recovery slave next change
98 SYS oracle@P2AAAAA2 (PR09) parallel recovery slave next change
106 SYS oracle@P2AAAAA2 (PR0A) parallel recovery slave next change
114 SYS oracle@P2AAAAA2 (PR0B) parallel recovery slave next change
122 SYS oracle@P2AAAAA2 (PR0C) parallel recovery slave next change
130 SYS oracle@P2AAAAA2 (PR0D) parallel recovery slave next change
138 SYS oracle@P2AAAAA2 (PR0E) parallel recovery slave next change
146 SYS oracle@P2AAAAA2 (PR0F) parallel recovery slave next change
154 SYS oracle@P2AAAAA2 (PR0G) parallel recovery slave next change
162 SYS oracle@P2AAAAA2 (PR0H) parallel recovery slave next change
169 SYS oracle@P2AAAAA2 (PR0I) parallel recovery slave next change
178 SYS oracle@P2AAAAA2 (PR0J) parallel recovery slave next change
186 SYS oracle@P2AAAAA2 (PR0K) parallel recovery slave next change
194 SYS oracle@P2AAAAA2 (PR0L) parallel recovery slave next change
202 SYS oracle@P2AAAAA2 (PR0M) parallel recovery slave next change
211 SYS oracle@P2AAAAA2 (PR0N) parallel recovery slave next change
218 SYS oracle@P2AAAAA2 (PR0O) parallel recovery slave next change
225 SYS oracle@P2AAAAA2 (PR0P) parallel recovery slave next change
235 SYS oracle@P2AAAAA2 (PR0Q) parallel recovery slave next change
241 SYS oracle@P2AAAAA2 (PR0R) parallel recovery slave next change
249 SYS oracle@P2AAAAA2 (PR0S) parallel recovery slave next change
250 SYS oracle@P2AAAAA2 (PR00) parallel recovery control message reply
33 rows selected.
$>ps -ef|grep ora_pro*
oracle 25652 1 3 16:18:12 ? 1:05 ora_pr0k_p1aaaaa2
oracle 25674 1 40 16:18:12 ? 0:57 ora_pr0u_p1aaaaa2
oracle 25623 1 9 16:18:11 ? 1:13 ora_pr06_p1aaaaa2
oracle 29093 27745 0 16:34:45 pts/5 0:00 grep ora_pro*
oracle 25658 1 28 16:18:12 ? 0:54 ora_pr0m_p1aaaaa2
oracle 25617 1 21 16:18:11 ? 1:17 ora_pr03_p1aaaaa2
oracle 25672 1 16 16:18:12 ? 1:21 ora_pr0t_p1aaaaa2
oracle 25662 1 33 16:18:12 ? 1:19 ora_pr0o_p1aaaaa2
oracle 25629 1 16 16:18:12 ? 1:17 ora_pr09_p1aaaaa2
oracle 25666 1 43 16:18:12 ? 1:03 ora_pr0q_p1aaaaa2
oracle 25645 1 31 16:18:12 ? 1:24 ora_pr0h_p1aaaaa2
oracle 25649 1 42 16:18:12 ? 0:52 ora_pr0j_p1aaaaa2
oracle 25678 1 22 16:18:12 ? 1:19 ora_pr0w_p1aaaaa2
oracle 25647 1 33 16:18:12 ? 1:21 ora_pr0i_p1aaaaa2
oracle 25670 1 21 16:18:12 ? 0:55 ora_pr0s_p1aaaaa2
oracle 25676 1 12 16:18:12 ? 1:13 ora_pr0v_p1aaaaa2
oracle 25627 1 16 16:18:11 ? 1:10 ora_pr08_p1aaaaa2
oracle 25668 1 4 16:18:12 ? 0:53 ora_pr0r_p1aaaaa2
oracle 25643 1 32 16:18:12 ? 1:06 ora_pr0g_p1aaaaa2
oracle 25613 1 16 16:18:11 ? 1:10 ora_pr01_p1aaaaa2
oracle 25641 1 19 16:18:12 ? 0:59 ora_pr0f_p1aaaaa2
oracle 25654 1 7 16:18:12 ? 0:57 ora_pr0l_p1aaaaa2
oracle 25639 1 0 16:18:12 ? 1:15 ora_pr0e_p1aaaaa2
oracle 25664 1 46 16:18:12 ? 1:14 ora_pr0p_p1aaaaa2
oracle 25609 1 254 16:18:10 ? 6:21 ora_pr00_p1aaaaa2
oracle 25625 1 22 16:18:11 ? 0:50 ora_pr07_p1aaaaa2
oracle 25621 1 61 16:18:11 ? 0:54 ora_pr05_p1aaaaa2
oracle 25619 1 14 16:18:11 ? 1:07 ora_pr04_p1aaaaa2
oracle 25637 1 17 16:18:12 ? 2:16 ora_pr0d_p1aaaaa2
oracle 25635 1 55 16:18:12 ? 0:50 ora_pr0c_p1aaaaa2
oracle 25660 1 33 16:18:12 ? 1:15 ora_pr0n_p1aaaaa2
oracle 25631 1 22 16:18:12 ? 1:02 ora_pr0a_p1aaaaa2
oracle 25633 1 13 16:18:12 ? 1:03 ora_pr0b_p1aaaaa2
oracle 25615 1 27 16:18:11 ? 1:05 ora_pr02_p1aaaaa2
1.4 对数据库内存及并行相关参数进行查验
通过对内存相关参数进行查验，当前使用的是AMM自动内存管理，共分配了1G内存。
当前主机是128G内存的，这个值明显偏小。
对于并行回滚、并行服务等相关参数进行查验，均为系统默认值。
SQL> select status,instance_name from gv$instance;
STATUS INSTANCE_NAME
———————— ——————————–
MOUNTED p1aaaaa2
SQL> show parameter memo
NAME TYPE VALUE
———————————— ———————- ——————————
hi_shared_memory_address integer 0
memory_max_target big integer 1G
memory_target big integer 1G
shared_memory_address integer 0
SQL> show parameter sga
NAME TYPE VALUE
———————————— ———————- ——————————
lock_sga boolean FALSE
pre_page_sga boolean FALSE
sga_max_size big integer 1G
sga_target big integer 0
SQL> show parameter pga
NAME TYPE VALUE
———————————— ———————- ——————————
pga_aggregate_target big integer 0
SQL> col name for a40
SQL> select * from v$sgainfo;
NAME BYTES RESIZE
—————————————- ———- ——
Fixed SGA Size 2212392 No
Redo Buffers 9756672 No
Buffer Cache Size 159383552 Yes
Shared Pool Size 381681664 Yes
Large Pool Size 79691776 Yes
Java Pool Size 4194304 Yes
Streams Pool Size 0 Yes
Shared IO Pool Size 0 Yes
Granule Size 4194304 No
Maximum SGA Size 1068937216 No
Startup overhead in Shared Pool 228519832 No
Free SGA Memory Available 432013312
12 rows selected.
———————————————
SQL> show parameter PARALLEL_MAX_SERVERS
NAME TYPE VALUE
———————————— ———————- ——————————
parallel_max_servers integer 120
SQL> show parameter fast_start_parallel
NAME TYPE VALUE
———————————— ———————- ——————————
fast_start_parallel_rollback string LOW
SQL> show parameter cpu
NAME TYPE VALUE
———————————— ———————- ——————————
cpu_count integer 32
parallel_threads_per_cpu integer 2
resource_manager_cpu_allocation integer 32
SQL> show parameter RECOVERY_PARALLELISM
NAME TYPE VALUE
———————————— ———————- ——————————
recovery_parallelism integer 0
问题查到这里，已经有些眉目；较大可能是因为并行恢复引起的争用；同时数据库内存资源分配较少，也会对并行恢复造成影响。
因此环境为迁移后的生产环境，目前进行的是数据恢复测试；因此，为了确认是否并行引起的问题，对恢复进程进行了10046跟踪。
1.5 使用trace命令对recover的过程进行跟踪
SQL> alter session set tracefile_identifier=’rman7_10046′;
Session altered.
SQL> alter session set events ‘10046 trace name context forever,level 12′;
Session altered.
SQL> recover database using backup controlfile until cancel;
ORA-00279: change 10286665324215 generated at 12/19/2015 04:02:42 needed for
thread 2
ORA-00289: suggestion : +DATA/p2aaaaa/arch/2_67571_790336456.dbf
ORA-00280: change 10286665324215 for thread 2 is in sequence #67571
Specify log: {<RET>=suggested | filename | AUTO | CANCEL}
auto
trace文件分析：
*** 2015-12-29 11:31:01.992
WAIT #11529215044981989888: nam=’class slave wait’ ela= 1009897 slave id=0 p2=0 p3=0 obj#=-1 tim=341067374554
WAIT #11529215044981989888: nam=’parallel recovery control message reply’ ela= 108015 p1=0 p2=0 p3=0 obj#=-1 tim=341067482664
*** 2015-12-29 11:31:03.110
WAIT #11529215044981989888: nam=’class slave wait’ ela= 1009993 slave id=0 p2=0 p3=0 obj#=-1 tim=341068492679
WAIT #11529215044981989888: nam=’parallel recovery control message reply’ ela= 109933 p1=0 p2=0 p3=0 obj#=-1 tim=341068602680
—这里的ela= 109933是微秒，约为1秒
*** 2015-12-29 11:31:04.230
WAIT #11529215044981989888: nam=’class slave wait’ ela= 1009912 slave id=0 p2=0 p3=0 obj#=-1 tim=341069612682
WAIT #11529215044981989888: nam=’parallel recovery control message reply’ ela= 109877 p1=0 p2=0 p3=0 obj#=-1 tim=341069722665
*** 2015-12-29 11:31:05.350
WAIT #11529215044981989888: nam=’class slave wait’ ela= 1009978 slave id=0 p2=0 p3=0 obj#=-1 tim=341070732669
WAIT #11529215044981989888: nam=’parallel recovery control message reply’ ela= 109908 p1=0 p2=0 p3=0 obj#=-1 tim=341070842664
*** 2015-12-29 11:31:06.470
WAIT #11529215044981989888: nam=’class slave wait’ ela= 1009980 slave id=0 p2=0 p3=0 obj#=-1 tim=341071852670
WAIT #11529215044981989888: nam=’parallel recovery control message reply’ ela= 109948 p1=0 p2=0 p3=0 obj#=-1 tim=341071962664
*** 2015-12-29 11:31:07.590
WAIT #11529215044981989888: nam=’class slave wait’ ela= 1009983 slave id=0 p2=0 p3=0 obj#=-1 tim=341072972669
WAIT #11529215044981989888: nam=’parallel recovery control message reply’ ela= 109950 p1=0 p2=0 p3=0 obj#=-1 tim=341073082665
———-tkprof格式化后的输出：
从如下输出可以看到在并行恢复上确实存在大量等待。
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
—————————————- Waited ———- ————
KSV master wait 8 0.00 0.00
parallel recovery control message reply 568 0.11 60.67
class slave wait 573 1.01 554.60
SQL*Net break/reset to client 8 0.00 0.00
SQL*Net message to client 6 0.00 0.00
SQL*Net message from client 6 7.20 7.20
latch free 2 0.00 0.00
master exit 65 3.01 10.12
********************************************************************************
通过以上分析，可以发现时间主要花费在class slave wait/parallel recovery control message reply等待事件上。
1.6 问题初步小结
通过以上分析，可以发现应用归档日志时大量时间花费在class slave wait/parallel recovery control message reply等待事件上。
通过对数据库相关参数的确认，当前数据库的内存设置偏小。
同时因为CPU数量多达32，对应的默认就会产生32个并行恢复进程。
通过在执行recover时对v$session视图进行查询，以及10046对recover恢复命令进行跟踪，可以确认是并行恢复时的争用引起的recover非常缓慢。
二、解决与验证
经过上一步的分析，基本确认是并行争用引起的问题，因此采取如下措施：
计划通过调大内存相关参数，然后再限制并行恢复进程的方式对此问题进行解决与验证。
2.1 调整内存相关参数
首先关闭AMM，设置SGA为50G,PGA为10G。
设置内存参数后，并未做其它设置。重新启动数据库，并进行归档日志的恢复应用；此时的恢复速度已经有了较大提高。
经测算，恢复速度大约在每分钟8G归档日志。
2.2 设置应用归档日志并发数量再次提高恢复速度
归档日志应用进程的数量，默认是取决于初始化参数CPU_COUNT中的CPU数量，默认启动的日志应用进程的数量与CPU数量相同。
因此，对于归档日志应用进程的数量，也就有两种方式来控制：
1.在恢复过程中人为临时修改cpu_count的值
2.在恢复命令中显式指定并行度
cpu_count默认是在启动时根据主机的CPU数量生成，因此本次不显式指定此参数。通过在命令中指定并行度的方式限制恢复的并行度。
分别通过指定并行度为16、8、4，对不同并行度时的恢复速度进行了对比；在并行为16与8时恢复速度基本一致，达到了每分钟恢复10G左右归档日志。
三、相关知识点与总结
3.1 问题总结
在大部分环境中，在创建数据库或者异机恢复时，一般都会对于数据库实例的内存根据经验值进行合理设置；因此很少出现RECOVER时非常慢之类的问题。
从而对于并行恢复是快或者慢的问题，也是很少被注意到。
在此次的故障解决中，通过v$session查看recover时的event,通过10046对恢复过程进行trace，通过这些分析步骤可以确定到问题的原因。通过分步修改内存及使用不同的recover并行度进行测试，可以找到合理的并行参数，来最终得到最优的恢复性能。
3.2 关于恢复的并行数量相关参数：
大事务或死事务的回滚进程数可以通过参数fast_start_parallel_rollback来设置是否启用并行恢复。
此参数有3个值:
FALSE –>Parallel rollback is disabled 即FALSE时关闭并行回滚，使用SMON的串行恢复；
LOW –>Limits the maximum degree of parallelism to 2 * CPU_COUNT LOW是11GR2默认值，
HIGH –>Limits the maximum degree of parallelism to 4 * CPU_COUNT
对应的回滚进程是：ora_p025_orcl ora_p022_orcl 这种都是后台启动的并行回滚的进程。
并行回滚的并发度如果参数是high或low，4倍或2倍的cpu数，也会受到另外一些参数的影响，如PARALLEL_MAX_SERVERS（主要决定于CPU_COUNT, PARALLEL_THREADS_PER_CPU, PGA_AGGREGATE_TARGET），会对最大的并发度限制。
RECOVERY_PARALLELISM 此参数只对instanceor crash recovery有效； Media recovery 不受此参数影响。
而经过测试，recover恢复时的并行进程数量，与以上参数值关系不大。
参考官方文档，对于recover恢复时的并行进程数量，如果在recover命令中进行指定，则按照指定并行度进行；如果未指定，则默认按照cpu_count值，生成相应数量的并行恢复进程。
http://docs.oracle.com/cd/E11882_01/backup.112/e10643/rcmsynta2001.htm#RCMRF140
PARALLEL
Specifies parallel recovery (default).
By default, the database uses parallel media recovery to improve performance
of the roll forward phase of media recovery. To override the default behavior of
performing parallel recovery, use the RECOVER with the NOPARALLEL option,
or RECOVER PARALLEL 0.
In parallel media recovery, the database uses a “division of labor” approach to
allocate different processes to different data blocks while rolling forward,
thereby making the operation more efficient. The number of processes is
derived from the CPU_COUNT initialization parameter, which by default equals
the number of CPUs on the system. For example, if parallel recovery is
performed on a system where CPU_COUNT is 4, and only one datafile is
recovered, then four spawned processes read blocks from the datafile and apply
redo.
Typically, recovery is I/O-bound on reads from and writes to data blocks.
Parallelism at the block level may only help recovery performance if it increases
total I/Os, for example, by bypassing operating system restrictions on
asynchronous I/Os. Systems with efficient asynchronous I/O see little benefit
from parallel media recovery.
3.3 对RMAN中命令进行10046跟踪
在RMAN备份恢复中的“异常”问题，也可以通过在RMAN窗口中执行10046命令来进行跟踪：
RMAN> sql “alter session set tracefile_identifier=”rman_10046””;
RMAN> sql “alter session set events ”10046 trace name context forever,level 12””;
3.4 参考文档
RMAN Backup Performance (文档 ID 360443.1)
RMAN Restore Performance (文档 ID 740911.1)
Advise On How To Improve Rman Performance (文档 ID 579158.1)
如何收集用来诊断性能问题的10046 Trace(SQL_TRACE) (文档 ID 1523462.1)
Interpreting Raw SQL_TRACE output (文档 ID 39817.1)
TKProf Interpretation (9i and above) (文档 ID 760786.1)
