一般来说一条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操作了。这样问题就能够基本定位了。 有了这些信息,就可以和开发部门协调。看看下一步该怎么改进了。