2020-07-07

项目背景

某银行项目所有Oracle数据库从11G整体迁移升级至19C，RAC架构，AIX平台，针对所有新版本数据库部署了13C EMCC,迁移上线后特殊维护期。

故障现象

故障现象是，Oracle EM上多次出现的metric为Disk file operations IO等待事件的average elapsed time超过阈值的告警

image.png

排查过程

结合告警时间段和具体等待事件类型，排查出引起该等待事件和一条EM代理自身执行的一条SQL语句似乎有点关系，语句如下：

SELECT TO_CHAR(current_timestamp AT TIME ZONE 'GMT', 'YYYY-MM-DD HH24:MI:SS TZD') AS curr_timestamp, 
  SUM(failed_count) AS failed_count , 
  TO_CHAR(MIN(first_occur_time), 'yyyy-mm-dd hh24:mi:ss') AS first_occur_time, 
  TO_CHAR(MAX(last_occur_time), 'yyyy-mm-dd hh24:mi:ss') AS last_occur_time 
FROM (
  SELECT COUNT(db_user) AS failed_count, 
    MIN(extended_timestamp) AS first_occur_time,
    MAX(extended_timestamp) AS last_occur_time 
  FROM sys.dba_common_audit_trail 
  WHERE action BETWEEN 100 AND 102 
    AND returncode != 0 
    AND STATEMENT_TYPE = 'LOGON' 
    AND extended_timestamp >= current_timestamp - TO_DSINTERVAL('0 0:30:00') 
  UNION 
  SELECT COUNT(DBUSERNAME) AS failed_count, 
    MIN(event_timestamp) AS first_occur_time, 
    MAX(event_timestamp) AS last_occur_time 
  FROM unified_audit_trail 
  WHERE ACTION_NAME='LOGON' and return_code <> 0 
    AND event_timestamp >= current_timestamp - TO_DSINTERVAL('0 0:30:00'))

对SQL搜集该时段AWR报告后发现该SQL执行时间为171s左右，但手动执行时，执行时间为1s左右，执行计划和AWR报告中的执行计划进行了对比，无差异，该SQL查询的表均为审计相关的表，检查审计功能状态为关闭，这些表也都不大，大多数是没有数据的，因此初步判断语句本身是正常的，怀疑可能是存储链路不稳定导致，联系存储工程师对存储进行了全面排查，但排查结果为：故障期间存储无任何异常。

image.png

随后几天内又出现了2次告警，发现每次都和这条SQL相关。因此怀疑是这条SQL本身的性能问题，而非硬件问题，因此对这条SQL的执行计划进行了进一步分析，对这条SQL涉及的Oracle基表进行了分析，最终通过执行计划定位到了X$XML_AUDIT_TRAIL这张基表，对这张表单独进行查询时，发现该表中没有数据，但执行计划中显示该表的扫描方式为PX并行扫描，并行扫描一般是针对数据量较大的表，而出现在这里让人有点琢磨不透。

image.png

而且，在对这张表count(*)时，并非瞬间完成，而是等待了约1s左右，虽说不算太慢，但对一张空表来说，显然是不合理的，隐隐感觉到这张基表后面潜藏着一些不为人知的秘密， 后来从官方文档中对这张表的功能进行了了解，官档对这个表的描述为:

V$XML_AUDIT_TRAIL shows standard, fine-grained, SYS, and mandatory audit records written in XML format files.

根据这段描述，我的理解是，这张表并非常规意义的表，而是Oracle用于访问审计文件的接口表，查询该表实际上可能会访问审计相关的操作系统文件。接下来，使用truss工具对SQLPLUS会话进行了跟踪验证，验证结果是：
对X$XML_AUDIT_TRAIL基表的查询的确会对adump目录中的文件进行打开、读取和关闭动作。

SYS@mccs1>c/9/8
  1* select  count(8) from X$XML_AUDIT_TRAIL
SYS@mccs1>/

  COUNT(8)
----------
         0

Elapsed: 00:00:08.20
SYS@mccs1>

实际在对会话跟踪时，该查询耗时又变成了8s左右，足以见得，对该表的查询操作，性能是很不稳定的。

