一条执行4秒的sql语句导致的系统问题(r3笔记第10天)
公众号：杨建荣的学习笔记 · 作者：r3笔记第10天 · 发布：2014-09-29 23:01:39 · 原文链接
一般来说一条sql语句执行个4秒钟是可以接受的，没有什么问题，但是如果应该执行1秒，却执行了4秒，问题就挺大的了。
今天查看数据库负载，发现在中午12:00 到1点之间，数据库的负载急剧增加，负载达到了百倍。
| Snap Id | Snap Time | Sessions | Cursors/Session | |
|---|---|---|---|---|
| Begin Snap: | 15106 | 29-Sep-14 12:00:07 | 1602 | 7.3 |
| End Snap: | 15107 | 29-Sep-14 13:00:13 | 2807 | 9.7 |
| Elapsed: | 60.10 (mins) | |||
| DB Time: | 8,575.93 (mins) |
为了一看究竟，抓取了一个awr报告。
发现系统的负载情况确实很严重，每秒的redo有1.6M,可见系统的负载不是主要在select上，可能有一些dml之类的操作极为频繁。
| Per Second | Per Transaction | Per Exec | Per Call | |
|---|---|---|---|---|
| DB Time(s): | 142.7 | 1.7 | 0.04 | 0.03 |
| DB CPU(s): | 5.9 | 0.1 | 0.00 | 0.00 |
| Redo size: | 1,694,755.6 | 20,724.1 | ||
| Logical reads: | 671,861.2 | 8,215.8 | ||
| Block changes: | 6,638.8 | 81.2 | ||
| Physical reads: | 51,477.6 | 629.5 | ||
| Physical writes: | 1,075.6 | 13.2 | ||
| User calls: | 5,458.5 | 66.8 | ||
| Parses: | 1,247.7 | 15.3 | ||
| Hard parses: | 2.0 | 0.0 | ||
| W/A MB processed: | 34.3 | 0.4 | ||
| Logons: | 1.9 | 0.0 | ||
| Executes: | 3,522.4 | 43.1 | ||
| Rollbacks: | 0.5 | 0.0 | ||
| Transactions: | 81.8 |
看了下等待事件。都是关于lock的。这个时候就有些纳闷了。到底什么样的操作会导致严重的锁等待。
Top 5 Timed Foreground Events
| Event | Waits | Time(s) | Avg wait (ms) | % DB time | Wait Class |
|---|---|---|---|---|---|
| enq: TX – row lock contention | 1,132,995 | 235,312 | 208 | 45.73 | Application |
| log file sync | 305,880 | 120,935 | 395 | 23.50 | Commit |
| db file sequential read | 35,361,005 | 110,402 | 3 | 21.46 | User I/O |
| DB CPU | 21,248 | 4.13 | |||
| read by other session | 259,224 | 17,942 | 69 | 3.49 | User I/O |
首先DB time极高，这个时候就可以关注一些elapsed time比较高的sql语句。
可以看到第一个sql语句占用了大量的时间，而且是一个dml语句。后面的几个都是select相关的，占用的比例不是很大，就没有全列出来。
| Elapsed Time (s) | Executions | Elapsed Time per Exec (s) | %Total | %CPU | %IO | SQL Id | SQL Module | SQL Text |
|---|---|---|---|---|---|---|---|---|
| 235,032.84 | 57,646 | 4.08 | 45.68 | 0.06 | 0.00 | cws3pma51s3tf | JDBC Thin Client | update EC1_USER set SYS_UPDAT… |
| 14,459.33 | 0 | 2.81 | 30.97 | 70.80 | 7wx3cgjqsmnn4 | ORACLE.EXE | SELECT “A3″.”SUBSCRIBER_NO”, “… | |
| 11,493.79 | 375,757 | 0.03 | 2.23 | 0.88 | 99.41 | bhm5y9tb096qd | JDBC Thin Client | selectNameAd… |
这个时候怎么把这条sql语句和对应的等待时间关联起来呢，如果为了清晰方便，可以使用ash。
Top SQL with Top Events
| SQL ID | Planhash | Sampled # of Executions | % Activity | Event | % Event | Top Row Source | % RwSrc | SQL Text |
|---|---|---|---|---|---|---|---|---|
| cws3pma51s3tf | 3040658791 | 5229 | 55.84 | enq: TX – row lock contention | 55.82 | UPDATE | 55.82 | update EC1_USER set SYS_UPDAT… |
| bhm5y9tb096qd | 1654978926 | 324 | 2.32 | db file sequential read | 1.62 | INDEX – RANGE SCAN | 0.48 | selectNameAd… |
| 7wx3cgjqsmnn4 | 418872265 | 4 | 2.30 | db file sequential read | 1.58 | TABLE ACCESS – FULL | 1.10 | SELECT “A3″.”SUBSCRIBER_NO”, “… |
| c0m89v4d91uhh | 799822736 | 160 | 1.35 | read by other session | 0.82 | INDEX – UNIQUE SCAN | 0.46 | selectS… |
问题基本确定了，是这条Update语句的执行极为频繁，但是执行时间达到了4秒。一个小时以内执行了5万多次。
但是为什么sql语句的执行时间这么长呢，是不是没有走索引，在简单排查了一下，索引是启用了的。
抓了一个awrsqrpt的报告。可以看到执行计划中的唯一性索引是启用了的，而且查取效率很多。0.01秒就查到了对应的记录，对于update的部分，不会那么慢把。
Execution Plan
| Id | Operation | Name | Rows | Bytes | Cost (%CPU) | Time |
|---|---|---|---|---|---|---|
| 0 | UPDATE STATEMENT | 1 (100) | ||||
| 1 | UPDATE | EC1_USER | ||||
| 2 | INDEX UNIQUE SCAN | EC1_USER_PK | 1 | 102 | 1 (0) | 00:00:01 |
这个时候怎么解释执行计划效率很高，但是执行时间却很长的问题。
第一个猜想就是系统的负载加大了，可能查取数据的时候就慢了。但是反过来说，也不会慢这么高的比例啊。
所以这种猜想不成立的。
第二个猜想就是有大量的并发dml,同时做update,导致其他的一些Update就在等待。当然这种设计是有问题的。
但是时间已经过去了很久，v$session里面早就没有对应的记录了。怎么验证自己的猜想呢。
还是使用ash。里面有一个章节是blocking sessions的细节。
| Blocking Sid (Inst) | % Activity | Event Caused | % Event | User | Program | # Samples Active | XIDs |
|---|---|---|---|---|---|---|---|
| 2647, 1( 1) | 16.74 | log file sync | 16.74 | SYS | oracle@xxxx(LGWR) | 97/360 [ 27%] | 0 |
| 2909,15473( 1) | 3.77 | enq: TX – row lock contention | 3.77 | ECC | JDBC Thin Client | 45/360 [ 13%] | 0 |
| 3624,52345( 1) | 3.01 | enq: TX – row lock contention | 3.01 | ECC | JDBC Thin Client | 44/360 [ 12%] | 1 |
| 6453,29237( 1) | 2.83 | enq: TX – row lock contention | 2.83 | ECC | JDBC Thin Client | 18/360 [ 5%] | 0 |
| 793,65345( 1) | 2.79 | enq: TX – row lock contention | 2.79 | ECC | JDBC Thin Client | 65/360 [ 18%] | 0 |
通过这个就能看到有4个并发的session在同时做dml操作了。这样问题就能够基本定位了。
有了这些信息，就可以和开发部门协调。看看下一步该怎么改进了。