Chinaunix首页 | 论坛 | 博客

沧海拾贝brjl.blog.chinaunix.net

首页　| 　博文目录　| 　关于我

brjl

  • 博客访问： 3693590
  • 博文数量： 715
  • 博客积分： 1860
  • 博客等级： 上尉
  • 技术积分： 7745
  • 用 户 组： 普通用户
  • 注册时间： 2008-04-07 08:51
个人简介

偶尔有空上来看看

文章分类

全部博文（715）

文章存档

2023年（75）

2022年（134）

2021年（238）

2020年（115）

2019年（11）

2018年（9）

2017年（9）

2016年（17）

2015年（7）

2014年（4）

2013年（1）

2012年（11）

2011年（27）

2010年（35）

2009年（11）

2008年（11）

我的朋友
最近访客
推荐博文
相关博文
ADR OR AHM operation error err_code=48132 ORA-48170

分类： Oracle

2021-11-12 11:31:38

alert.log中发现告警：
  1. Thread 1 advanced to log sequence 7943 (LGWR switch), current SCN: 987528252
  2.   Current log# 8 seq# 7943 mem# 0: +DATADG/ORCL/ONLINELOG/group_8.275.1069865339
  3.   Current log# 8 seq# 7943 mem# 1: +ARCHDG/ORCL/ONLINELOG/group_8.878.1069865339
  4. NET (PID:115300): Archived Log entry 28662 added for T-1.S-7942 ID 0x5eda13c5 LAD:1
  5. 2021-11-12 10:02:27.843000 +08:00
  6. NET (PID:115300): Archived Log entry 28664 added for T-2.S-7917 ID 0x5eda13c5 LAD:1
  7. 2021-11-12 10:04:07.382000 +08:00
  8. Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_ora_115326.trc:
  9. ORA-48132: requested file lock is busy, [HM_RUN] [/u01/app/oracle/diag/rdbms/orcl/orcl1/lck/AM_1618_3044626670.lck]
  10. ORA-48170: unable to lock file - already in use
  11. Linux-x86_64 Error: 11: Resource temporarily unavailable
  12. Additional information: 8
  13. Additional information: 275271
  14. 2021-11-12 10:06:01.920000 +08:00
  15. Errors in file /u01/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_ora_115326.trc:
  16. ORA-48132: requested file lock is busy, [HM_RUN] [/u01/app/oracle/diag/rdbms/orcl/orcl1/lck/AM_1618_3044626670.lck]
  17. ORA-48170: unable to lock file - already in use
  18. Linux-x86_64 Error: 11: Resource temporarily unavailable
  19. Additional information: 8
  20. Additional information: 275271
  21. 2021-11-12 10:06:03.538000 +08:00
  22. Control autobackup written to SBT_TAPE device
  23. comment 'API Version 2.0,MMS Version 11.0.0.80'
  24. media 'V_98393_10103970'
  25. handle 'c-1578961383-20211112-08'
  26. 2021-11-12 10:22:34.105000 +08:00
trc文件内容：
  1. Trace file /u01/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_ora_115326.trc
  2. Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
  3. Version 19.9.0.0.0
  4. Build label: RDBMS_19.9.0.0.0DBRU_LINUX.X64_200930
  5. ORACLE_HOME: /u01/app/oracle/product/19.3.0/db_1
  6. System name:    Linux
  7. Node name:    db1
  8. Release:    3.10.0-957.el7.x86_64
  9. Version:    #1 SMP Thu Oct 4 20:48:51 UTC 2018
  10. Machine:    x86_64
  11. Instance name: orcl1
  12. Redo thread mounted by this instance: 1
  13. Oracle process number: 240
  14. Unix process pid: 115326, image: oracle@db1


  17. *** 2021-11-12T10:04:07.381963+08:00
  18. *** SESSION ID:(6611.53968) 2021-11-12T10:04:07.382020+08:00
  19. *** CLIENT ID:() 2021-11-12T10:04:07.382033+08:00
  20. *** SERVICE NAME:(orcl) 2021-11-12T10:04:07.382044+08:00
  21. *** MODULE NAME:(backup archivelog) 2021-11-12T10:04:07.382055+08:00
  22. *** ACTION NAME:(0000019 STARTED10) 2021-11-12T10:04:07.382066+08:00
  23. *** CLIENT DRIVER:() 2021-11-12T10:04:07.382076+08:00
  24.  
  25. ADR or AMH operation error:; err_code=48132, "dbkh_create_pseudo_run_ctx-1"=dbkh_create_pseudo_run_ctx-1
  26. at 0x7fff137b6b40 placed krbb.c@24611
  27. ORA-48132: requested file lock is busy, [HM_RUN] [/u01/app/oracle/diag/rdbms/orcl/orcl1/lck/AM_1618_3044626670.lck]
  28. ORA-48170: unable to lock file - already in use
  29. Linux-x86_64 Error: 11: Resource temporarily unavailable
  30. Additional information: 8
  31. Additional information: 275271

  33. *** 2021-11-12T10:06:01.920478+08:00
  34. *** ACTION NAME:(0000031 STARTED111) 2021-11-12T10:06:01.920554+08:00
  35.  
  36. ADR or AMH operation error:; err_code=48132, "dbkh_create_pseudo_run_ctx-1"=dbkh_create_pseudo_run_ctx-1
  37. at 0x7fff137b4b00 placed krbb.c@24611
  38. ORA-48132: requested file lock is busy, [HM_RUN] [/u01/app/oracle/diag/rdbms/orcl/orcl1/lck/AM_1618_3044626670.lck]
  39. ORA-48170: unable to lock file - already in use
  40. Linux-x86_64 Error: 11: Resource temporarily unavailable
  41. Additional information: 8
  42. Additional information: 275271
