深入分析Oracle数据库日志文件（1）

作为Oracle DBA 我们有时候需要追踪数据误删除或用户的恶意 *** 作情况 此时我们不仅需要查出执行这些 *** 作的数据库账号 还需要知道 *** 作是由哪台客户端（IP地址等）发出的 针对这些问题 一个最有效实用而又低成本的方法就是分析Oracle数据库的日志文件 本文将就Oracle日志分析技术做深入探讨 一 如何分析即LogMiner解释 从目前来看 分析Oracle日志的唯一方法就是使用Oracle公司提供的LogMiner来进行 Oracle数据库的所有更改都记录在日志中 但是原始的日志信息我们根本无法看懂 而LogMiner就是让我们看懂日志信息的工具 从这一点上看 它和tkprof差不多 一个是用来分析日志信息 一个则是格式化跟踪文件 通过对日志的分析我们可以实现下面的目的 查明数据库的逻辑更改 侦察并更正用户的误 *** 作 执行事后审计 执行变化分析 不仅如此 日志中记录的信息还包括 数据库的更改历史 更改类型（INSERT UPDATE DELETE DDL等） 更改对应的SCN号 以及执行这些 *** 作的用户信息等 LogMiner在分析日志时 将重构等价的SQL语句和UNDO语句（分别记录在V$LOGMNR_CONTENTS视图的SQL_REDO和SQL_UNDO中） 这里需要注意的是等价语句 而并非原始SQL语句 例如 我们最初执行的是 delete a where c <>cyx 而LogMiner重构的是等价的 条DELETE语句 所以我们应该意识到V$LOGMNR_CONTENTS视图中显示的并非是原版的现实 从数据库角度来讲这是很容易理解的 它记录的是元 *** 作 因为同样是 delete a where c <>cyx 语句 在不同的环境中 实际删除的记录数可能各不相同 因此记录这样的语句实际上并没有什么实际意义 LogMiner重构的是在实际情况下转化成元 *** 作的多个单条语句 另外由于Oracle重做日志中记录的并非原始的对象（如表以及其中的列）名称 而只是它们在Oracle数据库中的内部编号（对于表来说是它们在数据库中的对象ID 而对于表中的列来说 对应的则是该列在表中的排列序号 COL COL 等） 因此为了使LogMiner重构出的SQL语句易于识别 我们需要将这些编号转化成相应的名称 这就需要用到数据字典（也就说LogMiner本身是可以不用数据字典的 详见下面的分析过程） LogMiner利用DBMS_LOGMNR_D BUILD()过程来提取数据字典信息 LogMiner包含两个PL/SQL包和几个视图 dbms_logmnr_d包 这个包只包括一个用于提取数据字典信息的过程 即dbms_logmnr_d build()过程 dbms_logmnr包 它有三个过程 add_logfile(name varchar options number) 用来添加/删除用于分析的日志文件 start_logmnr(start_scn number end_scn number start_time number end_time number dictfilename varchar options number) 用来开启日志分析 同时确定分析的时间/SCN窗口以及确认是否使用提取出来的数据字典信息 end_logmnr() 用来终止分析会话 它将回收LogMiner所占用的内存 与LogMiner相关的数据字典 v$logmnr_dictionary LogMiner可能使用的数据字典信息 因logmnr可以有多个字典文件 该视图用于显示这方面信息 v$logmnr_parameters 当前LogMiner所设定的参数信息 v$logmnr_logs 当前用于分析的日志列表 v$logmnr_contents 日志分析结果 二 Oracle i LogMiner的增强支持更多数据/存储类型 链接/迁移行 CLUSTER表 *** 作 DIRECT PATH插入以及DDL *** 作 在V$LOGMNR_CONTENTS的SQL_REDO中可以看到DDL *** 作的原句（CREATE USER除外 其中的密码将以加密的形式出现 而不是原始密码） 如果TX_AUDITING初始化参数设为TRUE 则所有 *** 作的数据库账号将被记录 提取和使用数据字典的选项 现在数据字典不仅可以提取到一个外部文件中 还可以直接提取到重做日志流中 它在日志流中提供了 *** 作当时的数据字典快照 这样就可以实现离线分析 允许对DML *** 作按事务进行分组 可以在START_LOGMNR()中设置MITTED_DATA_ONLY选项 实现对DML *** 作的分组 这样将按SCN的顺序返回已经提交的事务 支持SCHEMA的变化 在数据库打开的状态下 如果使用了LogMiner的DDL_DICT_TRACKING选项 Oracle i的LogMiner将自动对比最初的日志流和当前系统的数据字典 并返回正确的DDL语句 并且会自动侦察并标记当前数据字典和最初日志流之间的差别 这样即使最初日志流中所涉及的表已经被更改或者根本已经不存在 LogMiner同样会返回正确的DDL语句 在日志中记录更多列信息的能力 例如对于UPDATE *** 作不仅会记录被更新行的情况 还可以捕捉更多前影信息 支持基于数值的查询 Oracle i LogMiner在支持原有基于元数据（ *** 作 对象等）查询的基础上 开始支持基于实际涉及到的数据的查询 例如涉及一个工资表 现在我们可以很容易地查出员工工资由 变成 的原始更新语句 而在之前我们只能选出所有的更新语句 三 Oracle i/ i的日志分析过程 LogMiner只要在实例起来的情况下都可以运行 LogMiner使用一个字典文件来实现Oracle内部对象名称的转换 如果没有这个字典文件 则直接显示内部对象编号 例如我们执行下面的语句 delete from C A where C = gototop and ROWID = AAABg AAFAAABQaAAH 如果没有字典文件 LogMiner分析出来的结果将是 delete from UNKNOWN OBJ# where COL = HEXTORAW( d a d ae ) and ROWID = AAABg AAFAAABQaAAH 如果想要使用字典文件 数据库至少应该出于MOUNT状态 然后执行dbms_logmnr_d build过程将数据字典信息提取到一个外部文件中 下面是具体分析步骤 确认设置了初始化参数 UTL_FILE_DIR 并确认Oracle对改目录拥有读写权限 然后启动实例 示例中UTL_FILE_DIR参数如下 SQL>show parameter utlNAME TYPEvalue utl_file_dir string　/data /cyx/logmnr 这个目录主要用于存放dbms_logmnr_d build过程所产生的字典信息文件 如果不用这个 则可以不设 也就跳过下面一步 生成字典信息文件 exec dbms_logmnr_d build(dictionary_filename =>dic ora dictionary_location =>/data /cyx/logmnr )其中dictionary_location指的是字典信息文件的存放位置 它必须完全匹配UTL_FILE_DIR的值 例如 假设UTL_FILE_DIR=/data /cyx/logmnr/ 则上面这条语句会出错 只因为UTL_FILE_DIR后面多了一个 / 而在很多其它地方对这一 / 是不敏感的 dictionary_filename指的是放于字典信息文件的名字 可以任意取 当然我们也可以不明确写出这两个选项 即写成 exec dbms_logmnr_d build( dic ora /data /cyx/logmnr )如果你第一步的参数没有设 而直接开始这一步 Oracle会报下面的错误 ERROR at line :ORA : initialization parameter utl_file_dir is not setORA : at SYS DBMS_LOGMNR_D line ORA : at SYS DBMS_LOGMNR_D line ORA : at line 需要注意的是 在oracle for Windows版中会出现以下错误 : : SQL>execute dbms_logmnr_d build( oradict ora c:\oracle\admin\ora\log )BEGIN dbms_logmnr_d build( oradict ora c:\oracle\admin\ora\log )END*ERROR at line :ORA : Subscript outside of limitORA : at SYS DBMS_LOGMNR_D line ORA : at line 解决办法 编辑 $ORACLE_HOME/rdbms/admindbmslmd sql 文件 把其中的TYPE col_desc_array IS VARRAY( ) OF col_description改成 TYPE col_desc_array IS VARRAY( ) OF col_description保存文件 然后执行一遍这个脚本 : : SQL>@c:\oracle\ora \rdbms\admin\dbmslmd sqlPackage created Package body created No errors Grant succeeded 然后重新编译DBMS_LOGMNR_D包 : : SQL>alter package DBMS_LOGMNR_D pile bodyPackage body altered 之后重新执行dbms_logmnr_d build即可 : : SQL>execute dbms_logmnr_d build( oradict ora c:\oracle\admin\ora\log )PL/SQL procedure successfully pleted 添加需要分析的日志文件 SQL>exec dbms_logmnr add_logfile( logfilename=>/data /cyx/rac arch/arch_ _ arc options=>dbms_logmnr new)PL/SQL procedure successfully pleted 这里的options选项有三个参数可以用 NEW 表示创建一个新的日志文件列表 ADDFILE 表示向这个列表中添加日志文件 如下面的例子 REMOV lishixinzhi/Article/program/Oracle/201311/18949

