AWR是我们进行Oracle性能调整的主要工具之一;一般情况而言,时间是衡量性能好坏的一个重要指标,AWR中有很多与时间相关的内容和指标。先来看一下Oracle定义的响应时间公式:

Response time = Service time + Wait time

服务时间(Service time)就是进程“真正”在cpu上运行的时间,可以简单理解为AWR中的cpu time/db cpu,服务时间包括前台进程( Server process)和后台进程(Backgroud process)消耗的时间。等待时间就是等待某种资源的时间耗费,比如等待锁资源的耗费,可以简单对应为awr中的wait time, 等待时间包括很多类型,一般最常见的是IO等待和并发等待,比如进程等待从物理磁盘读取数据块到内存中的等待。 Awr中的db time可以简单对应为Response time;
 
l db time与cpu time
首先需要说明一个概念:时间片。现代操作系统(unix/Linux)将cpu资源划分成时间片(cpu slice)为单位来使用,一般是一个很小的值,一般为10ms。操作系统使用一个调度程序(比如linux的CFS调度器,来协调各个进程使用cpu资源。更详细的内容超出了本文的讨论范围,有兴趣的可以参考操作系统相关的文档。对于操作系统而言,一个进程要么在cpu中运行,要么处于等待队列中;注意这里的“等待”并不完全等同于os中的等待。
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分钟,据此我们初步认为从整体来看第二个系统的性能是比较差的。
接下来我们来讨论一下cpu time,cpu time在awr中也表示为db cpu,同时cpu time也是一个空闲等待事件,但这三者没有太大区别,时间值也是相同的。cpu time是Oracle对操作系统而言真正意义上的cpu消耗。那如何计算一个Oracle实例对操作系统的时间占比呢?很简单,公式如下:

Cpu time/ (Elapsed  time * CPU cores)

在AWR中的top 5 waits或Time Model Statistics都可以找到 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
 
l Time Model Statistics

在awr中,Time Model Statistics用于回答“到底前台进程消耗了多少时间?”,“语句解析消耗了多少时间?”等诸如此类的问题,我们来看一个例子:

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瓶颈。
 
l 五、多关注平均时间
“平均”是一个很有意思的话题,大家对平均的最直观的感受就是统计局发布“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 file sync达到了惊人的493ms,也就是近0.5秒。log file sync一般由事务提交引起,也就是说一个事务光在提交上,就需要花费0.5s!请记住,这还是一个平均数,还有很多事务,是远远大于这个时间的!最终检查出来的原因是医院的存储使用了7200转的sata硬盘构建的RAID5,这样的配置对于ZLHIS这样的oltp系统来说,无疑就是灾难!
 
l 也说一下次数

前面谈的都是“时间”,下面我们来谈一下次数,同时作为本文的结束。首先,一些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 Elapsed Time
l   SQL ordered by CPU Time
l   SQL ordered by Cluster Wait Time
比如,我们可以通过SQL ordered by Elapsed Time来找到执行时间最慢的sql,通过SQL ordered by CPU Time最消耗cpu的sql等等。
还有就是IO部分,awr也提供了表空间与数据文件的io响应时间,也对于我们分散IO热点区域,在存储底层进行性能调整提供了有价值的参考。
透过前面对awr时间模型的讨论,我们可以看到awr提供给我们的很多数据,之间有非常紧密的联系;这就要求我们在对awr作分析时,不能孤立的看待某些指标,需要结合不同的内容来相互映证,同时结合应用的特点、环境变更、硬件条件等方面来作出正确的判断。