跟踪上述SQLPLUS的操作如下：
truss -d -o /tmp/truss_xml.log -p 29360546 ；
其中trace log信息如下：

Tue Jun 16 13:06:51 2020
0.0000:        kread(7, "\0\0\01506\0\0\0\0\00305".., 8208) (sleeping...)
0.0000:        kread(7, "\0\0019006\0\0\0\0\011 i".., 8208) = 400
7.3600:        _poll(0x072000000B4E1518, 3, 0)  = 0
7.3611:        statx("/usr/share/lib/zoneinfo/Asia/Shanghai", 0x0FFFFFFFFFFF68F0, 176, 0) = 0
7.3613:        statx("/u01/app/oracle/admin/mccs/adump/adx_mccs1_ora_29360546.txt", 0x0FFFFFFFFFFF3AD0, 176, 010) Err#2  ENOENT
7.3615:        statx("/u01/app/oracle/admin/mccs/adump/adx_mccs1_ora_29360546.txt", 0x0FFFFFFFFFFF3A10, 176, 010) Err#2  ENOENT
7.3616:        statx("/u01/app/oracle/admin/mccs/adump/adx_mccs1_ora_29360546.txt", 0x0FFFFFFFFFFF3440, 176, 010) Err#2  ENOENT
7.3618:        statx("/u01/app/oracle/admin/mccs/adump/", 0x0FFFFFFFFFFF2098, 176, 010) = 0
7.3620:        statfs("/u01/app/oracle/admin/mccs/adump/adx_mccs1_ora_29360546.txt", 0x0FFFFFFFFFFF1F10) Err#2  ENOENT
7.3622:        statfs("/u01/app/oracle/admin/mccs/adump/", 0x0FFFFFFFFFFF1F10) = 0
7.3623:        mntctl(2, 512, "")               = 0
7.3625:        mntctl(2, 1888, "")              = 13
7.3627:        kopen("/etc/vfs", O_RDONLY)      = 11
7.3628:        kioctl(11, 22528, 0x0000000000000000, 0x0000000000000000) Err#25 ENOTTY
7.3630:        kioctl(11, 22528, 0x0000000000000000, 0x0000000000000000) Err#25 ENOTTY
7.3631:        kread(11, " #   @ ( # ) 7 7\t 1 . 3".., 4096) = 1786
7.3633:        close(11)                        = 0
7.3634:        kopen("/u01/app/oracle/admin/mccs/adump/adx_mccs1_ora_29360546.txt", O_WRONLY|O_CREAT|O_TRUNC|O_LARGEFILE, S_IRUSR|S_IWUSR|S_IRGRP|S_IWGRP) = 11
7.3641:        fstatx(11, 0x0FFFFFFFFFFF1F10, 176, 010) = 0
7.3642:        close(11)                        = 0
7.3644:        statx("/u01/app/oracle/admin/mccs/adump/adx_mccs1_ora_29360546.txt", 0x0FFFFFFFFFFF3580, 176, 010) = 0
7.3646:        statx("/u01/app/oracle/admin/mccs/adump/", 0x0FFFFFFFFFFF21D8, 176, 010) = 0
7.3647:        statfs("/u01/app/oracle/admin/mccs/adump/adx_mccs1_ora_29360546.txt", 0x0FFFFFFFFFFF2050) = 0
7.3649:        mntctl(2, 512, "")               = 0
7.3650:        mntctl(2, 1888, "")              = 13
7.3652:        kopen("/etc/vfs", O_RDONLY)      = 11
7.3654:        kioctl(11, 22528, 0x0000000000000000, 0x0000000000000000) Err#25 ENOTTY
......
7.4088:        close(12)                        = 0
7.4089:        chdir("adump/")                  = 0
7.4090:        statx(".", 0x0FFFFFFFFFFED580, 176, 010) = 0
7.4092:        kopen(".", O_RDONLY|O_LARGEFILE) = 12
7.4093:        getdirent64(12, 0x0000000121328E70, 4096) = 4056
7.4095:        klseek(12, 0, 0, 0x0FFFFFFFFFFED480) = 0
7.4096:        kfcntl(12, F_GETFD, 0x0000000120C4FFD8) = 0
7.4098:        kfcntl(12, F_SETFD, 0x0000000000000001) = 0
7.4099:        getdirent64(12, 0x0000000121328E70, 4096) = 4056
......
15.5541:        getdirent64(12, 0x0000000121328E70, 4096) = 4032
15.5542:        getdirent64(12, 0x0000000121328E70, 4096) = 4032
15.5544:        getdirent64(12, 0x0000000121328E70, 4096) = 4032
15.5546:        getdirent64(12, 0x0000000121328E70, 4096) = 4032
15.5547:        getdirent64(12, 0x0000000121328E70, 4096) = 4032
15.5549:        getdirent64(12, 0x0000000121328E70, 4096) = 4032
15.5551:        getdirent64(12, 0x0000000121328E70, 4096) = 4032
15.5552:        getdirent64(12, 0x0000000121328E70, 4096) = 936
15.5554:        getdirent64(12, 0x0000000121328E70, 4096) = 0
15.5555:        close(12)                       = 0
15.5557:        chdir("/u01/app/oracle/admin/mccs") = 0
15.5559:        chdir("/u01/app/oracle/admin")  = 0
15.5560:        chdir("/u01/app/oracle")        = 0
15.5562:        chdir("/u01/app")               = 0
15.5563:        chdir("/u01")                   = 0
15.5564:        chdir("/")                      = 0
15.5566:        chdir("/u01/app/oracle/product/19c/dbhome_1/dbs") = 0
15.5568:        close(11)                       = 0
15.5571:        _poll(0x072000000B4E1518, 3, 0) = 0
15.5572:        statx("/u01/app/oracle/admin/mccs/adump/adx_mccs1_ora_29360546.txt", 0x0FFFFFFFFFFF44A0, 176, 011) = 0
15.5574:        unlink("/u01/app/oracle/admin/mccs/adump/adx_mccs1_ora_29360546.txt") = 0
15.5586:        kwrite(10, "\0\0018506\0\0\0\0\010\0".., 389) = 389
15.5588:        kread(7, "\0\0\01506\0\0\0\0\00305".., 8208) = 21
15.5589:        kwrite(10, "\0\0\0 0\0\0\0\004\0".., 180) = 180
17.5592:        kread(7, "\0\0\01506\0\0\0\0\00305".., 8208) (sleeping...)