在“oracle安装路径\product\oracle版本\admin\实例名称\bdump”路径下。

备注：根据文件修改的时间，找到启动日志“.trc”文件，即可看到错误信息。

‍测试环境中出现了一个异常的告警现象：一条告警通过 Thanos Ruler 的 HTTP 接口观察到持续处于 active 状态，但是从 AlertManager 这边看这条告警为已解决状态。按照 DMP 平台的设计，告警已解决指的是告警上设置的结束时间已经过了当前时间。一条发送至 AlertManager 的告警为已解决状态有三种可能：1. 手动解决了告警2. 告警只产生了一次，第二次计算告警规则时会发送一个已解决的告警3. AlertManager 接收到的告警会带着一个自动解决时间，如果还没到达自动解决时间，则将该时间重置为 24h 后首先，因为了解到测试环境没有手动解决过异常告警，排除第一条；其次，由于该告警持续处于 active 状态，所以不会是因为告警只产生了一次而接收到已解决状态的告警，排除第二条；最后，告警的告警的产生时间与自动解决时间相差不是 24h，排除第三条。那问题出在什么地方呢？

分析

下面我们开始分析这个问题。综合第一节的描述，初步的猜想是告警在到达 AlertManager 前的某些阶段的处理过程太长，导致告警到达 AlertManager 后就已经过了自动解决时间。我们从分析平台里一条告警的流转过程入手，找出告警在哪个处理阶段耗时过长。首先，一条告警的产生需要两方面的配合：

