最近处理一个问题的时候，先是收到DB time升高的报警，然后查看DB time的情况发现，已经有近1000%的负载了。带着好奇心想看看到底是什么样的一个语句导致如此的情况。先抓取了一个awr报告，因为问题发生的时间段比较集中而且时间持续有几个小时，所以抓取了一个小时的快照。得到的awr部分内容如下：Cache Sizes
| | Begin | End | | |
|---|
| Buffer Cache: | 39,472M | 39,472M | Std Block Size: | 8K |
| Shared Pool Size: | 1,440M | 1,440M | Log Buffer: | 14,256K |
从下面的部分可以看出数据库其实内部的活动并不多，redo生成量不高，tps也不高。
Load Profile
| | Per Second | Per Transaction |
|---|
| Redo size: | 154,276.41 | 24,024.13 |
| Logical reads: | 4,864.90 | 757.57 |
| Block changes: | 779.75 | 121.42 |
| Physical reads: | 509.53 | 79.35 |
| Physical writes: | 359.90 | 56.04 |
| User calls: | 2,658.46 | 413.98 |
| Parses: | 837.89 | 130.48 |
| Hard parses: | 0.09 | 0.01 |
| Sorts: | 171.22 | 26.66 |
| Logons: | 0.47 | 0.07 |
| Executes: | 949.10 | 147.80 |
| Transactions: | 6.42 | |
而查看等待时间，发现第一个等待事件是db file sequential read,平均等待时间有近17ms,延迟一般需要在10ms以下,或者至少100 reads/sec，在基于SAN存储缓存数据的情况下，sequential read的指标有时候会保持在2ms左右，这个只能说明SAN已经把数据转化为缓存了，倒不能说明硬盘驱动确实很快。这个地方已经超过了10ms说明IO上还是存在较大的影响。我们先放过这个问题，继续往下看。
| Event | Waits | Time（s） | Avg Wait（ms） | % Total Call Time | Wait Class |
|---|
| db file sequential read | 917,810 | 15,310 | 17 | 96.1 | User I/O |
| CPU time | | 596 | | 3.7 | |
| log file sync | 16,085 | 186 | 12 | 1.2 | Commit |
| log file parallel write | 15,466 | 140 | 9 | .9 | System I/O |
| ARCH wait on SENDREQ | 374 | 10 | 27 | .1 | Network |
而根据时间模型来看，绝大部分的DB time都在sql语句方面，所以关注sql语句就是一个很重要的部分。
| Statistic Name | Time （s） | % of DB Time |
|---|
| sql execute elapsed time | 15,533.43 | 97.47 |
| DB CPU | 596.11 | 3.74 |
| connection management call elapsed time | 82.89 | 0.52 |
| parse time elapsed | 20.22 | 0.13 |
而对于top1的sql语句让自己和吃惊，竟然是一个很简单的update.
| Elapsed Time （s） | CPU Time （s） | Executions | Elap per Exec （s） | % Total DB Time | SQL Id | SQL Module | SQL Text |
|---|
| 8,659 | 69 | 622 | 13.92 | 54.34 | 94p345yuqh3zd | | update user_test t set t.login_status="" where t.CN_TEST=:1 |
第一感觉就是这个语句走了全表扫描，因为一个简单的Update竟然需要花费近13秒的时间，已经算很长的了。
当然猜测也需要验证，我们来看看awrsqrpt的结果。
发现这个报告还是蛮有意思。至于执行计划是走了唯一性索引扫描，所以执行计划的情况来看还是没有问题的。
| Id | Operation | Name | Rows | Bytes | Cost （%CPU） | Time |
|---|
| 0 | UPDATE STATEMENT | | | | 1 （100） | |
| 1 | UPDATE | USER_BILLING | | | | |
| 2 | INDEX UNIQUE SCAN | IDX_USER_TEST_CNMASTER | 1 | 30 | 1 （0） | 00:00:01 |
但是查看sql语句的执行统计信息，就有些奇怪了。
| Stat Name | Statement Total | Per Execution | % Snap Total |
|---|
| Elapsed Time （ms） | 8,659,180 | 13,921.51 | 54.34 |
| CPU Time （ms） | 69,346 | 111.49 | 11.63 |
| Executions | 622 | | |
| Buffer Gets | 3,146,068 | 5,057.99 | 35.91 |
| Disk Reads | 645,229 | 1,037.35 | 70.31 |
| Parse Calls | 622 | 1.00 | 0.04 |
| Rows | 621,827 | 999.72 | |
| User I/O Wait Time （ms） | 8,608,075 | |
sql语句的执行总共持续8659s左右，然后8608s的时间在user I/O的等待上，这样下来，622次的执行其实花费的时间并不多。
对于这个问题，自己也比较疑惑，开始怀疑是否是磁盘的IO上出现了问题。
但是使用MegaCli查看的时候，发现不存在任何的坏块。
# MegaCli -CfgDsply -a0|grep Error
Media Error Count: 0
Other Error Count: 0
Media Error Count: 0
Other Error Count: 0
Media Error Count: 0
Other Error Count: 0
Media Error Count: 0
Other Error Count: 0
Media Error Count: 0
Other Error Count: 0
Media Error Count: 0
Other Error Count: 0
Media Error Count: 0
这个时候的一个猜测就是可能由绑定变量的数据类型不同导致的sql性能问题。但是排查一番，发现还是没有得到自己期望的结果。
查看输入的参数类型，都是期望中的varchar2，所以sql语句的过程中还是不会出现自己猜想的全表扫描的可能性。
select name,datatype_string,value_string,datatype from DBA_HIST_SQLBIND where sql_id="94p345yuqh3zd" and snap_id between 58711 and 58712
NAME DATATYPE_STRING VALUE_STRING DATATYPE
------------------------------ --------------- ------------------------------ ----------
:1 VARCHAR2（128） xxxxxx9@test.com 1
:1 VARCHAR2（128） 23234324324234 1
对于IO的瓶颈问题，自己还是从addm中得到了自己需要的东西。
对于磁盘吞吐量的说法，addm的报告中是这么描述的。FINDING 6: 39% impact （6136 seconds）
------------------------------------
The throughput of the I/O subsystem was significantly lower than expected. RECOMMENDATION 1: Host Configuration, 39% benefit （6136 seconds）
ACTION: Consider increasing the throughput of the I/O subsystem.
Oracle"s recommended solution is to stripe all data file using the
SAME methodology. You might also need to increase the number of disks
for better performance. Alternatively, consider using Oracle"s
Automatic Storage Management solution.
RATIONALE: During the analysis period, the average data files" I/O
throughput was 3.9 M per second for reads and 2.7 M per second for
writes. The average response time for single block reads was 16
milliseconds.
这个部分还是能够说明问题的，在IO上还是遇到了较大的瓶颈。这些延迟等待是造成DB time急剧升高的主因。
当然了我们也不能按照addm的说法，直接替换成asm，这个不是马上能够实现的方法。
但是在awr报告中还是发现了一丝蛛丝马迹，有一些辅助的调优方法。
第一个就是shared pool的大小，这个库大概有1000个session,但是因为使用了sga的自动管理，结果shared pool被30G的空间中只剩下了1.4G左右的缓存，很明显对于支持1000多个session的库来说，shard pool被压榨的太多了，可以指定一个稍大一些的值，保证shared pool不被全部榨干。
另外一个问题就是update执行如此缓慢，出了user I/O的原因之外，可以一个执行极为频繁的sql语句扫描的是同一张表，会造成一些热块的争用。同时会为了支持一致性读，势必在undo上会有较大的消耗，查看了这个库的undo还是一个相对较小的值，可以调大一些。
本文永久更新链接地址 
易网时代-编程资源站