然后查看审计目录adump中发现，目录中竟然有200多万个审计文件，这套库为RAC架构，另一个节点上，这个目录只有8000多个审计文件，而且这个库从测试安装到上线，生命周期才不到一年，审计功能也是关闭状态，这个节点出现这么多审计文件令人震惊。抽查了几个最新生成的审计文件，都是对以sysdba权限登录数据库操作的审计记录，并且登录频率很高，每天大概1万左右，平均大概每8s就会有产生一个SYSDBA权限登录数据库的审计日志（SYSDBA权限登录数据库属于强制审计范围，即使关闭审计功能，也是会生成审计文件）。因此，怀疑有可能是有什么程序或脚本不断地在连接数据库然后完成某种简短操作后推出，并且肯定是用操作系统的oracle用户连接，于是马上查看了crontab中的内容，发现的确是有一个每秒执行的脚本，脚本中的内容是用RMAN登录数据库后执行crosscheck命令验证归档状态，然后执行delete expired archivelog all删除过期的归档。终于真相大白，原来使用RMAN登录数据库也是会在adump目录中生成审计日志，并且等同于sysdba权限登录数据库。至此，终于发现了这几次Disk file operations IO等待时间过长的罪魁祸首，竟然是因为一个频繁运行的RMAN验证过期归档的登录脚本引起的。

解决方案

至于解决这个问题的方法就很简单了，停掉了这个意义不大的RMAN操作脚本定时任务，然后把adump中大量的审计日志全部清理掉了，为了彻底杜绝adump中文件过多，还部署了shell脚本对adump目录下的文件进行定时清理，仅保留了最近1个月内的审计日志。

后来对其他数据库也进行了排查，某些其他系统的Oracle服务器上也都发现了同样的CRONTAB的脚本，都一一做了处理。