metric 数据

告警规则

将 metric 数据输入到告警规则进行计算，如果符合条件则产生告警。DMP 平台集成了 Thanos 的相关组件，数据的提供和计算则会分开，数据还是由 Prometheus Server 提供，而告警规则的计算则交由 Thanos Rule（下文简称 Ruler）处理。下图是 Ruler 组件在集群中所处的位置：

看来，想要弄清楚现告警的产生到 AlertManager 之间的过程，需要先弄清除 Ruler 的大致机制。官方文档对 Ruler 的介绍是：You can think of Rule as a simplified Prometheus that does not require a sidecar and does not scrape and do PromQL evaluation (no QueryAPI)。

不难推测，Ruler 应该是在 Prometheus 上封装了一层，并提供一些额外的功能。通过翻阅资料大致了解，Ruler 使用 Prometheus 提供的库计算告警规则，并提供一些额外的功能。下面是 Ruler 中告警流转过程：

请点击输入图片描述

请点击输入图片描述

首先，图中每个告警规则 Rule 都有一个 active queue（下面简称本地队列），用来保存一个告警规则下的活跃告警。

其次，从本地队列中取出告警，发送至 AlertManager 前，会被放入 Thanos Rule Queue（下面简称缓冲队列），该缓冲队列有两个属性：