lck文件为空
  1. -rw-r----- 1 oracle asmadmin 0 Sep 15 2020 AM_1502621355_3638225870.lck
  2. -rw-r----- 1 oracle asmadmin 0 Sep 15 2020 AM_1432227889_1110943450.lck
  3. -rw-r----- 1 oracle asmadmin 0 Sep 15 2020 AM_3222012286_854140907.lck
  4. -rw-r----- 1 oracle asmadmin 0 Sep 15 2020 AM_2133151281_4062580841.lck
  5. -rw-r----- 1 oracle asmadmin 0 Sep 15 2020 AM_3293841721_1014909846.lck
  6. -rw-r----- 1 oracle asmadmin 0 Sep 15 2020 AM_58170159_2309433480.lck
  7. -rw-r----- 1 oracle asmadmin 0 Sep 15 2020 AM_3293835190_3462375459.lck
  8. -rw-r----- 1 oracle asmadmin 0 Sep 15 2020 AM_1256574238_2295251304.lck
  9. -rw-r----- 1 oracle asmadmin 0 Sep 15 2020 AM_1317892465_764739657.lck


  12. $ cat /etc/re*se
  13. Red Hat Enterprise Linux Server release 7.6 (Maipo)
  14. $ sqlplus -v

  16. SQL*Plus: Release 19.0.0.0.0 - Production
  17. Version 19.9.0.0.0

  19. $ opatch lspatches
  20. 31772784;OCW RELEASE UPDATE 19.9.0.0.0 (31772784)
  21. 31668882;OJVM RELEASE UPDATE: 19.9.0.0.201020 (31668882)
  22. 31771877;Database Release Update : 19.9.0.0.201020 (31771877)
