Chinaunix首页 | 论坛 | 博客
  • 博客访问: 3494039
  • 博文数量: 738
  • 博客积分: 1860
  • 博客等级: 上尉
  • 技术积分: 7745
  • 用 户 组: 普通用户
  • 注册时间: 2008-04-07 08:51
个人简介

偶尔有空上来看看

文章分类

全部博文(738)

文章存档

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)

最近访客

分类: 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


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

  30. *** 2021-11-12T10:06:01.920478+08:00
  31. *** ACTION NAME:(0000031 STARTED111) 2021-11-12T10:06:01.920554+08:00
  32.  
  33. ADR or AMH operation error:; err_code=48132, "dbkh_create_pseudo_run_ctx-1"=dbkh_create_pseudo_run_ctx-1
  34. at 0x7fff137b4b00 placed krbb.c@24611
  35. ORA-48132: requested file lock is busy, [HM_RUN] [/u01/app/oracle/diag/rdbms/orcl/orcl1/lck/AM_1618_3044626670.lck]
  36. ORA-48170: unable to lock file - already in use
  37. Linux-x86_64 Error: 11: Resource temporarily unavailable
  38. Additional information: 8
  39. 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


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

  13. SQL*Plus: Release 19.0.0.0.0 - Production
  14. Version 19.9.0.0.0

  15. $ opatch lspatches
  16. 31772784;OCW RELEASE UPDATE 19.9.0.0.0 (31772784)
  17. 31668882;OJVM RELEASE UPDATE: 19.9.0.0.201020 (31668882)
  18. 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; 进行测试
  4. tail -f stace.out |grep AM_1618_3044626670.lck

  5. 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>
  6. 5986 09:03:55.637595 chown("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", -1, 1001) = 0 <0.000312>
  7. 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>
  8. 5986 09:03:55.638044 chmod("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", 0640) = 0 <0.000042>
  9. 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>
  10. 5986 09:03:57.851289 chown("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", -1, 1001) = 0 <0.000042>
  11. 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>
  12. 5986 09:03:57.851513 chmod("/u01/app/diag/rdbms/orcl/orcl/lck/AM_1618_3044626670.lck", 0640) = 0 <0.000027>
  13. 对这个文件又是打开、又是修改属主、又是看状态

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

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

  1. 再深入看一看

  2. SQL> oradebug doc component krb

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

  23. oradebug setospid 9015
  24. oradebug dump krb_options 16
  25. oradebug tracefile_name

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

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


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

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

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

  44. 2021-11-16 09:39:38.902*:KRB:krb.c@1200:krbtpv(): krbcsi=0, krbcss=0, krbcsr=0, krbcso=0
  45. 2021-11-16 09:39:38.902*:KRB:krb.c@1202:krbtpv(): krbpfn=0, krbpfl=0xff38
  46. 2021-11-16 09:39:38.903*:KRB:krb.c@1205:krbtpv(): krbdsd=(nil), krbbxp=(nil), krbrxp=(nil), krbnas=0
  47. 2021-11-16 09:39:38.903*:KRB:krb.c@1207:krbtpv(): krbbsbct=0, krbovac=0
  48. 2021-11-16 09:39:38.904*:KRB:krb.c@1211:krbtpv(): krbubsphi=0, krbubsphr=0, krbubspbi=0, krbubspbr=0
  49. 2021-11-16 09:39:38.904*:KRB:krb.c@1214:krbtpv(): krbubbsbi=0, krbubbsbs=0, krbubfl=0x0
  50. 2021-11-16 09:39:38.904*:KRB:krb.c@1216:krbtpv(): ==============================================


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

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

  57. 2021-11-16 09:40:44.798*:KRB:krb.c@1200:krbtpv(): krbcsi=0, krbcss=0, krbcsr=0, krbcso=0
  58. 2021-11-16 09:40:44.798*:KRB:krb.c@1202:krbtpv(): krbpfn=0, krbpfl=0x8
  59. 2021-11-16 09:40:44.799*:KRB:krb.c@1205:krbtpv(): krbdsd=0x7f84d710fb68, krbbxp=(nil), krbrxp=(nil),
  60. krbnas=0
  61. 2021-11-16 09:40:44.799*:KRB:krb.c@1207:krbtpv(): krbbsbct=0, krbovac=0
  62. 2021-11-16 09:40:44.799*:KRB:krb.c@1211:krbtpv(): krbubsphi=0, krbubsphr=0, krbubspbi=0, krbubspbr=0
  63. 2021-11-16 09:40:44.799*:KRB:krb.c@1214:krbtpv(): krbubbsbi=0, krbubbsbs=0, krbubfl=0x0
  64. 2021-11-16 09:40:44.800*:KRB:krb.c@1216:krbtpv(): ================================================
  65. 暂时看不出来哪个选项与adr有关。

  1. 一些参考命令:

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

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

  14. 禁用
  15. alter system set events 'logon trace name krb_options off';
  16. alter system set event='logon trace name krb_options off' scope=spfile;
参考:DOC ID 2565120.1

阅读(3010) | 评论(0) | 转发(0) |
给主人留下些什么吧!~~