2.1 调优排故的一般步骤
总的来说,调优、排故大都是从原理的角度分析问题可能出现在哪个环节。但Oracle不是单车,其原理庞杂,单是Oracle编译过的可执行文件,在Oracle 11g中就已经达到250MB左右,在Oracle最新版12C中,可执行文件大小已达340MB左右(在不同操作系统下,稍微会有些差异),自定义函数有十几万个。
这么庞大的软件,在实际遇到问题时,不可能从头到尾把所有原理分析一遍。事实上,Oracle为我们提供了很多工具和信息,可以帮助确定问题的大概方向。
其实,Oracle在各种资料(包括联机文档)中多次宣称Oracle是一个可观测、可调节的数据库。Oracle不单有DBA_系列视图,可以查阅“数据定义”类元数据信息,还有丰富的 V$系列视图,可以查阅SGA中的状态。如果这还不够,V$的底层X$还提供了更详细的信息,另外还有各种各样的跟踪事件、DUMP命令。善于使用这些工具,将使你能体会“发现”的乐趣。利用这些工具,一步步地挖掘Oracle工作原理,将会拨开网络上各种信息的“迷雾”,一步步接近真相。正如我一直宣称的,研究Internal,结果不是目的,过程更有意义。在这个过程中,你会收获很多。
下面,把最重要、最常用的工具介绍一下。
2.1.1 常见DUMP和Trace文件介绍
Oracle的问题通常可以分为两大类:性能问题和故障。性能问题通常都是对用户的反应慢,而故障多指异常的宕机或其他数据库的异常情况。
如果你遇到了故障,DUMP文件和Trace文件将成为你调查故障的最佳入口。
按照存放位置不同,DUMP、Trace文件共分3类:后台进程DUMP文件、核心DUMP文件和用户DUMP文件。它们分别对应参数background_dump_dest、core_dump_dest、user_dump_dest所在的位置。在Oracle 11g之后,这3个参数通常是一个位置。
其中最重要的就是background_dump_dest中的告警日志文件了。
在阿里巴巴,Oracle数据库的所有监控中,最重要的一个就是将告警日志中大部分以ORA-开头的错误信息,以短信的方式发送到DBA的手机上。
至于这些文件的阅读示例,网络中有很多相关描述,本章不再论述。
2.1.2 等待事件
如果遇到故障,在分析完DUMP、Trace文件后,就得关注等待事件了。
而对于性能问题,等待事件将是我们判断问题首先要关注的。
其实Oracle称呼等待事件为Event,也就是事件,并不一定发生等待时才有Event。Event目的是告诉我们Oracle此刻正在做什么的,不能单纯只把它看作等待。
比如,当你看到某个Session当前的Event是db file sequential read时,说明此Session对应的进程,正在完成物理I/O,也就是正在从磁盘上读一些块。如果这个Event一共用了15毫秒,那就是说Oracle完成这批物理I/O,用时15毫秒。
如果在过去的半小时中,数据库一共产生过777375次db file sequential read事件,这70多万次事件共占用时间3308秒,用3308除以777375,可以得到每个事件的平均占用时间约4毫秒。这个值可以作为磁盘的随机I/O响应时间。也就是说,在过去的半小时内,Oracle随机I/O响应时间为4毫秒。
这个值可以很方便地在AWR或老版的Statspack中查到。在评估存储是否正常时,这个值是很重要的值。从经验上来说,通常高端存储的随机I/O响应时间都可以控制在10毫秒以下,中端的控制在10毫秒左右。响应时间超过20毫秒的I/O,一般认为是比较缓慢的I/O。
I/O响应时间慢一般有两种原因:存储问题或者I/O太多。这里不再对这一事件展开描述,在后面的章节中会详细讲述I/O。
我一直觉得Oracle中的等待事件很奇妙,在Oracle 11g中,一共有1118个等待事件,几乎覆盖了Oracle工作的方方面面,它是如何实现为每个操作记录等待事件的呢?机制是怎样的呢?网络中关于这方面的资料很少。有一段时间我一直认为等待事件是超过一定时间就记录,但其实不是。经过用gdb、mdb等调试工具调试Oracle可执行文件发现,Oracle中的事件,按照工作原理一共可以分为两类,一类是主动触发事件,另一类是被动触发事件。
比如前文一直提到的db file sequential read就是一个主动触发事件。Oracle在完成一个I/O时,它知道I/O不会很快完成,于是会主动登记一个事件,然后再开始进行I/O操作。
所有I/O类相关的等待事件,包括网络I/O,都是主动触发事件。除db file sequential read外,db file sequential read、direct path read、direct path write、log file parallel write等这些与I/O相关的事件,都是主动触发的。
主动触发事件还有一个特点:只要发生一次I/O,一定会对应一次I/O相关事件。仍以db file sequential read为例,无论I/O的完成速度有多快,在读I/O操作开始前,Oracle都会登记一次db file sequential read事件。
Oracle明知I/O操作会很慢,因此会主动登记一个等待事件,告诉用户“我在完成I/O”。但有些动作,比如一个Latch的获取,会在极短的时间内完成。在获取一个Latch前,进程不会主动登记等待事件。只有当遇到阻塞、获取不到时,才会记录等待事件,这种就是被动事件。
除I/O相关、网络相关的等待之外的事件,基本上都是被动事件。
仍以Latch为例,再次强调一下被动事件的主要特点,如果没有遇到阻塞,哪怕Latch的获取过程非常慢,也不会有任何等待事件。
对各种事件以及其背后原理的深入挖掘是十分必要的。因为一旦遇到问题, Oracle就会用事件告诉你此刻它正在做什么,如果你对事件不理解或者理解错了,就会错失解决问题的良机。
一般遇到性能问题时,通过查看事件即可解决,所以相对来说还是很简单的。但如果遇到故障,特别是异常宕机的故障,则很难知道最后时刻Oracle登记的事件是什么。如果能找到这个事件,对于诊断宕库类故障将很有意义,因为根据事件可以推测出Oracle最后时刻的动作。下面说一下如何挖掘宕库时数据库最后时刻的等待事件。
正常情况下,等待事件的查询可以通过v$session、v$session_evnt、v$system_event、v$session_wait等视图来查看,这里不再详述。对于异常故障,Oracle通常会产生一些 DUMP文件或Trace文件,有时,我们可以从中挖掘出等待事件。下面通过案例来介绍一种在异常情况下挖掘等待事件的方法。
首先查看告警日志文件。Oracle生成的重要Trace文件会在告警日志文件中有记录。找到告警日志后,再在其中找Trace文件,因为在Trace文件中,通常可以找到Call Stack Trace,也就是运行堆栈。
运行堆栈是当出问题时Oracle进程自身调用的函数信息。Oracle开发人员在确诊代码Bug时,这部分函数内容是很重要的信息,通常我们在查看Trace文件时,会把这部分信息略去。但如果想找到数据库异常宕掉时的等待事件,这部分信息就不能略去。
还有一点要知道,Oracle 10g的全部事件和Oracle 11g的大部分事件,都是用一个Oracle内部自定义函数kslwait登记的。在Trace文件的运行堆栈中,找一下是否有kslwait函数的调用,如果有,就能确定在数据库宕掉时,最后的等待事件是什么,或者说,进程发生异常时,等待事件是什么。下面我们通过一个案例了解一下这种情况。
首先,以Oracle 11.2.0.4、Linux为测试环境,深入了解一下等待事件的相关知识。
步骤1:打开一个测试Session,如图2-1所示。
测试会话SID为140,进程号是4718。
步骤2:使用gdb调试它。
这一步的结果很多,分成两张图显示,如图2-2和图2-3所示。
从图2-3可以看到,gdb命令运行成功后,最终会显示gdb的提示符(gdb)。
步骤3:在kslwtbctx函数处设置断点,如图2-4所示。
kslwtbctx函数是等待事件的起始函数。在它的入口处设置断点,接着使用了“c”命令,让进程继续处理指令流。
由于现在4718进程没有任何动作,因此没有执行到kslwtbctx函数处,所以在“c”命令后,gdb显示continuing,表示进程正在运行中,没有触发断点。
步骤4:执行测试语句。
在测试会话中,随便执行一条语句(比如select语句),Oracle都会产生等待事件。比如select会产生SQL*Net类的等待事件。下面执行测试SQL,如图2-5所示。
图2-5 执行测试语句
140会话中的SQL被Gdb Hang住了,说明断点已经被触发。
步骤5:在gdb中查看断点被触发的情况。
测试会话的执行流,停在kslwtbctx函数处,如图2-6所示。
图2-6 查看断点
此函数的第一个参数是一个指向进程自身堆栈内存的地址,它是一个Struct的指针。在进程自身堆栈空间中,可以认为Struct的内存属于PGA。此struct中有等待事件的信息。
这些内部信息是使用Dtrace和mdb调试出来的。我在Solaris下调试Oracle时,曾经研究过等待事件的相关函数,因此了解这些信息。
如何查看kslwtbctx第一个参数的值呢?如果是32位系统,函数参数会放在堆栈中,可以通过rbp、rsp寄存器找到函数参数。而在64位系统中,OS已经做了优化,函数参数直接放在rdi寄存器中,即函数的第一个参数在rdi寄存器中。
关于这些信息,可以查阅Intel CPU手册和Linux内核分析的书籍。一名精通调试技术的DBA,不是普通的DBA,他必然会对CPU、OS内核非常了解。将来我们调试的不一定是Oracle,也可以是其他重要的系统。
下面显示一下寄存器的值,如图2-7所示。
图2-7 显示寄存器
这里特意将rdi这行涂黑。它保存的数据是0x7fff7ba0eb88。前文说了,这是一个地址。下面,显示它所指向的数据。使用命令x/32 0x7fff7ba0eb88,从0x7fff7ba0eb88开始,显示32个字,如图2-8所示。
图2-8 显示数据
注意被涂黑的数据0x00000092,这个值就是被调试进程的等待事件。这个等待事件是什么呢?
SQL>select event#,name from v$event_name where event#=to_number('92','xxxx');
EVENT# NAME
---------- ----------------------------------------------------------------
146 db file sequential read
如何验证当前会话正在等的事件的确是db file sequential read呢?直接查询v$session视图是不行的。
SQL>select event from v$session where sid=140;
EVENT
----------------------------------------------------------------
Disk file operations I/O
因为等待事件信息还没有完全写到资料视图中。其实验证方法很简单。
如图2-9所示是140会话曾经发生过的等待事件。
图2-9 等待事件
在gdb中,输入命令“c”,让进程的执行流停在下一个等待事件上,如图2-10所示。
图2-10 停在等待事件上
再次查看140会话当前曾经发生过的等待事件,如图2-11所示。
和刚才相比,多了一次db file sequential read。
好,现在已经验证了kslwtbctx函数的第一个参数,向下104字节处的一个字,就是等待事件的event#。
图2-11 140会话等待事件
有了这些信息,使用dtrace或Linux下的ptrace等调试工具,非常容易就能编写出显示进程运行过程中所有等待事件的跟踪脚本。但这已经超出本章主题,以后再讲。
下面看一个案例。情况很简单,用户的RAC系统最近一段时间老是莫名其妙地宕机。下面来分析一下宕机时的DUMP文件。
在CRS_HOME/log的日志中,只能看到节点DOWN了,没有进一步的信息。但告警日志中显示,宕机时LMS进程产生一个TRC文件。下面就尝试从这个文件挖掘线索。
先从DUMP文件开头开始,开头显示LMS进程会话号为449。
*** SESSION ID:(449.1)
下面用会话号“449”,在文件内搜索,找到如下内容:
----------------------------------------
SO: 0xc00000123065dcc8, type: 4, owner: 0xc00000123000a0c8, flag: INIT/-/-/0x00
if: 0x3 c: 0x3
proc=0xc00000123000a0c8, name=session, file=ksu.h LINE:10719 ID:, pg=0
(session) sid: 449 ser: 1 trans: 0x0000000000000000, creator:
0xc00000123000a0c8
ksuxds FALSE at location: 0
service name: SYS$BACKGROUND
Current Wait Stack:
0: waiting for 'gcs remote message'
Wait State:
auto_close=0 flags=0x22 boundary=0x0000000000000000/-1
Session Wait History:
0: waited for 'gcs remote message'
1: waited for 'gcs remote message'
2: waited for 'gcs remote message'
3: waited for 'gcs remote message'
………………
这里显示449会话最后的等待事件是gcs remote message。知道这点,对于解决问题没有任何帮助,因为Oracle后台进程日常的等待事件就是gcs remote message。从Session Wait History中也能看到这点。
但在进程调用堆栈中,发现有如下的内容:
………
kslwaitctx()+240 call $cold_ksliwat() C00000123065F668 ?
C00000123065F668 ?
000000003 ?
600000000013F700 ?
kslwait()+192 call kslwaitctx() 9FFFFFFFFFFFB710 ?
000000003 ?
………
这段运行堆栈说明,kslwait函数在偏移0x192字节处调用了函数kslwaitctx。
由于用户数据库版本是11.1.0.7,而前文中的测试版本是11.2.0.4,因此Oracle内部函数名会略有不同。注意,这里的kslwaitctx就是前文测试中的kslwtbctx,它的第一个参数指向等待事件的具体信息。
此处,它的第一个参数值为0x 9FFFFFFFFFFFB710。用这个地址在DUMP文件中搜索,相关内容如图2-12所示。
图2-12 查找相关内容
注意, 9FFFFFFFFFFFB710向下104字节处的值是 000000A0,它就是等待事件的event#,十进制是160。在相同的版本下(这个库版本是11.1.0.7),在v$event_name查看event#为160的等待事件:gc current block lost。
为什么跟踪文件下面的等待事件是gcs remote message,而我们从调用堆栈挖出的等待事件是gc current block lost呢?
具体原因已经是另一个话题了,需要更深一步了解Oracle等待事件机制,这里不再详述。
本例中这种DUMP文件中等待事件错误的情况是很少见的,大部分时候调用堆栈中的等待事件,和下面DUMP的等待事件是一样的。
但如果出现不一样的情况,应该以调用堆栈中的等待事件作为最后的等待事件。
gc current block lost是一个有关gc当前块的等待事件。这个等待事件笔者也没有深究过。不过,什么时候会有“当前块”的需求呢?很简单,进程在修改某个块时。这和单实例下的当前读一样。
普通DML所引发的gc current类等待,等待进程大多是服务器进程,很少是后台进程。这个gc current既然是后台进程,很有可能是DDL引起的,而且应该是频繁执行的DDL。根据这个猜想对数据库应用进行排查,发现有一个truncate被频繁地执行。和应用部分协商后,将此表改为临时表后,节点就不再DOWN掉了。
这个例子先介绍到这里,总之,在确定问题时,等待事件是非常重要的。
等待事件的查看、等待事件的意义是DBA必须掌握的内容。但我们不能只关注等待事件,还有一些其他的信息可以帮助我们确定问题,比如资料视图。
2.1.3 各种资料视图介绍
Oracle提供了很多V$*STAT资料视图,以便我们可以及时了解数据库的运行状态。比如v$undostat记录UNDO的使用情况,v$segstat记录段级访问资料,等等。各种资料类视图中,有一类使用最为广泛,就是v$sysstat、v$sesstat、v$statname。
在AWR中,许多信息其实都来自于v$sysstat,比如报告最前面的Profile中的逻辑读次数、物理读次数、执行次数、解析次数等。
除了Profile,AWR中的Instance Activity Statistics其实展示的就是v$sysstat中的所有信息,这对于诊断问题还是很有帮助的。
阿里巴巴有一套核心数据库,曾经出现过一个奇怪的问题。某天中午11点多,应用服务器上的数据库连接数突然大增,数据库进程数迅速超过Processes参数值,新的连接无法建立,客服不断收到用户投诉。
这套库的Processes参数值设定为4000,平常连接数每天低峰时2000左右,高峰时3000左右,出问题时是上午11点多,正是业务高峰期,连接数本来接近3000。但在短短几分钟内,从这个数字上升到4000,用完了所有的Processes。
随后几天,这样的问题每天定时出现,每次都是11点左右。
由于当时使用的Oracle版本还是9i,没有ASH可用,无法查询历史等待事件,而在以半小时为粒度的Statspack中又查不到任何异常,只能暂时Kill掉一些不重要的进程,暂时缓解一下问题。
至于对进程重要性的判定,则是通过看进程来自哪个应用服务器,也就是v$session的MACHINE列,还有PROGRAM列,和开发人员一起来判断的。
除了Kill进程外,我们一直在观察等待事件,因为既然进程数大增,说明一定是哪里出现了阻塞,导致用户操作完成得慢,而此时新的用户又在不断地连接,于是造成了进程数突增。但很可惜,等待事件非常正常,没有发现任何异常的等待事件,一些关键等待事件的等待时间也都很正常。
几分钟后,也就是过了问题发生的时段,进程数滑落到正常范围内。虽然通过等待事件没有确定任何问题,不过幸好,我们以10秒为单位从数据库中抓取了一些关键资料,而这些资料的数据来源就是v$sysstat。
如图2-13所示就是出问题时,执行次数、用户调用数、解析次数的曲线图。
图2-13 v$sysstat资料视图使用示例(一)
图中这3个指标最上面的曲线是执行次数(execute count),中间的是调用次数(user calls),最下面的曲线是解析次数(parse count)。
虽然该图有些简陋,但仍可以看到问题,这3个指标在11点20分前,突然下滑,之后快速升高,再之后,又迅速恢复正常。而连接数(也就是进程数)的高涨,发生在11点20分左右,到11点21分之后恢复正常,正好是在这3个指标下滑到升高之间。
可以看到这3个指标都是先下降,后升高,而在此期间没有任何可以观察到的异常等待,甚至连总的等待次数、等待时间都没有太大波动。
所以,单纯依赖等待事件是无法判断此问题的。根据执行次数等资料值的波动倒是可以分析一下。
调用次数、执行次数、解析次数的下降说明用户都不再执行SQL操作了,又没有等待事件阻塞着用户,那么,是什么原因让用户同时都不再执行SQL了?很明显,是用户突然无法将需求发送给数据库了。又是什么原因导致用户无法将需求发送给数据库的呢?只能是网络。
但是网络的状态和资料的查看时间粒度比较粗,是以10分钟为周期的,所以并没有发现异常情况。
数据库端资料显示,每次都是在11点20分前执行次数开始下滑时,应用服务器上的需求无法传到数据库,到11点20分后,网络恢复正常,大量积压的需求突然一下传到数据库,导致执行次数等资料值突升。
另外,开发人员也检查了应用服务器上的程序,逻辑设计还是有点问题的:在网络异常阶段,程序有连接或执行SQL需求无法完成,会不断循环,尝试创建新的连接。这导致一旦无法建立连接,或SQL无法完成,应用服务器会疯狂地向数据库发送连接请求。这可能造成网络一旦恢复正常,数据库瞬间收到大量连接和SQL执行请求。
由于网络那边无法检查以分钟以下为单位的异常,最终我们将目光瞄向了和数据库服务器同一网段、共享网络的其他主机。经过排查,发现有一组十几台MySQL数据库,每天会定时向另外一组MySQL同步数据,而在出问题的那天,同步数据的时间变了,本来应该是晚上同步,而变到了11点20分左右。而且,在刚开始同步时,流量还是很大的。
看来问题已经找出来了,11点20分左右MySQL突然同步,导致网络带宽被大量占用,应用服务器上的连接、SQL请求无法传到数据库,导致此时数据库的执行次数等资料突然下降。然后,应用服务器上的程序开始不断创建新的连接。接着,MySQL同步数据量下降,网络空闲,大量新的连接、和命令请求同时传到数据库,使得进程数瞬间增加至很高。
将MySQL的同步数据时间改变后,数据库恢复正常,再没有出现过连接数突增的情况。
从这个案例可以看出,如果在确定问题时只关注等待事件是无法找出产生问题的根源的,因为网络只是被别的程序占用,并不是完全断开,仍有部分请求可以传到数据库上执行,而且虽然新的SQL请求无法及时传到数据库,但原来已有的语句还在执行。所以,从等待事件上看,数据库完全正常,都是一些I/O类等待事件。
执行次数指标的先低后高,再加上没有异常的等待事件,使我们可以确定,问题一定不在Oracle范围内。
其实对于这种情况,还有两个资料也可以帮助确定问题:bytes received via SQL*Net from client和bytes sent via SQL*Net to client。对这两个网络相关的资料,大部分DBA并不怎么重视,因为数据库的主要瓶颈就是I/O、CPU和内存,网络通常并不会造成竞争和等待。特别是网络相关等待事件SQL*Net message from client(等待从客户端接收命令),更是相关进程空闲的代表。但网络相关的资料是十分有意义的,网络相当于Oracle的大门,用户需求通过网络传送到Oracle,Oracle处理完需求后,结果数据还是要通过网络传送给客户端。这一进一出都要经过网络这道大门,统计进、出网络的流量,对于了解数据库负载是十分有意义的事。其实几乎数据库的任何风吹草动都会在网络上体现出来。
比如在该示例中,在执行次数先低后高时,bytes received via SQL*Net from client资料值也出现突然的下降。这些都可以帮助我们确定问题。
之后又遇到过一个类似案例:一个DBA所维护的数据库被投诉应用不正常。在出问题时段,从AWR报告、ASH视图中的等待事件查不到任何异常。我对比了AWR报告中的bytes received via SQL*Net from client和bytes sent via SQL*Net to client,发现通过网络收到的信息量在出现问题时段比平常少一个量级。收到的信息减少,说明数据库根本收不到应用程序发送的SQL请求。我把结果告诉那个DBA,让他将问题交给网络人员定位,结果果真找出了问题所在。
其实,只要是数据出问题,网络资料都会有些异常。用图形工具软件可以将网络资料转成曲线图,只要网络曲线图有任何风吹草动,数据库中必会有所反应。
图2-14至图2-17是我的一些总结,依次来看看。
图2-14 v$sysstat资料视图使用示例(二)
从图2-14中可以看到,在14点54分多一点的时候,有一条曲线波动剧烈,这条曲线就是bytes received via SQL*Net from client,即收到字节数。它突然大幅升高,表示数据库定有异常。再查看其他资料,如图2-15所示。
图2-15 v$sysstat资料视图使用示例(三)
在这幅图中,波动剧烈的资料是物理写。在同一时间,它也大幅增加,它的曲线图和bytes received via SQL*Net from client基本吻合。更进一步排查原因,发现是由大量的排序操作所导致的,调整SQL后变得正常,未再出现物理写数据量飙升的情况。
再来看一个例子,如图2-16所示。
图2-16 v$sysstat资料视图使用示例(四)
在图2-16中,从9点46分到9点51分出现了收到字节数异常的情况。经过对比,发现这次是出现了日志资料异常,如图2-17所示。
图2-17 v$sysstat资料视图使用示例(五)
图2-17中波动剧烈的曲线是Log File Sync的响应时间,在9点46分到9点51分之间,响应时间慢了将近10倍。最终的问题是由于存储控制器后端口压力不平衡,在I/O压力大时,响应时间出现抖动。存储工程师对此进行调整后该问题得到解决。
更多例子这里不再列举。在阿里巴巴的所有数据库中,重要的资料都会用曲线图展现。在每日查看数据库健康状态时,我都会从网络曲线图入手。如果网络资料没有大幅度波动,数据库基本上都是正常的。如果看到网络资料波动很大,就要进一步查看数据库是否有问题。
资料视图中的有些资料,其本身虽有一定含义,但从名字上却不容易看出来,比如Redo entries(重做条目数)。一条Redo Recoder,又可以称为一个Redo entrie。因此这项资料是用于记录Oracle一共生成了多少条Redo Recoder的。这个资料看似意义不大,但是,如果进一步发掘Redo的原理,可以发现Redo Recoder的数目可以告诉我们其他信息。
分析一下Redo信息的生成流程:通常Oracle会先在PGA中记录后映像,在IMU方式下,后映像还会传送到共享池中暂存,并且最终在Log Buffer中根据后映像组装成一条Redo Recoder。
这里暂时不对IMU相关问题及日志流程详细讨论,后面有专门章节描述相关内容。
注意一点,只有在Redo相关的数据被传送到Log Buffer后,这些数据才会被组装成Redo Recoder。换句话说,当Redo相关的数据被传送到Log Buffer时,这些数据才会被称为Redo Recoder。
可见,有一条Redo Recoder则说明向Log Buffer传送过一次Redo数据,有100条Redo Recoder则说明向Log Buffer传送过100次数据。也就是说,Redo Recoder的数量代表了向Log Buffer中写数据的次数,这就是Redo entries资料背后的意义。
如果出现Log Buffer Space类的等待事件,或者Redo Copy Latch、Redo allocate Latch竞争严重,可以对比一下正常和不正常时段Redo entries资料的值。
如果Redo entries的值很高,则说明向Log Buffer中写数据的次数很多。
每向Log Buffer中写一次数据,都会申请一次Redo Copy Latch、Redo allocate Latch等相关的Latch。向Log Buffer中写数据次数太多,必然会导致这些Latch有竞争。IMU的出现,就是为了缓解这些竞争的。
2.1.4 等待事件的注意事项
在查看等待事件的时候,有一个小的注意事项,很多人平常并不注意,在此用一小测试,提醒一下各位读者。
步骤1:在两个会话中分别执行类似下面的PL/SQL匿名块。
declare
m_id number;
begin
fori in 1..10000000 loop
select id into m_id from vage where rownum=1;
end loop;
end;
/
此匿名块什么工作都不做,只是在循环中反反复复查询表T的第一行数据。
如果在两个会话中同时执行此段程序,会遇到什么等待事件?
步骤2:在另一会话中观察等待事件。
col event for a45
setlinesize 1000
select sid,seq#,event from v$session where wait_class<>'Idle' order by event;
SID SEQ# EVENT
--- ---- --------------------------
237 769 SQL*Net message to client
256 231 latch: cache buffers chains
253 253 latch: cache buffers chains
可以看到,由于反复逻辑读同样的块,会有块上的Cache Buffer Chain Latch竞争。还有,由于两个会话中会反复解析同样的SQL,因此有可能会有解析时的Mutex等待。如果重复执行上面的SQL,可以观察到Cache Buffer Chain Latch或Cursor:pin S等待事件。
出现等待事件的原因是两个会话对应的服务器进程同时请求同样的资源,如果此时将一个会话中的PL/SQL程序块终止掉会怎样呢?想必只剩一个进程解析、逻辑读,就不会有等待了。是否真是这样呢?
步骤3:将一个会话中正在执行的PL/SQL终止,再次观察等待事件。
终止PL/SQL的执行是很简单,在一个会话中使用快捷键Ctrl+C即可。现在只剩一个会话反反复复解析、逻辑读了,这样应该就不会再有等待了。使用步骤2中的SQL,再一次观察等待事件。结果如下:
SQL> select sid,seq#,event from v$session where wait_class<>'Idle' order by event;
SID SEQ# EVENT
---------- ---------- ---------------------------------------------
237 825 SQL*Net message to client
256 350 latch: cache buffers chains
还是有等待。一个进行正在执行的程序已经被终止了,只剩另一个进程在运行,但查询结果还是有等待。
原因很简单,我们在用v$session查看当前等待事件时,记得要把STATE列带上。下面是修改后的显示结果:
SQL> select sid,seq#,event,state from v$session where wait_class<>'Idle' order by event;
SID SEQ# EVENT STATE
--- ---- ---------------------------- -------------------
237 829 SQL*Net message to client WAITED SHORT TIME
256 350 latch: cache buffers chains WAITED SHORT TIME
STATE列如果为 WAITING,说明会话正在等待此事件。如果不是WAITING,说明当前会话已经不再等待某个事件了,v$session中的EVENT列,显示的只是会话最后一次等待的事件。
新的显示结果中,STATE为WAITED SHORT TIME,所以,此处的Cache Buffer Chain Latch等待,是会话最后一次等待时的事件。会话现在已经不等待了。
不等待这是进程工作的理想状态,即没有任何等待完成工作就仿佛开车上班,一路无红灯,畅通无阻地前行。
这个例子很简单,但越是简单的地方,越容易被忽视。