新年，给大家拜年了。祝大家工作顺利，万事如意。
今天照例简单检查了系统的情况，发现在客户的服务器在下午的3-5点这个时间段，数据库负载略有上升，但是幅度不大，因为生产的awr抓取频率是10分钟，所以还是能够通过awr分析出一些问题。
负载情况如下：
抓取了一个最新时间段的awr报告。
查看数据库负载，比平时的负载要高一些。
从这个概览来看还是看不出特别之处，只能对整体的情况有一个把握。这是一个10分钟的报告。
Load profile是我查看awr报告的重点部分。能够发现user calls和executions的值很高。
这个时候基本能够从load profile里面找到问题的方向了，user calls和executions的部分需要注意，首先问题的方向很可能是从sql语句级别导致的，语句执行的如此频繁，势必会对buffer gets有较大的影响，这个报告中parses的值很低，至少说明问题不是由于绑定变量导致的。我们可以查看等待事件基本确定时间都去哪了，哪些等待事件是需要重点关注的。然后在sql语句部分来分析了，基本可以从order by Elapsed time, order by Gets, order by Executions这三个部分来佐证了。
等待事件如下：
今天照例简单检查了系统的情况，发现在客户的服务器在下午的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
| 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信息部分。
但是这个问题和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 Gets Executions Gets per Exec %Total Elapsed Time (s) %CPU %IO SQL Id SQL Module SQL Text 1.2 TB 2,552,072 486.9 KB 19.12 514.37 99.27 0.00 0mynq29fmat7d getdate_int@ccbdbpr1 (TNS V1-V3) select TO_CHAR(LOGICAL_DATE, '...705.8 GB 25 28.2 GB 11.39 105.95 72.71 27.95 1hg2wcuapy3y3 JDBC Thin Client select bl1_run_request.run_mod...234.0 GB 13 18.0 GB 3.78 1,476.63 30.53 66.68 4gz51fphuarsw JDBC Thin Client /* CL_ProcInstScanner_selectAv...228.4 GB 13 17.6 GB 3.69 924.90 30.09 66.53 6fu3z8pqd2y9g JDBC Thin Client /* CL_WaitScanner_selectWorkab...190.4 GB 335 582.0 MB 3.07 192.38 99.90 0.00 aty7a3bvqfxxx JDBC Thin Client SELECT COUNT(1) FROM (/* null_...
SQL ordered by Executions
-
Executions Rows Processed Rows per Exec Elapsed Time (s) %CPU %IO SQL Id SQL Module SQL Text 2,552,072 2,551,077 1.00 514.37 99.27 0.00 0mynq29fmat7d getdate_int@ccbdbpr1 (TNS V1-V3) select TO_CHAR(LOGICAL_DATE, '...445,868 445,865 1.00 14.05 90.20 0.20 fa311gg43yjyf JDBC Thin Client Select CSM_TRX_1SQ.NEXTVAL fro...380,095 380,041 1.00 101.08 21.71 83.42 aprfnw5vk6szs java_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语句照样能够导致一些意外的情况。但是执行的频率为什么这么频繁，还是属于应用部分，只能让他们提供更多的信息了。而且分析问题的时候，发现了一些问题，可能在检查的过程中又被其它的问题干扰了，很可能会让自己偏离问题检查的方向，很容易造成一个情况，发现忙活了半天，查问题的针对性不够。
分析了这些问题之后，我的判断是认为程序逻辑中的问题，稍后发送了邮件和开发做确认。
通过这个问题可以看到sql语句导致的问题不一定是差的执行计划导致的，简单的sql语句照样能够导致一些意外的情况。但是执行的频率为什么这么频繁，还是属于应用部分，只能让他们提供更多的信息了。而且分析问题的时候，发现了一些问题，可能在检查的过程中又被其它的问题干扰了，很可能会让自己偏离问题检查的方向，很容易造成一个情况，发现忙活了半天，查问题的针对性不够。
扫一扫
1459
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