capacity（默认值为 10000）：控制缓冲队列的大小，

maxBatchSize（默认值为 100）：控制单次发送到 AlertManager 的最大告警数

了解了上述过程，再通过翻阅 Ruler 源码发现，一条告警在放入缓冲队列前，会为其设置一个默认的自动解决时间（当前时间 + 3m），这里是影响告警自动解决的开始时间，在这以后，有两个阶段可能影响告警的处理：1. 缓冲队列阶段2. 出缓冲队列到 AlertManager 阶段（网络延迟影响）由于测试环境是局域网环境，并且也没在环境上发现网络相关的问题，我们初步排除第二个阶段的影响，下面我们将注意力放在缓冲队列上。通过相关源码发现，告警在缓冲队列中的处理过程大致如下：如果本地队列中存在一条告警，其上次发送之间距离现在超过了 1m（默认值，可修改），则将该告警放入缓冲队列，并从缓冲队列中推送最多 maxBatchSize 个告警发送至 AlertManager。反之，如果所有本地队列中的告警，在最近 1m 内都有发送过，那么就不会推送缓冲队列中的告警。也就是说，如果在一段时间内，产生了大量重复的告警，缓冲队列的推送频率会下降。队列的生产方太多，消费方太少，该队列中的告警就会产生堆积的现象。因此我们不难猜测，问题原因很可能是是缓冲队列推送频率变低的情况下，单次推送的告警数量太少，导致缓冲队列堆积。下面我们通过两个方面验证上述猜想：首先通过日志可以得到队列在大约 20000s 内推送了大约 2000 次，即平均 10s 推送一次。结合缓冲队列的具体属性，一条存在于队列中的告警大约需要 (capacity/maxBatchSize)*10s = 16m，AlertManager 在接收到告警后早已超过了默认的自动解决时间（3m）。其次，Ruler 提供了 3 个 metric 的值来监控缓冲队列的运行情况：

thanos_alert_queue_alerts_dropped_total

thanos_alert_queue_alerts_pushed_total

thanos_alert_queue_alerts_popped_total

通过观察 thanos_alert_queue_alerts_dropped_total 的值，看到存在告警丢失的总数，也能佐证了缓冲队列在某些时刻存在已满的情况。

解决通过以上的分析，我们基本确定了问题的根源：Ruler 组件内置的缓冲队列堆积造成了告警发送的延迟。针对这个问题，我们选择调整队列的 maxBatchSize 值。下面介绍一下这个值如何设置的思路。由于每计算一次告警规则就会尝试推送一次缓冲队列，我们通过估计一个告警数量的最大值，得到 maxBatchSize 可以设置的最小值。假设你的业务系统需要监控的实体数量分别为 x1、x2、x3、...、xn，实体上的告警规则数量分别有 y1、y2、y3、...、yn，那么一次能产生的告警数量最多是(x1 * y2 + x2 * y2 + x3 * y3 + ... + xn * yn)，最多推送（y1 + y2 + y3 + ... + yn）次，所以要使缓冲队列不堆积，maxBatchSize 应该满足：maxBatchSize >= (x1 * y2 + x2 * y2 + x3 * y3 + ... + xn * yn) / (y1 + y2 + y3 + ... + yn)，假设 x = max(x1,x2, ...,xn), 将不等式右边适当放大后为 x，即 maxBatchSize 的最小值为 x。也就是说，可以将 maxBatchSize 设置为系统中数量最大的那一类监控实体，对于 DMP 平台，一般来说是 MySQL 实例。

注意事项

上面的计算过程只是提供一个参考思路，如果最终计算出该值过大，很有可能对 AlertManager 造成压力，因而失去缓冲队列的作用，所以还是需要结合实际情况，具体分析。因为 DMP 将 Ruler 集成到了自己的组件中，所以可以比较方便地对这个值进行修改。如果是依照官方文档的介绍使用的 Ruler 组件，那么需要对源码文件进行定制化修改。

‍‍

---