AWR是我们进行Oracle性能调整主要的工具之一;一般情况而言,时间是衡量性能好坏一个重要因素,AWR中有很多与时间相关的内容和指标。先来看一上Oracle定义的响应时间模型公式:
Response time = Service time + Wait time
服务时间(Servicetime)就是进程“真正”在cpu上运行的时间,可以简单理解为AWR中的cpu time/db cpu,服务时间包括前台进程(Server process)和后台进程(Backgroud process)消耗的时间。等待时间就是等待某种资源的时间耗费,比如等待锁资源的耗费,可以简单对应为awr中的wait time, 等待时间包括很多类型,一般最常见的是IO等待和并发等待,比如进程等待从物理磁盘读取数据块到内存中的等待。
Awr中的db time可以简单对应为Responsetime;对于操作系统而言,一个进程要么在cpu中运行,要么处于等待队列中;注意这里的“等待”并不完全等同于os中的等待。
一、 db time与cpu time
首先需要说明一个概念:时间片。现代操作系统(unix/Linux)将cpu资源划分成时间片(cpu slice)为单位来使用,一般是一个很小的值,一般为10ms。操作系统使用一个调度程序(比如linux的CFS调度器,来协调各个进程使用cpu资源。更详细的内容超出了本文的讨论范围,有兴趣的可以参考操作系统相关的文档。
DB time是整个数据库用户进程消耗的总时间,可用于衡量一个数据库整体负载,这有一些类似unix/linux系统中的平均负载(average load)指标。我们来看一份awr:
Snap Id | Snap Time | Sessions | Cursors/Session | |
Begin Snap: | 9820 | 13-2月 -12 08:00:17 | 735 | 89.3 |
End Snap: | 9821 | 13-2月 -12 09:00:13 | 965 | 92.3 |
Elapsed: | 59.93 (mins) | |||
DB Time: | 437.53 (mins) |
我们可以看到这一个awr的间隔时间为60分钟,而db time达到了437分钟,比率大致为7.3,我们这一个系统为16 core cpu 的小型机,那么在60分钟可以提供的cpu time为16*60=960分钟的cpu time;如果我们的db time全部都由cpu time来构成(当然是不可能的,Oracle总会有一些等待),cpu的占用率为46%;cpu资源还是足够的;考虑到db time还包括一部分wait time,我们的cpu占用率会远远低于46%。
Db time主要用于对比同一系统的不同时段,或同一时段的不同系统来得到整体负载的初步映象,对比法是性能调整中,屡试不爽的重要法门!
Snap Id | Snap Time | Sessions | Cursors/Session | |
Begin Snap: | 571 | 31-May-10 08:00:16 | 472 | 56.9 |
End Snap: | 572 | 31-May-10 09:00:17 | 307 | 50.1 |
Elapsed: | 60.02 (mins) | |||
DB Time: | 1,139.42 (mins) |
这同样是一个16 core的系统,不同医院同一时段的系统,我们可以看到在会话数(sessions)与每个会话的平均cursor数量(Cursors/Session)都小于前一个系统的情况下(可以简单的理解为医院的规模和应用范围都小于前一个系统),db time大幅增加;总的db time达到了1139分钟,据此我们初步认为从整体来看第二个系统的性能是比较差的。
接下来我们来讨论一下cputime,cpu time在awr中也表示为db cpu,同时cpu time也是一个空闲等待事件,但这三者没有太大区别,时间值也是相同的。cpu time是Oracle对操作系统而言真正意义上的cpu消耗。那如何计算一个Oracle实例对操作系统的时间占比呢?很简单,公式如下:
Cpu time/ (Elapsed time * CPU cores)
在AWR中的top 5 waits或Time ModelStatistics都可以找到 cpu time:
Event | Waits | Time(s) | Avg Wait(ms) | % Total Call Time | Wait Class |
latch: cache buffers chains | 76,560 | 33,283 | 435 | 48.7 | Concurrency |
CPU time | 23,129 | 33.8 | |||
log file sync | 28,057 | 2,754 | 98 | 4.0 | Commit |
db file sequential read | 312,477 | 2,169 | 7 | 3.2 | User I/O |
log file parallel write | 24,580 | 633 | 26 | .9 | System I/O |
三、Time ModelStatistics
在awr中,Time ModelStatistics用于回答“到底前台进程消耗了多少时间?”,“语句解析消耗了多少时间?”等诸如此类的问题,我们来看一个例子:
Statistic Name | Time (s) | % of DB Time |
connection management call elapsed time | 21,708.46 | 15.22 |
sql execute elapsed time | 21,596.44 | 15.14 |
parse time elapsed | 17,648.50 | 12.37 |
hard parse elapsed time | 9,081.89 | 6.37 |
hard parse (sharing criteria) elapsed time | 4,158.48 | 2.92 |
hard parse (bind mismatch) elapsed time | 3,189.62 | 2.24 |
PL/SQL execution elapsed time | 2,362.21 | 1.66 |
DB CPU | 2,311.28 | 1.62 |
PL/SQL compilation elapsed time | 145.25 | 0.10 |
failed parse elapsed time | 89.78 | 0.06 |
sequence load elapsed time | 69.16 | 0.05 |
repeated bind elapsed time | 0.21 | 0.00 |
DB time | 142,622.31 | |
background elapsed time | 4,871.65 | |
background cpu time | 22.41 |
我们看到,真于用于sql执行的时间(sql execute elapsed time)只占到了15.14%;这个比率是非常低的,作来一个相对正常的系统,这一比率不应低于90%甚至更高!我们看到用于连接管理(connection management call elapsed time)的时间为15%,用于sql解析(parse time elapsed)的时为12.37%,且其中硬解析sql(hard parse elapsed time)的时间为6.37%。从这几个方面来看,我们可以作一些合理的推测:
1. 系统是否存在频繁连接和断开连接的情况?如果存在这种情况,是否是网络不稳定,或者监听程序存在问题造成了这个情况?还有就是中间件到数据库服务器的连接池是否出了问题?
2. Sql语句解析不合理;这是否因为共享池设置过小?应用程序是否未使用绑定变量?还是因为开启了SGA自动管理,带来了严重的内存颠簸现象?
可以看到,通过对时间模型的分析,可以帮助我们结合等待事件、latch信息等内容而对性能问题作出更为准确的判断。
四、操作系统相关的信息
Awr中也采集了部分操作系统的信息,特别是到了11g,更进一步的帮我们计算出了cpu占用率,非常方便;awr中的Operating System Statistics部分:
NUM_LCPUS | 0 |
NUM_VCPUS | 0 |
AVG_BUSY_TIME | 149,127 |
AVG_IDLE_TIME | 211,742 |
AVG_IOWAIT_TIME | 40,260 |
AVG_SYS_TIME | 14,015 |
AVG_USER_TIME | 135,004 |
BUSY_TIME | 2,387,903 |
IDLE_TIME | 3,389,758 |
IOWAIT_TIME | 646,085 |
SYS_TIME | 225,900 |
USER_TIME | 2,162,003 |
LOAD | 0 |
OS_CPU_WAIT_TIME | 2,474,600 |
RSRC_MGR_CPU_WAIT_TIME | 0 |
PHYSICAL_MEMORY_BYTES | 49,123,688,448 |
NUM_CPUS | 16 |
NUM_CPU_CORES | 8 |
从图中,我们可以得到cpu数量、busy_time、idle_time、iowait_time、物理内存等信息,对于我们了解系统级的性能信息很有帮助。比如我可以透过如下公式来计算awr采集期间的平均cpu占用率:
BUSY_TIME/( BUSY_TIME+ IDLE_TIME) * 100%
具体到我们的例子,2,387,903/(2,387,903+3,389,758)*100%=41.33%。当然这里的cpu占用率,是从操作系统层面来看的,并不是Oracle实例的cpu占用情况,因为主机可以运行了其他Oracle实例、或者中间件之类的其他软件系统。同时,我们也可以通过IOWAIT_TIME来初步判断我们的系统是否存在io瓶颈。
五、多关注平均时间
“平均”是一个很有意思的话题,大家对平均的最直观的感受就是统计局发布“XX地区平均收入已经突破XX元”,很多人都会发出“拖伟大祖国的后腿了!”这样的感叹。根据平均理论:即使我们的头被火烧,脚浸泡在冰水里,也不会感到难受!这种情况在AWR的分析中也是需要注意的。
Awr采集的是一段时间整体性能数据,可能平均数据看起来没有问题,但前端用户可能还是感觉慢,因为某些次数的长时间等待被其他较短时间的等待给“平均”掉了!这就需要我们区别不同的类型的问题,可能这些问题并不适合awr来诊断,而应该选用更合适的ash、sql trace等工具进行诊断。但这并说明“平均”的时间没有任何价值,只是需要具体问题具体分析。
我们这里谈一下等待事件的平均等待时间:
Top 5 Timed Events
Event | Waits | Time(s) | Avg Wait(ms) | % Total Call Time | Wait Class |
CPU time | 17,217 | 54.5 | |||
db file sequential read | 1,155,423 | 8,422 | 7 | 26.6 | User I/O |
db file scattered read | 30,541 | 660 | 22 | 2.1 | User I/O |
gc current block 2-way | 900,865 | 538 | 1 | 1.7 | Cluster |
gc cr grant 2-way | 467,627 | 244 | 1 | .8 | Cluster |
对于IO类型的等待事件来说,比如常见的db file sequential read平均等待时间一般不要超过10ms,这是根据当前硬盘的机械结构、转速等得出的一个经验值,因为单块10000转的普通磁盘,寻道时间在7-10ms左右。当然,如果考虑存储缓存、文件系统缓存、IO大小等情况,这个值一般在4-7ms之间;同时必须是IO系统在正常的iops(每秒的io次数,用于衡量存储并发吞量)下才有意义。如果超过经验值很多,就要分析具体的原因了,可能是存储的缓存功能没有启用、raid组中的磁盘损坏、不合理的raid级别等各种原因;当然也有可能是系统io负载过大,存储的负担较重,如果是这种情况就需要给合应用的io量(物理读与逻辑读),特别是sql的io情况来分析了。
我们再来看一个真实的案例:
Top 5 Timed Foreground Events
Event | Waits | Time(s) | Avg wait (ms) | % DB time | Wait Class |
db file sequential read | 561,555 | 37,163 | 66 | 34.73 | User I/O |
read by other session | 405,945 | 20,251 | 50 | 18.92 | User I/O |
log file sync | 30,655 | 15,101 | 493 | 14.11 | Commit |
direct path read | 171,963 | 12,254 | 71 | 11.45 | User I/O |
DB CPU | 9,907 | 9.26 |
我们看到整个系统的等待事件主要集中在IO上。db file sequential read的平均等待时间为66ms,而log filesync达到了惊人的493ms,也就是近0.5秒。log file sync一般由事务提交引起,也就是说一个事务光在提交上,就需要花费0.5s!请记住,这还是一个平均数,还有很多事务,是远远大于这个时间的!最终检查出来的原因是医院的存储使用了7200转的sata硬盘构建的RAID5,这样的配置对于ZLHIS这样的oltp系统来说,无疑就是灾难!
六、也说一下次数
前面谈的都是“时间”,下面我们来谈一下次数,同时作为本文的结束。首先,一些latch相关的等待事件,与latch中的sleep的次数相一致!比如library cache lock/pin、latch:shared pool等。比如:
Event | Waits | %Time -outs | Total Wait Time (s) | Avg wait (ms) | Waits /txn |
rdbms ipc reply | 1,622 | 0.00 | 1 | 0 | 0.05 |
latch: cache buffers chains | 3,941 | 0.00 | 1 | 0 | 0.12 |
这里我们可以看到,等待事件latch:cache buffers chains的等待次数为3941次,相应的latch统计信息如下:
Latch Name | Get Requests | Misses | Sleeps | Spin Gets | Sleep1 | Sleep2 | Sleep3 |
cache buffers chains | 3,686,756,120 | 7,504,592 | 3,941 | 7,505,392 | 0 | 0 |
可以看到两者确实是相等的,也就是说只有latch获取过程中,sleep的操作才会产生一次对应的等待事件。
最后还是回到我们的时间模型上来,如果我们的系统只运行了一个数据库实例,则cpu time与busy time扣除io wait time后,应该是基本一致,来看一下案例:
Top 5 Timed Events
Event | Waits | Time(s) | Avg Wait(ms) | % Total Call Time | Wait Class |
CPU time |
| 17,217 |
| 54.5 |
|
db file sequential read | 1,155,423 | 8,422 | 7 | 26.6 | User I/O |
db file scattered read | 30,541 | 660 | 22 | 2.1 | User I/O |
gc current block 2-way | 900,865 | 538 | 1 | 1.7 | Cluster |
gc cr grant 2-way | 467,627 | 244 | 1 | .8 | Cluster |
Operating System Statistics
Statistic | Total |
NUM_LCPUS | 0 |
NUM_VCPUS | 0 |
AVG_BUSY_TIME | 149,127 |
AVG_IDLE_TIME | 211,742 |
AVG_IOWAIT_TIME | 40,260 |
AVG_SYS_TIME | 14,015 |
AVG_USER_TIME | 135,004 |
BUSY_TIME | 2,387,903 |
IDLE_TIME | 3,389,758 |
IOWAIT_TIME | 646,085 |
SYS_TIME | 225,900 |
USER_TIME | 2,162,003 |
LOAD | 0 |
OS_CPU_WAIT_TIME | 2,474,600 |
RSRC_MGR_CPU_WAIT_TIME | 0 |
PHYSICAL_MEMORY_BYTES | 49,123,688,448 |
NUM_CPUS | 16 |
NUM_CPU_CORES | 8 |
cpu time为17,217s,也就是17,217000ms;
busy_time-iowait_time为:1741818ms(387,903-646,085)
可以看到两者基本相近;如果两者相差过大,就表示服务器上可能运行了其他程序或者其他的Oracle实例。
七、RAC性能
如果使用了RAC架构,需要特别关注RAC相关的时间要素,还是通过一个案例来说明:
Avg global enqueue get time (ms): | 2.5 |
Avg global cache cr block receive time (ms): | 172.2 |
Avg global cache current block receive time (ms): | 6.6 |
Avg global cache cr block build time (ms): | 0.0 |
Avg global cache cr block send time (ms): | 0.0 |
Global cache log flushes for cr blocks served %: | 13.6 |
Avg global cache cr block flush time (ms): | 0.8 |
Avg global cache current block pin time (ms): | 0.2 |
Avg global cache current block send time (ms): | 0.0 |
Global cache log flushes for current blocks served %: | 0.3 |
Avg global cache current block flush time (ms): | 3.2 |
这些值的官方数字从几ms到10ms不等,但我们这里的Avg global cache cr block receive time (ms)达到了惊人的172.2ms,这个指标表示,Oracle实例接收全局的CR块(一致性读数据块)的平均时间,这表示RAC中,各个节点间的热块急用是相当严重,需要在底层打散IO或者调整应用,减少总的IO量,并降低各个节点访问相同数据块的机率。具体的打散IO热点的技术,请参照其他文档。
八、总结
最后需要提及一点的就是awr中使用“时间”对SQL作出较多的分类,以便于我们找到消耗某类”时间”最多的sql语句,主要包括:
l SQL ordered by Cluster Wait Time
比如,我们可以通过SQLordered by Elapsed Time来找到执行时间最慢的sql,通过SQL ordered by CPU Time最消耗cpu的sql等等。
还有就是IO部分,awr也提供了表空间与数据文件的io响应时间,也对于我们分散IO热点区域,在存储底层进行性能调整提供了有价值的参考。
透过前面对awr时间模型的讨论,我们可以看到awr提供给我们的很多数据,之间有非常紧密的联系;这就要求我们在对awr作分析时,不能孤立的看待某些指标,需要结合不同的内容来相互映证,同时结合应用的特点、环境变更、硬件条件等方面来作出正确的判断。