一． 现象xx网管平台的用户反映，在打开工单时忽然发现较平时慢了非常多，打开工单界面，需要刷新将近2分钟才正常载入。网元视图也存在同样的情况。影响用户工单的处理。 数据库环境简单介绍： 1.RAC双机 2.数据库主机物理内存分别为16G 3.数据库主机CPU分别为16个 4.两节点均为ORACLE10.2.0.4.0版本,ORACLE 的SGA设置为6G二． 分析过程2.1 传统方法，整体排查，空喜一场，暂无所获根据该情况，做了[font="]11点到[font="]12点的[font="]AWR采样报表进行分析（默认是一小时一个采样），并没有发现特别异常的情况，查看数据库告警日志，也并没发现异常情况。接下来查看数据库监听日志情况，无意发现日志非常庞大，有[font="]1G左右，如此大的日志必然导致写入会比较缓慢，因此怀疑是监听日志太大导致前台连接缓慢。当即及时清理了日志，发现前台立即恢复了正常。当时以为问题解决了。结果在当天的晚上[font="]19点多又出现问题了。监听日志非常小，看来中午解决问题的方法是巧合，并没有真正解决问题。继续做了[font="]19点到[font="]20点这时间段的[font="]AWR报表采样，看报表整体并不能发现数据库有啥问题。不解的是，过了[font="]20点，再问现场人员，居然系统又恢复了，现场人员告知工单系统使用非常正常，再也不卡了。[font="]28日上午又接连出现工单操作很卡，过一会儿又恢复正常的情况，电信局方对此很不满。2.2即时定位，精确打击，苦尽甘来，终获突破2.2.1 问题再现时进行实施跟踪看来[font="]AWR默认的一小时一次的采样太泛了，无法准确定位出问题，因为前台觉得工单处理缓慢的时间一般不长，大致[font="]10来分钟，但是却频频发生。看来方法应该改变了，应该采取工单处理缓慢时做[font="]AWR报表跟踪，这样才能突出重点。于是我要求现场人员遇到问题时立即电话通知我在[font="]18点的时候，系统又出现这样的问题了，此时现场人员及时电话联系了我，当时安排如下操作[table=98%,rgb(221, 217, 195)]
[td=574] 步骤[font="]1．先登录数据库主机，[font="]sqlplus bosswg/bosswg登录后，执行如下： exec dbms_workload_repository.create_snapshot(); 步骤2.接下来，新疆前台人员操作前台界面（这个时候执行非常缓慢，需要2分钟才可以正常载入页面） 步骤3. --2分钟后，执行如下： exec dbms_workload_repository.create_snapshot(); 步骤4. 紧接着，执行如下跟踪 @?/rdbms/admin/awrrpt.sql 将开始和结束的这2分钟时间做一个短暂的AWR报表分析，看看系统主要等待事件
2.2.2 分析即时AWR报表查询出主要等待事件[font="] 观察[font="]AWR报表，我们可以看到，我们把时间范围缩短到非常精确的[font="]2分钟范围[font="],具体如下
[font="][img=541,120]file:///C:/Users/%E9%99%88/AppData/Local/Temp/msohtmlclip1/01/clip_image002.jpg[/img]
在这个精确的基础上再观察AWR报表,终于观察到了,原先一小时的采样不能突出重点, Top5 Timed Events 排在第一位的是CPU time,而现在情况变化了,我们可以翡翠明显的观察到一个等待事件readby other session , 说明数据库存在读的竞争，根据文档，这个事件的解释如下：[table=98%,rgb(221, 217, 195)]
[td=574] This event occurs when a session requests a buffer that is currently being read into the buffer cache by another session. Prior to release 10.1, waits for this event were grouped with the other reasons for waiting for buffers under the 'buffer busy wait' event
[font="] AWR报表，具体如下[font="]:
[font="][size=10.0pt][img=559,189]file:///C:/Users/%E9%99%88/AppData/Local/Temp/msohtmlclip1/01/clip_image004.jpg[/img]
2.2.3 根据AWR时段进一步分析ASH报表查找问题SQL[font="] 到底是什么语句导致数据库在前台工单刷新缓慢的时候出现这个严重的[font="]r[font="]eadby other session的等待事件呢？这个时候观看[font="]ASH报表是一个非常好的方法，[font="]ASH可以很方便的定位到主要等待事件和具体哪个[font="]SQL有关系，是一个不可多得到[font="]ORACLE好工具。观察结果如下：[img=560,269]file:///C:/Users/%E9%99%88/AppData/Local/Temp/msohtmlclip1/01/clip_image006.jpg[/img] 我把[font="]SQL_ID=7v6brfxyyzxh7和buwbzrt3vkkfw的SQL语句发给新疆现场人员，并告知是这两个SQL导致了整个系统运行缓慢。结果新疆先擦好难过人员对此非常不解，答复是不可能，因为在前台操作工单的时候，根本没有运行这个语句，这个语句是告警监控类的，而前台他们操作的是工单扭转类。面对现场人员的疑问，我心里更有数了，可以猜测到，正是由于前台在操作工单的时候，系统恰好在跑刚才我说的那两个语句，这个时候前台操作就慢了，而什么时候恢复正常呢？就是在这两个语句没有运行的时候。也正好解释了为什么工单查询会时快时慢。为了证明自己的观点消除现场人员的疑问，我建议他们现场做个实验（当时系统正好是正常状态），让他们操作一下前台的告警监控的菜单进行查询，并且多点开几个，然后再打开工单进行操作。结果很快现场人员反馈，工单操作非常卡，要2分多钟才可以打开，故障很快再现了。接下来，等告警监控的查询操作完全结束后，工单操作又开始飞快起来。看来问题终于定位出来了，现在的问题就在于，告警类查询到底有啥问题，为什么会导致系统产生如此大的热点块竞争导致的事件[font="]r[font="]ead by other session首先分析[font="]SQL_ID=7v6brfxyyzxh7的语句，该语句非常冗长，具体代码如下[table=98%,rgb(221, 217, 195)]
[td=621] select * from (select rownum sid, a.* from (select a.ne_alarm_list_id id, a.flow_id, /*流程ID*/ a.oprt_state oprtState, /*操作状态*/ a.alarm_state alarmState, /*告警状态*/ a.alarm_Level alarmLevel, /*告警级别*/ a.perf_msg_id, /*性能消息ID*/ a.alarm_class alarmClass, /*告警类别*/ to_char(a.generate_time, 'yyyy-mm-dd') generatedate, /*产生日期*/ to_char(a.last_generate_time, 'yyyy-mm-dd') lastdate, /*最后产生日期*/ b1.list_label alarm_type, c1.ne_name, d.kpi_name, a.kpi_value, decode(c1.ne_flag, 6, e.region_name, c2.ne_name) datasource, '' || decode(a.alarm_Level, '1', '严重', '2', '重要', '3', '一般', '未知') || '' alarm_Level, to_char(a.generate_time, 'yyyy-mm-dd hh24:mi:ss') generate_time, to_char(a.last_generate_time, 'yyyy-mm-dd hh24:mi:ss') last_generate_time, a.alarm_times, decode(a.OPRT_STATE, '20', to_char(a.CONFIRM_TIME, 'yyyy-mm-dd hh24:mi:ss'), '25', to_char(a.SUSPEND_TIME, 'yyyy-mm-dd hh24:mi:ss'), '30', to_char(a.CLEAR_TIME, 'yyyy-mm-dd hh24:mi:ss'), '40', to_char(a.DELETE_TIME, 'yyyy-mm-dd hh24:mi:ss')) executeTim, b2.list_label alarm_state, DECODE(A.FLOW_ID, '', '未派单', '已派单') work_state /*自定义列项*/ from ne_alarm_list a, (select * from TP_DOMAIN_LISTVALUES where domain_code = 'DOMAIN_NE_ALARM_TYPE') b1, (sel ect * from tp_domain_listvalues where domain_code = 'DOMAIN_ALARM_STATE') b2, (select * from tp_domain_listvalues where domain_code = 'DOMAIN_DR_ID_FLAG') b3, (select * from tp_domain_listvalues where domain_code = 'DOMAIN_ALARM_OPRT_STATE') b4, net_element c1, net_element c2, kpi_code_list d, manage_region e, kpi_mapping_cfg f, ne_trans_alarm nta, (SELECT T.PRIMARY_ID "$PRIMARY_ID", SUM(T.HAS_READ) "$HAS_READ" FROM TREE_PRIVILEGE T WHERE T.TREE_CFG_NAME = :1 AND T.ASSIGN_OBJECT IN (:2, :3, :4, :5, :6, :7) GROUP BY T.PRIMARY_ID) "$PRI_VIEW" where NVL(a.CONFIG_NE_ID, a.NE_ID) = "$PRI_VIEW"."$PRIMARY_ID"(+) AND NVL("$PRI_VIEW"."$HAS_READ", :8) > 0 and b1.list_value = a.alarm_Type and a.ne_id = c1.ne_id and b2.list_value = a.alarm_state and b3.list_value = a.dr_id || '' and b4.list_value = a.oprt_state and a.config_ne_id = c2.ne_id(+) and a.kpi_id = d.kpi_id and a.kpi_id = f.kpi_id(+) and nvl(a.ALARM_REGION_ORIGIN, '-1') = to_char(e.region_id(+)) and a.ne_alarm_list_id = nta.ne_alarm_list_id(+) and (select path || '/' from net_element where ne_id = a.ne_id) not like (select path || '/%' from net_element where ne_type_id = 30 and NE_FLAG = '6' AND STATE = '0SA') /*非业务系统*/ and TO_NUMBER(a.DR_ID) = :9 order by b2.sort_id, b4.sort_id, a.alarm_type, a.ne_id, nvl(a.last_send_time, a.create_Time) desc) a) b where b.sid >= :10 and b.sid <= :11 以上语句虽然冗长，但是我们可以很明确的知道，具体需要优化的语句就是如下一小段，[font="] [table=98%,rgb(221, 217, 195)] [td=621] (SELECT T.PRIMARY_ID "$PRIMARY_ID", SUM(T.HAS_READ) "$HAS_READ" FROM TREE_PRIVILEGE T WHERE T.TREE_CFG_NAME = :1 AND T.ASSIGN_OBJECT IN (:2, :3, :4, :5, :6, :7) GROUP BY T.PRIMARY_ID) "$PRI_VIEW" 而且观察了其他[font="]SQL语句后我们发现，虽然语句不一样，但是都有一个共同的特点，就是大家都有嵌套进上述这一小块代码。2.2.4进一步分析SQL执行计划从而找到原因[font="] 我们进一步做[font="]AWRSQRPT报表[font="],定位这个[font="]SQL_ID=7v6brfxyyzxh7的语句的执行计划是什么[font="],由于非常冗长，我只贴出主要矛盾的地方，具体如下：[font="][img=588,234]file:///C:/Users/%E9%99%88/AppData/Local/Temp/msohtmlclip1/01/clip_image008.jpg[/img][font="] 可以看出，[font="]TREE_PRIBLEGE表的全表扫描是开销最大的部分，花费了[font="]4分[font="]26秒的时间，而整个[font="]SQL的执行时间是[font="]5秒[font="][img=559,147]file:///C:/Users/%E9%99%88/AppData/Local/Temp/msohtmlclip1/01/clip_image010.jpg[/img]我们观察[font="]TREE_PRIBLEGE的记录时候吓了一跳，该表有[font="]1千多万条记录，居然采用全表扫描，看来问题进一步缩小到为什么会对该表进行全表扫描的问题上了。在分析此问题前，我们还有一个疑问需要解决，为什么上午[font="]11点多出现这个工单操作时快时慢的问题（我们现在可以定位时而快是因为恰好此时此类语句没在运行），我对整个数据库做了[font="]21日到[font="]28日这么长时间内的[font="]SQL分析，终于发现该[font="]SQL原来有[font="]2个执行计划，除了对[font="]TREE_PRIBLEGE做全表扫那个外，还有一个是对[font="]TREE_PRIBLEGE做索引读的，如下：[font="][img=560,124]file:///C:/Users/%E9%99%88/AppData/Local/Temp/msohtmlclip1/01/clip_image012.jpg[/img]两个SQL的执行计划居然有天壤之别，对TREE_PRIBLEGE做全表扫那个需5分钟完成，而对TREE_PRIBLEGE做索引读那个在30秒内完成。我之前询问过先现场人员，27日前后是否有对数据库做一些动作，如打补丁升级系统啥的，回答是没有，所以我非常纳闷，现在这种情况的原因是ORACLE由于使用了绑定变量，无法正确的识别到直方图，为什么前一天好好的，原因应该是，该SQL被SHARED POOL重新解析过了，并且当时ORACLE在第一次窥视绑定变量时候选择了全表扫描（或许恰好这个时刻返回了绝大部分的记录，ORACLE判断全表扫描更快），以后就不会再改变执行计划了。为什么会被SHAREDPOOL重新解析过，原因不得而知，但是一定有人为操作的因素在里面。三． 解决方案有了上面的分析，问题好解决了，具体方案如下： 3.1临时用索引的HINT来改造热点竞争块表的扫描方式[font="]ASSIGN_OBJECT这个表有索引，因此建议加上[font="]IDX_ASSIGN_OBJECT 这个[font="]HINT，让[font="]ORACLE不走全表扫描，估计问题可以暂时得到缓解。因为这个表全表扫描实在是开销太大了，跟踪的系统真实执行计划，现在都是走全表扫描。当然，如果极端情况，当[font="]ANDT.ASSIGN_OBJECT IN (:2, :3, :4, :5, :6, :7) 返回几乎所有的数据的时候，索引还更慢，不过由于使用的是绑定变量，[font="]ORACLE无法聪明的自适应了，只能赌这情情况不多见了。[table=98%,rgb(221, 217, 195)] [td=574] [color=navy][font="][size=10.0pt] (SELECT [font="][size=10.0pt]/*+index(t,IDX_ASSIGN_OBJECT)*/[color=navy][font="][size=10.0pt] T.PRIMARY_ID "$PRIMARY_ID", [color=navy][font="][size=10.0pt] SUM(T.HAS_READ) "$HAS_READ" [color=navy][font="][size=10.0pt] FROM TREE_PRIVILEGE T [color=navy][font="][size=10.0pt] WHERE T.TREE_CFG_NAME = :1 [color=navy][font="][size=10.0pt] AND T.ASSIGN_OBJECT IN (:2, :3, :4, :5, :6, :7) [color=navy][font="][size=10.0pt] GROUP BY T.PRIMARY_ID) "$PRI_VIEW" 3.2考虑对TREE_PRIVILEGE 这个热表进行瘦身当初对这个TREE_PRIVILEGE表瘦身的改造当时已经探讨过多次了，这个表的记录如果能大幅度缩小，也能方便解决问题。[font="] 3.3避免监控语句查询的操作[font="] 如果前两个没完成好，就要尽量避免内部人员在白天工单繁忙时去点监控查询。[font="] 最终在[font="]29日晚上临时性的打了补丁，将增了[font="] /*+index(t,IDX_ASSIGN_OBJECT)*/的[font="]HINT的[font="]CALSS更新上系统后，系统完全恢复了正常，监控查询变得非常迅速，而工单操作也变得非常流畅了。预计下周会完成对[font="] TREE_PRIVILEGE表的大幅度瘦身，后续这个问题可以被真正解决了。四． 总结4.1.解决问题要善于灵活选择整体分析和即时跟踪两种方案。本次为什么一小时或数小时之间的采样无法定位到具体问题，而在用户出现问题的那个时刻进行短暂跟踪，却立即定位出问题所在？因为在比较长的时间段里，比如一小时甚至一天的时间里，由于累积量的原因，readby other session的等待事件排名远不如CPUTIME和其他几个，所以整体报表上我们无法有收获，但是事实是，系统经常卡住，时好时坏，让人郁闷。打个比喻，比如的士司机开市区一天总计30分钟的红绿灯等待时间也许很正常，所以30分钟红绿灯等待时间出现在该司机一天的交通状态报告里，根本无法发现啥问题，报表系统一定提示红绿灯等待时间正常！但是这里面如果包含了这样一个事实就很有问题了：比如仅仅早上9点到9点半之间等了20分钟红绿灯！这只是一个比喻，希望大家能明白。当然，即时分析固然准确，但是整体分析大部分情况下还是方便的。举个直白的例子，比如一天下来，某的士司机的红绿灯等待时间总共花费了500分钟，此时傻子也知道，该城市交通早已瘫痪了。4.2.AWR结合ASH是定位问题的黄金组合AWR 是一个好工具，结合ASH和AWRSQRPT.SQL这两个工具，三者一结合，可以非常方便的查出问题。 AWR查处有问题的等待事件是什么，ASH可以在这个特定范围的AWR中显示导致这些等待的主要SQL是什么？ 而AWRSQRPT可以定位出SQL语句的执行计划，如果出现过多个，比如执行计划原先是A,现在改变为B，会把A,B同时展现出来。有了这三者结合，基本上都能很方便的定位出问题所在。 当然ORACLE还有一个ADDMA的建议工具包，这个可以给我们起到参考作用。