关于等待事件"read by other session"(r3笔记第89天)
关于等待事件"read by other session"(r3笔记第89天)
在查看数据库负载的时候，发现早上10点开始到12点的这两个钟头，系统负载异常的高。于是抓取了一个awr报告。
Snap Id | Snap Time | Sessions | Cursors/Session | |
|---|---|---|---|---|
Begin Snap: | 24027 | 18-Dec-14 10:00:43 | 3065 | 6.6 |
End Snap: | 24033 | 18-Dec-14 11:00:48 | 3441 | 6.5 |
Elapsed: | 60.08 (mins) | |||
DB Time: | 3,650.67 (mins) |
可以从profile里看到，系统的IO负载还是很高的。 Load Profile
Per Second | Per Transaction | Per Exec | Per Call | |
|---|---|---|---|---|
DB Time(s): | 60.8 | 1.2 | 0.02 | 0.01 |
DB CPU(s): | 10.2 | 0.2 | 0.00 | 0.00 |
Redo size: | 1,835,598.3 | 35,780.1 | ||
Logical reads: | 1,910,437.0 | 37,238.9 | ||
Block changes: | 4,923.1 | 96.0 | ||
Physical reads: | 182,370.1 | 3,554.8 | ||
Physical writes: | 1,670.7 | 32.6 | ||
User calls: | 7,331.1 | 142.9 | ||
Parses: | 2,128.1 | 41.5 | ||
Hard parses: | 8.4 | 0.2 | ||
W/A MB processed: | 48.0 | 0.9 | ||
Logons: | 3.5 | 0.1 | ||
Executes: | 3,911.2 | 76.2 | ||
Rollbacks: | 1.5 | 0.0 | ||
Transactions: | 51.3 |
等待事件的情况如下：
Top 5 Timed Foreground Events
Event | Waits | Time(s) | Avg wait (ms) | % DB time | Wait Class |
|---|---|---|---|---|---|
db file sequential read | 24,806,147 | 91,539 | 4 | 41.79 | User I/O |
read by other session | 20,260,140 | 37,030 | 2 | 16.91 | User I/O |
DB CPU | 36,766 | 16.79 | |||
direct path read | 3,090,582 | 30,292 | 10 | 13.83 | User I/O |
log file sync | 191,401 | 7,738 | 40 | 3.53 | Commit |
看完awr报告，大概能够定位是sql的问题了，直接生成了一个addm报告，作为参考。最后确认发现的几个问题sql已经在修复了，还没有部署到生产中。 今天想仔细的分析一下，毕竟很多东西都是在实践中总结出来的。 对于read by other session自己还是比较陌生的。 从metalink的描述来看。这个等待事件是在10g之后对于buffer busy waits 的一个细分。(MOS ID "Read By Other Session" Wait Event (Doc ID 732891.1)) This wait event occurs when we are trying to access a buffer in the buffer cache but we find that the buffer is currently being read from disk by another user so we need to wait for that to complete before we can access it. In previous versions, this wait was classified under the "buffer busy waits" event. However, in Oracle 10.1 and higher, the wait time is now broken out into the "read by other session" wait event.
Excessive waits for this event are typically due to several processes repeatedly reading the same blocks, e.g. many sessions scanning the same index or performing full table scans on the same table. Tuning this issue is a matter of finding and eliminating this contention.
对于这个等待事件可以结合awr和ash来进行排查。 首先我们在awr报告中已经得知这个等待事件，一般都会存在sequential read。但是通过awr不能清晰的定位出哪些sql语句和这个等待事件相关。 使用ash可以把时间段有针对性的调整在一个合理的范围。如果问题已经发生了一段时间，我们可以通过历史数据能够大体定位。 Top SQL with Top Events
SQL ID | Planhash | Sampled # of Executions | % Activity | Event | % Event | Top Row Source | % RwSrc | SQL Text |
|---|---|---|---|---|---|---|---|---|
guqd44uzkyy56 | 3622987757 | 73 | 8.72 | direct path read | 6.48 | TABLE ACCESS - FULL | 6.48 | SELECT /*+leading(CYC_CUST) p... |
db file sequential read | 1.30 | INDEX - RANGE SCAN | 0.80 | |||||
a6a7y2bsmmpjb | 2808023112 | 4 | 8.54 | CPU + Wait for CPU | 4.42 | INDEX - UNIQUE SCAN | 1.41 | SELECT COUNT(1) FROM (/* |
db file sequential read | 2.28 | INDEX - UNIQUE SCAN | 1.74 | |||||
read by other session | 1.56 | INDEX - UNIQUE SCAN | 1.56 | |||||
fg5mc598u799u | 2134445868 | 6 | 7.24 | db file sequential read | 3.58 | TABLE ACCESS - BY INDEX ROWID | 2.61 | select /*+ leading (bpm_ai bpm... |
read by other session | 2.14 | TABLE ACCESS - BY INDEX ROWID | 1.88 | |||||
db file parallel read | 1.12 | TABLE ACCESS - BY INDEX ROWID | 1.12 | |||||
6h6dj1tnz3gwt | 1565267664 | 35 | 5.03 | direct path read | 4.71 | TABLE ACCESS - FULL | 4.71 | SELECT /*+parallel(CYC_PAY... |
6w3p95uqduya3 | 561414009 | 71 | 4.27 | direct path read | 3.87 | TABLE ACCESS - FULL | 3.87 | SELECT SUB.CUSTOMER_ID FROM SU... |
对于read by other session,和热点块也是相关的。 我们可以使用下面的sql语句来查看一下指定时间段内的等待事件的细节。 通过ash中的Top Event P1/P2/P3 Values能够直接找到。
Event | % Event | P1 Value, P2 Value, P3 Value | % Activity | Parameter 1 | Parameter 2 | Parameter 3 |
|---|---|---|---|---|---|---|
db file sequential read | 43.11 | "1","3386","1" | 0.04 | file# | block# | blocks |
direct path read | 25.62 | "5","756618","127" | 0.07 | file number | first dba | block cnt |
read by other session | 3.98 | "46","1609148","1" | 0.07 | file# | block# | class# |
db file scattered read | 2.53 | "3","116107","126" | 0.04 | file# | block# | blocks |
db file parallel read | 2.50 | "2","2","2" | 0.51 | files | blocks | requests |
或者通过如下的sql语句来看看对应的热点块。
SQL> SELECT relative_fno, owner, segment_name, segment_type FROM dba_extents
WHERE file_id = 46
AND 1609148 BETWEEN block_id AND block_id + blocks - 1;
RELATIVE_FNO OWNER SEGMENT_NAME SEGMENT_TYPE
------------ ------------------------------ --------------------------------------------------------------------------------- ------------------
20 APPO PAYMENT_DETAILS_PK INDEX PARTITION
a6a7y2bsmmpjb这条sql语句在文章(巧用rowid简化sql查询 http://blog.itpub.net/23718752/viewspace-1240404/)已经做了讨论。 但是不知道什么原因被遗漏了,和客户做了确认。 fg5mc598u799u这条sql语句是在产品线中统一规划的，已经使用Hint稳定了执行计划，但是涉及的几个表都是千万的大表，查询中使用了并行，同时需要在多台服务器中同时执行这条语句。这样的话，就会存在多个session执行 多个并行查询。从这个角度来说发生read by other session也是意料之中的。因为这个查询是一个分页查询，从操作上也可以做一些优化，目前是每隔10分钟做一次查询，然后查取1000条相关的数据。和业务部分协调的结果是，每隔半个小时执行一次查询，每次查取3000条数据。 可能一个等待事件中能够体现出一个表象。更多的细节还需要排查确认，很多优化工作不止能从数据库层面做，还可以从业务层面调整。 关于IO诊断的一些问题，可以参考 Troubleshooting I/O Related Waits (Doc ID 223117.1)