一条简单的sql语句导致的系统问题(r4笔记第51天)
一条简单的sql语句导致的系统问题(r4笔记第51天)
新年，给大家拜年了。祝大家工作顺利，万事如意。 今天照例简单检查了系统的情况，发现在客户的服务器在下午的3-5点这个时间段，数据库负载略有上升，但是幅度不大，因为生产的awr抓取频率是10分钟，所以还是能够通过awr分析出一些问题。 负载情况如下： 抓取了一个最新时间段的awr报告。 查看数据库负载，比平时的负载要高一些。
Host Name | Platform | CPUs | Cores | Sockets | Memory (GB) |
|---|---|---|---|---|---|
xxxxx | Linux x86 64-bit | 80 | 40 | 4 | 346.22 |
Snap Id | Snap Time | Sessions | Cursors/Session | |
|---|---|---|---|---|
Begin Snap: | 33108 | 19-Feb-15 15:40:21 | 5147 | 5.4 |
End Snap: | 33109 | 19-Feb-15 15:50:22 | 5256 | 5.5 |
Elapsed: | 10.01 (mins) | |||
DB Time: | 533.14 (mins) |
从这个概览来看还是看不出特别之处，只能对整体的情况有一个把握。这是一个10分钟的报告。 Load profile是我查看awr报告的重点部分。能够发现user calls和executions的值很高。
Load Profile
Convert to CSV
Per Second | Per Transaction | Per Exec | Per Call | |
|---|---|---|---|---|
DB Time(s): | 53.3 | 0.9 | 0.00 | 0.00 |
DB CPU(s): | 10.3 | 0.2 | 0.00 | 0.00 |
Redo size: | 2.2 MB | 37.4 KB | ||
Logical reads: | 10.3 GB | 179.3 MB | ||
Block changes: | 10,738.9 | 182.2 | ||
Physical reads: | 1.2 GB | 21.5 MB | ||
Physical writes: | 7.8 MB | 136.0 KB | ||
User calls: | 20,256.8 | 343.7 | ||
Parses: | 2,447.3 | 41.5 | ||
Hard parses: | 4.3 | 0.1 | ||
W/A MB processed: | 72.5 | 1.2 | ||
Logons: | 4.6 | 0.1 | ||
Executes: | 11,414.1 | 193.7 | ||
Rollbacks: | 0.6 | 0.0 | ||
Transactions: | 58.9 |
这个时候基本能够从load profile里面找到问题的方向了，user calls和executions的部分需要注意，首先问题的方向很可能是从sql语句级别导致的，语句执行的如此频繁，势必会对buffer gets有较大的影响，这个报告中parses的值很低，至少说明问题不是由于绑定变量导致的。我们可以查看等待事件基本确定时间都去哪了，哪些等待事件是需要重点关注的。然后在sql语句部分来分析了，基本可以从order by Elapsed time, order by Gets, order by Executions这三个部分来佐证了。 等待事件如下：
Top 5 Timed Foreground Events
Event | Waits | Time(s) | Avg wait (ms) | % DB time | Wait Class |
|---|---|---|---|---|---|
db file sequential read | 13,019,569 | 15,375 | 1 | 48.06 | User I/O |
enq: TX - row lock contention | 403 | 7,779 | 19303 | 24.32 | Application |
DB CPU | 6,185 | 19.34 | |||
direct path read | 425,941 | 1,882 | 4 | 5.88 | User I/O |
read by other session | 1,126,812 | 774 | 1 | 2.42 | User I/O |
从这个等待事件可以看出，大部分的等待事件都集中在IO部分，当然导致的原因也是多方面的。第2个等待事件至少可以说明表中存在着锁，这个也可能是导致数据库负载增加的一个原因，在通过监控记录查看，或者抓取一个ash报告就能够基本定位出那个时间段的锁细节。已经做了确认，发现某一个process存在很多的并发dml操作，抓取了相应的信息交给了开发处理。 但是这个问题和load profile中的user calls,executions的值过高应该没有太大的关系。我们来直接进入sql信息部分。
SQL ordered by Elapsed Time
Elapsed Time (s) | Executions | Elapsed Time per Exec (s) | %Total | %CPU | %IO | SQL Id | SQL Module | SQL Text |
|---|---|---|---|---|---|---|---|---|
01:39:59 | 1,344 | 4.46 | 18.75 | 0.33 | 0.00 | dch8sxwt6ujvc | JDBC Thin Client | /* CL_ProcessController_update... |
01:25:38 | 95 | 54.08 | 16.06 | 6.94 | 96.79 | 6csnjz5kqcffm | bl1extract@ccbdbpr1 (TNS V1-V3) | SELECT /*+ leading (list payp... |
2,612.67 | 206 | 12.68 | 8.17 | 8.55 | 94.69 | ffnjuh9qz1wy8 | bl1extract@ccbdbpr1 (TNS V1-V3) | SELECT /*+ leading (cust rate ... |
1,800.85 | 519 | 3.47 | 5.63 | 0.01 | 0.00 | ffv3am85ccm25 | JDBC Thin Client | /* AC_AcCloseUpdateAcControl_u... |
1,554.22 | 13 | 119.56 | 4.86 | 17.15 | 86.22 | fg5mc598u799u | JDBC Thin Client | select /*+ leading (bpm_ai bpm... |
1,476.63 | 13 | 113.59 | 4.62 | 30.53 | 66.68 | 4gz51fphuarsw | JDBC Thin Client | /* CL_ProcInstScanner_selectAv... |
952.12 | 361,344 | 0.00 | 2.98 | 12.69 | 92.74 | 62h1u7vsgjx9p | bl1extract@ccbdbpr1 (TNS V1-V3) | /* */ SELECT CUSTOMER_ID, SUBS... |
924.90 | 13 | 71.15 | 2.89 | 30.09 | 66.53 | 6fu3z8pqd2y9g | JDBC Thin Client | /* CL_WaitScanner_selectWorkab... |
600.66 | 0 | 1.88 | 8.85 | 94.53 | 1taqbbq0mw35u | JDBC Thin Client | SELECT OK.BAN, OK.MSISDN, OK.P... | |
565.49 | 0 | 1.77 | 4.19 | 97.80 | cqrms45fqwvr3 | JDBC Thin Client | /* Formatted on 2012/04/26 16:... | |
514.37 | 2,552,072 | 0.00 | 1.61 | 99.27 | 0.00 | 0mynq29fmat7d | getdate_int@ccbdbpr1 (TNS V1-V3) | select TO_CHAR(LOGICAL_DATE, '... |
SQL ordered by Gets
- Buffer GetsExecutionsGets per Exec%TotalElapsed Time (s)%CPU%IOSQL IdSQL ModuleSQL Text1.2 TB2,552,072486.9 KB19.12514.3799.270.000mynq29fmat7dgetdate_int@ccbdbpr1 (TNS V1-V3)select TO_CHAR(LOGICAL_DATE, '...705.8 GB2528.2 GB11.39105.9572.7127.951hg2wcuapy3y3JDBC Thin Clientselect bl1_run_request.run_mod...234.0 GB1318.0 GB3.781,476.6330.5366.684gz51fphuarswJDBC Thin Client/* CL_ProcInstScanner_selectAv...228.4 GB1317.6 GB3.69924.9030.0966.536fu3z8pqd2y9gJDBC Thin Client/* CL_WaitScanner_selectWorkab...190.4 GB335582.0 MB3.07192.3899.900.00aty7a3bvqfxxxJDBC Thin ClientSELECT COUNT(1) FROM (/* null_...
SQL ordered by Executions
- ExecutionsRows ProcessedRows per ExecElapsed Time (s)%CPU%IOSQL IdSQL ModuleSQL Text2,552,0722,551,0771.00514.3799.270.000mynq29fmat7dgetdate_int@ccbdbpr1 (TNS V1-V3)select TO_CHAR(LOGICAL_DATE, '...445,868445,8651.0014.0590.200.20fa311gg43yjyfJDBC Thin ClientSelect CSM_TRX_1SQ.NEXTVAL fro...380,095380,0411.00101.0821.7183.42aprfnw5vk6szsjava_q4p@ccbappr7 (TNS V1-V3)SELECT ch_objects.obj_id, ch_o...
这个时候通过这三个部分，能够基本定位出问题发生在sql_id 0mynq29fmat7d这个语句上，这个语句就是 一个简单的select查询，查询的表也很小。但是问题就是在10分钟的时间范围内执行了2百多万次，这确实很不正常。从sql order by elapased部分可以看出这个语句占用的 db time比例不高，从sql语句的执行上还是没有问题的，但是通过sql order by gets和execution这两个部分，可以很明显的看到，这条语句是top 1的语句，使用的buffer gets高达1T，这个表中的数据量就几千条数据，大小都是MB级别的，但是在10分钟内却能使用1T的buffer gets，确实让我感觉很意外。 分析了这些问题之后，我的判断是认为程序逻辑中的问题，稍后发送了邮件和开发做确认。 通过这个问题可以看到sql语句导致的问题不一定是差的执行计划导致的，简单的sql语句照样能够导致一些意外的情况。但是执行的频率为什么这么频繁，还是属于应用部分，只能让他们提供更多的信息了。而且分析问题的时候，发现了一些问题，可能在检查的过程中又被其它的问题干扰了，很可能会让自己偏离问题检查的方向，很容易造成一个情况，发现忙活了半天，查问题的针对性不够。