通过比对发现，每次都提示 AM_1618_3044626670.lck 这个文件无法锁定。这个文件在其他的环境中也有，应该是安装软件时生成的。

  1. 设置跟踪
  2. strace -Tttfv -s 8192 -o /tmp/stace.out rman target /
  3. 执行 backup current controlfile; 进行测试
  5. tail -f stace.out |grep AM_1618_3044626670.lck

  7. 5986 09:03:55.637519 open("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", O_RDWR|O_CREAT, 0660) = 8 <0.000034>
  8. 5986 09:03:55.637595 chown("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", -1, 1001) = 0 <0.000312>
  9. 5986 09:03:55.637960 stat("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", {st_dev=makedev(253, 0), st_ino=1644167245, st_mode=S_IFREG|0640, st_nlink=1, st_uid=1001, st_gid=1001, st_blksize=4096, st_blocks=0, st_size=0, st_atime=2021/11/16-09:02:20.216553937, st_mtime=2021/11/15-14:17:43.345324599, st_ctime=2021/11/16-09:03:55.636559726}) = 0 <0.000021>
  10. 5986 09:03:55.638044 chmod("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", 0640) = 0 <0.000042>
  11. 5986 09:03:57.851216 open("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", O_RDWR|O_CREAT, 0660) = 8 <0.000029>
  12. 5986 09:03:57.851289 chown("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", -1, 1001) = 0 <0.000042>
  13. 5986 09:03:57.851422 stat("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", {st_dev=makedev(253, 0), st_ino=1644167245, st_mode=S_IFREG|0640, st_nlink=1, st_uid=1001, st_gid=1001, st_blksize=4096, st_blocks=0, st_size=0, st_atime=2021/11/16-09:02:20.216553937, st_mtime=2021/11/15-14:17:43.345324599, st_ctime=2021/11/16-09:03:57.850559860}) = 0 <0.000020>
  14. 5986 09:03:57.851513 chmod("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", 0640) = 0 <0.000027>
  15. 对这个文件又是打开、又是修改属主、又是看状态

  17. strace tail -f AM_1618_3044626670.lck 同时跟踪这个lck文件可以看到备份期间至少5次读取
  18. read(4, "\1\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0", 39) = 16
  19. read(4, "\1\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0", 39) = 16
  20. read(4, "\1\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0", 39) = 16
  21. read(4, "\1\0\0\0\4\0\0\0\0\0\0\0\0\0\0\0", 39) = 16
  22. read(4,
 MOS提示尝试对AM_1618_3044626670.lck改名这样的回避方法应该不管用，RMAN备份时会自动生成一个同名新文件。

 解决方法是设置 alter system set event='logon trace name krb_options level 20' scope=spfile;重启实例
 原理：RMAN在备份过程中不再往ADR诊断信息里面追加写入信息，对RMAN的操作没有影响。

  2. 再深入看一看

  4. SQL> oradebug doc component krb

  6.   KRB Kernel Backup Restore (krb)
  7.     KRB_THREAD KRBBPC Thread Switches ((null))
  8.     KRB_IO KRB I/O ((null))
  9.     KRB_INCR KRB Incremental Restore ((null))
  10.     KRB_PERF KRB Performance Tracing ((null))
  11.     KRB_BPOUTPUT Detailed Backup Piece Output ((null))
  12.     KRB_BPVAL Detailed Block List During Restore Validate ((null))
  13.     KRB_FLWRES Details on Restore Flow ((null))
  14.     KRB_FLWCPY Details on krbydd Flow ((null))
  15.     KRB_FLWBCK Details on Backup Flow ((null))
  16.     KRB_FLWUSAGE RMAN Feature Usage ((null))
  17.     KRB_OPTIM Unused Space Compression ((null))
  18.     
  19. col PROGRAM for a30
  20. col module for a30
  21. select sid,paddr,program,module from v$session where program like 'rman%';
  22. select spid from v$process where addr in (select paddr from v$session where program like 'rman%');
  23. 9015
  24. 9080
  25. 9082

  27. oradebug setospid 9015
  28. oradebug dump krb_options 16
  29. oradebug tracefile_name

  31. ***第一个rman进程**********
  32. *** 2021-11-16T09:35:10.447846+08:00
  33. Received ORADEBUG command (#5) 'dump krb_options 16' from process '9492'
  34. 2021-11-16 09:35:10.449*:KRB:krb.c@1195:krbtpv(): Current KRB flags set for session
  35. 2021-11-16 09:35:10.450*:KRB:krb.c@1197:krbtpv(): ==============================================

  37. 2021-11-16 09:35:10.450*:KRB:krb.c@1200:krbtpv(): krbcsi=0, krbcss=0, krbcsr=0, krbcso=0
  38. 2021-11-16 09:35:10.451*:KRB:krb.c@1202:krbtpv(): krbpfn=0, krbpfl=0x8000
  39. 2021-11-16 09:35:10.452*:KRB:krb.c@1205:krbtpv(): krbdsd=(nil), krbbxp=(nil), krbrxp=(nil), krbnas=0
  40. 2021-11-16 09:35:10.452*:KRB:krb.c@1207:krbtpv(): krbbsbct=0, krbovac=0
  41. 2021-11-16 09:35:10.453*:KRB:krb.c@1211:krbtpv(): krbubsphi=0, krbubsphr=0, krbubspbi=0, krbubspbr=0
  42. 2021-11-16 09:35:10.453*:KRB:krb.c@1214:krbtpv(): krbubbsbi=0, krbubbsbs=0, krbubfl=0x0
  43. 2021-11-16 09:35:10.454*:KRB:krb.c@1216:krbtpv(): ==============================================


  46. *** 2021-11-16T09:35:10.455314+08:00
  47. Finished processing ORADEBUG command (#5) 'dump krb_options 16'

  49. ***第二个rman进程**********

  51. Received ORADEBUG command (#1) 'dump krb_options 65536' from process '9771'
  52. 2021-11-16 09:39:38.901*:KRB:krb.c@1195:krbtpv(): Current KRB flags set for session
  53. 2021-11-16 09:39:38.902*:KRB:krb.c@1197:krbtpv(): ===============================================

  55. 2021-11-16 09:39:38.902*:KRB:krb.c@1200:krbtpv(): krbcsi=0, krbcss=0, krbcsr=0, krbcso=0
  56. 2021-11-16 09:39:38.902*:KRB:krb.c@1202:krbtpv(): krbpfn=0, krbpfl=0xff38
  57. 2021-11-16 09:39:38.903*:KRB:krb.c@1205:krbtpv(): krbdsd=(nil), krbbxp=(nil), krbrxp=(nil), krbnas=0
  58. 2021-11-16 09:39:38.903*:KRB:krb.c@1207:krbtpv(): krbbsbct=0, krbovac=0
  59. 2021-11-16 09:39:38.904*:KRB:krb.c@1211:krbtpv(): krbubsphi=0, krbubsphr=0, krbubspbi=0, krbubspbr=0
  60. 2021-11-16 09:39:38.904*:KRB:krb.c@1214:krbtpv(): krbubbsbi=0, krbubbsbs=0, krbubfl=0x0
  61. 2021-11-16 09:39:38.904*:KRB:krb.c@1216:krbtpv(): ==============================================


  64. *** 2021-11-16T09:39:38.905854+08:00
  65. Finished processing ORADEBUG command (#1) 'dump krb_options 65536'

  67. **第三个rman进程*************
  68. Received ORADEBUG command (#1) 'dump krb_options 4' from process '9889'
  69. 2021-11-16 09:40:44.797*:KRB:krb.c@1195:krbtpv(): Current KRB flags set for session
  70. 2021-11-16 09:40:44.798*:KRB:krb.c@1197:krbtpv(): ===============================================

  72. 2021-11-16 09:40:44.798*:KRB:krb.c@1200:krbtpv(): krbcsi=0, krbcss=0, krbcsr=0, krbcso=0
  73. 2021-11-16 09:40:44.798*:KRB:krb.c@1202:krbtpv(): krbpfn=0, krbpfl=0x8
  74. 2021-11-16 09:40:44.799*:KRB:krb.c@1205:krbtpv(): krbdsd=0x7f84d710fb68, krbbxp=(nil), krbrxp=(nil),
  75. krbnas=0
  76. 2021-11-16 09:40:44.799*:KRB:krb.c@1207:krbtpv(): krbbsbct=0, krbovac=0
  77. 2021-11-16 09:40:44.799*:KRB:krb.c@1211:krbtpv(): krbubsphi=0, krbubsphr=0, krbubspbi=0, krbubspbr=0
  78. 2021-11-16 09:40:44.799*:KRB:krb.c@1214:krbtpv(): krbubbsbi=0, krbubbsbs=0, krbubfl=0x0
  79. 2021-11-16 09:40:44.800*:KRB:krb.c@1216:krbtpv(): ================================================
  80. 暂时看不出来哪个选项与adr有关。

  1. 一些参考命令：

  3. 诊断
  4. run {
  5. sql "alter system set events ''logon trace name krb_options level 20''";
  6. allocate channel c1 type disk;
  7. backup check logical validate datafile 46;
  8. release channel c1;
  9. }

  11. 启用
  12. alter system set events 'logon trace name krb_options level 14';
  13. alter system set event='logon trace name krb_options level 20' scope=spfile;
  14. alter system set event='logon trace name krb_options level 24' scope=spfile;
  15. alter system set events 'logon trace name krb_options level 26';

  17. 禁用
  18. alter system set events 'logon trace name krb_options off';
  19. alter system set event='logon trace name krb_options off' scope=spfile;
参考：DOC ID 2565120.1

阅读(3789) | 评论(0) | 转发(0) |
0

上一篇：监控正在运行的rman过程

下一篇：oracle文件名中含有tab字符，如何改名？

给主人留下些什么吧！~~
关于我们 | 关于IT168 | 联系方式 | 广告合作 | 法律声明 | 免费注册

Copyright 2001-2010 ChinaUnix.net All Rights Reserved 北京皓辰网域网络信息技术有限公司. 版权所有

感谢所有关心和支持过ChinaUnix的朋友们

16024965号-6