RMAN备份时碰到ORA-48132 &ORA-48170且备份变慢案例

征象形貌：

环境：

操作系统：Red Hat Enterprise Linux release 8.10
数据库版本： Oracle 19.24.0.0.0 企业版
备份作业在执行RMAN备份时，告警日记中会出现ORA-48132 & ORA-48170错误，如下所示(数据库实例用xxx做了混淆)

1. 2025-02-12T11:10:11.070519+08:00
   
2. Errors in file /xxxdb/diag/rdbms/xxx/xxx/trace/xxx_ora_3430285.trc:
   
3. ORA-48132: requested file lock is busy, [HM_RUN] [/xxxdb/diag/rdbms/xxx/xxx/lck/AM_1618_3044626670.lck]
   
4. ORA-48170: unable to lock file - already in use
   
5. Linux-x86_64 Error: 11: Resource temporarily unavailable
   
6. Additional information: 8
   
7. Additional information: 2421413
   
8. 2025-02-12T11:11:50.186760+08:00
   
9. Errors in file /xxxdb/diag/rdbms/xxx/xxx/trace/xxx_ora_3430287.trc:
   
10. ORA-48132: requested file lock is busy, [HM_RUN] [/xxxdb/diag/rdbms/xxx/xxx/lck/AM_1618_3044626670.lck]
    
11. ORA-48170: unable to lock file - already in use
    
12. Linux-x86_64 Error: 11: Resource temporarily unavailable
    
13. Additional information: 8
    
14. Additional information: 2421413

复制代码

原因分析：

备份作业之前是完全正常的，而且没有做过设置与参数的变动，忽然间出现了如许的报错。研究了报错的trc文件后确定是RMAN备份时抛出的错误，另外，在分析研究过程中，我们发现假如备份的时候能够重现这个错误的话，就可以观察到有ADR file lock。假如错过了备份时间段，也可以通过AWR或ASH发现，如下截图所示:

另外，我还发现一个很希奇的标题，如下截图所示，最开始碰到这个标题的时间是是2025-02-02，在出现这个标题后，发现备份时间从15分钟多变成了50多分钟，而且每秒写出IO(OUTPUT_BYTES_PER_SEC_DISPLAY)也变小了，也就是说RMAN备份变慢了，如下所示：

1. CON_ID START_TIME          END_TIME            BACKUP_TYP   IN_GB IO_IN_RATE  OUT_GB IO_OUT_RAT ELAPSED_MIN OUTPUT_D
   
2. ------ ------------------- ------------------- ---------- ------- ---------- ------- ---------- ----------- --------
   
3.      1 2025-01-29 18:30:07 2025-01-29 18:45:54 DB FULL      588.6   636.47M    144.4   156.18M         15.8 DISK
   
4.      1 2025-01-30 18:30:07 2025-01-30 18:46:02 DB FULL      587.8   630.25M    143.8   154.17M         15.9 DISK
   
5.      1 2025-01-31 18:30:07 2025-01-31 18:45:54 DB FULL      587.8   635.63M    143.7   155.43M         15.8 DISK
   
6.      1 2025-02-01 18:30:07 2025-02-01 18:46:00 DB FULL      587.4   631.12M    142.9   153.52M         15.9 DISK
   
7.      1 2025-02-02 18:30:06 2025-02-02 19:21:39 DB FULL      582.1   192.73M    137.4    45.49M         51.6 DISK
   
8.      1 2025-02-03 18:30:07 2025-02-03 19:21:39 DB FULL      582.3   192.84M    137.4    45.51M         51.5 DISK
   
9.      1 2025-02-04 18:30:07 2025-02-04 19:21:39 DB FULL      582.2   192.80M    137.4    45.50M         51.5 DISK
   
10.      1 2025-02-05 18:30:07 2025-02-05 19:21:39 DB FULL      588.0   194.74M    140.7    46.59M         51.5 DISK
    
11.      1 2025-02-06 18:30:06 2025-02-06 19:21:38 DB FULL      586.4   194.22M    140.5    46.54M         51.5 DISK
    
12.      1 2025-02-07 18:30:07 2025-02-07 19:21:38 DB FULL      582.6   193.00M    136.7    45.30M         51.5 DISK
    
13.      1 2025-02-08 18:30:07 2025-02-08 19:21:39 DB FULL      583.4   193.21M    136.9    45.34M         51.5 DISK
    
14.      1 2025-02-09 18:30:07 2025-02-09 19:21:40 DB FULL      583.6   193.21M    137.3    45.45M         51.6 DISK
    
15.      1 2025-02-10 18:30:06 2025-02-10 19:21:40 DB FULL      583.7   193.17M    137.1    45.39M         51.6 DISK
    
16.      1 2025-02-11 18:30:07 2025-02-11 19:21:38 DB FULL      584.4   193.62M    137.2    45.46M         51.5 DISK
    
17.      1 2025-02-12 10:36:50 2025-02-12 11:20:23 DB FULL      590.2   231.30M    142.9    56.00M         43.6 DISK
    
18.      1 2025-02-12 11:21:35 2025-02-12 11:35:55 DB FULL      550.4   655.32M    103.1   122.71M         14.3 DISK
    
19. 
    
20. 16 rows selected

复制代码

解决这个标题是在2025-02-12日10点多，暂时解决后RMAN备份速度又恢复正常了。我搜索了Oracle官方文档，关于这个错误，其实官方文档Oracle Support上有详细文档ORA-48132 ORA-48170 When Running RMAN Backups (Doc ID 2904353.1)介绍，我们这边碰到的案例跟链接内容极其相似(但是还有点差别)，这里就不画蛇添足了，贴上具体内容如下所示
[code]APPLIES TO:

Oracle Database - Enterprise Edition - Version 11.2.0.4 and later
Information in this document applies to any platform.

SYMPTOMS

Alert log flooded with below errors while running the RMAN backup.
 
ADR or AMH operation error:; err_code=48132, "dbkh_create_pseudo_run_ctx-1"=dbkh_create_pseudo_run_ctx-1
at 0xffffffff7fff5870 placed krbb.c@25071
ORA-48132: requested file lock is busy, [HM_RUN] [/db01/app/oracle/diag/rdbms///lck/AM_1618_3044626670.lck]
ORA-48170: unable to lock file - already in use
SVR4 Error: 11: Resource temporarily unavailable
Additional information: 8
Additional information: 2701


'ADR file lock' wait event observed during the backup.
 
INST_ID     SID CH                            SEQ# EVENT                         STATE            SECS        
---------- ------- --------------------------- ------ ----------------------------  ---------- ----------
        1     262                               6114 SQL*Net message from client   WAITING            50
        1     467 rman channel=ORA_SBT_TAPE_1    898 ADR file lock                 WAITING             2 >>>>>>>>>>>>>>>>>>>>>>>>>
 
 
CHANGES
 
CAUSE
This symptom is being investigated by developer in Bug 10125939.
Bug 10125939 - GSFBDRA: RMAN VALIDATE HANG WAITING FOR 'ADR FILE LOCK' Closed as could not reproduce


SOLUTION
Choose the following workaround:

Solution 1:

Disable HM Monitor as below:

alter system set "_diag_hm_rc_enabled"=false scope=both;


Solution 2:

Enable krb trace , this might lead to more RMAN KRB traces to generate.

If RAC, Krb tracing needs to enabled on all nodes.

alter system set event='logon trace name krb_options level 20' scope=spfile;