Oracle性能突然变得非常慢

godspeed

5月8日的下午，Oracle性能突然就很低，以至于在16:00至18:00之间17:00的AWR Snap都丢了。我查看了这段时间附近的AWR报告，发现15:00到16:00之间SharePoolSize增大挤占Buffer Cache。我感觉可能是15:00至16:00之间的某些操作触发了ASMM机制，希望大家能帮我一起分析一下。
我很想利用当时的数据搞清楚这个问题的根源，但不知道从什么地方下手。
附件有三个AWR文件，15:00到16:00的，16:00到18:00的。另外还提供第二天15:00到16:00的（我们的业务基本上每天都是很有规律的，第二天却没有出现性能问题，提供这个文件供参考吧）
附件还有这段时间的alert文件、trace文件、incident文件。
这台服务器硬件上主要是一颗Xeon E5606四核心处理器，12GB内存，4块300GB磁盘做了RAID5+Hotspare（RAID控制器带电池）
软件主要是Redhat Linux 5.8 + Oracle 11.2.0.3 + Tomcat 6（跑了好几个Tomcat服务）

godspeed

自己初步看了一下，好像15:47的时候发生ORA-04031问题了，share pool size确实不够用了，好像是ASMM调整到极限了。但不知道如何才能看出不够用的具体原因，可能要对incident文件进行深入分析？
trace文件和incident文件很多，附件只是几个感觉有代表性的文件。

godspeed

仔细再看15:47有一连串的incident，有一个173034编号的incident，里面xnjt_ora_3239_i173034.trc文件达到了4852881930字节（4.5GB），我看了一下这个文件前面的内容：
Dump file /opt/oracle/diag/rdbms/xnjt/xnjt/incident/incdir_173034/xnjt_ora_3239_i173034.trc
Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
With the Partitioning, OLAP, Data Mining and Real Application Testing options
ORACLE_HOME = /opt/oracle/product/11g/db_1
System name:    Linux
Node name:      localhost.localdomain
Release:        2.6.18-308.el5
Version:        #1 SMP Fri Jan 27 17:17:51 EST 2012
Machine:        x86_64
Instance name: xnjt
Redo thread mounted by this instance: 1
Oracle process number: 177
Unix process pid: 3239, image: oracle@localhost.localdomain


*** 2013-05-08 15:47:01.484
*** SESSION ID:(658.3459) 2013-05-08 15:47:01.484
*** CLIENT ID:() 2013-05-08 15:47:01.484
*** SERVICE NAME:(SYS$USERS) 2013-05-08 15:47:01.484
*** MODULE NAME:() 2013-05-08 15:47:01.484
*** ACTION NAME:() 2013-05-08 15:47:01.484

Dump continued from file: /opt/oracle/diag/rdbms/xnjt/xnjt/trace/xnjt_ora_3239.trc
ORA-04031: ÎÞ·¨·ÖÅä 56 ×ֽڵĹ²ÏíÄÚ´æ ("shared pool","unknown object","KGLH0^83b1be85","kkocsBeElem: kkoMergeBindEqvCtx")

========= Dump for incident 173034 (ORA 4031) ========

*** 2013-05-08 15:47:01.500
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=c78r0nu1v3gn5) -----
SELECT distinct TC.id,TC.all_name,TC.address,TC.linkman,TC.telephone,TC.short_name,TC.qy_type,TC.addtime,TC.lon,TC.lat,TC.kh_state,TC.kh_belong,TC.gro
upid,TC.link_sim,TC.clon,TC.clat FROM T_CUSTOMER TC, T_CUSTOMER_ASSIGN TCA WHERE TC.ID=TCA.CUSTOMERID AND TCA.YG_GUID=:1 AND TCA.GGUID=:2
难道是这条语句在执行的时候把share pool size用完了？

雪影舞剑

alert真难看...大量的tns信息混杂...logfile应调整...
AWR中的等待事件值得分析

dla001

别费劲分析了，把与数据库无关的服务都弄出去。
把tomcat弄走，没服务器用，那就找几个PC，这东西总会有吧。
64位系统，只给oracle 3.5G的内存，并且你绑定变量做的也不行。还可能有内存交换，业务稍微大点，你系统就应该挂了。

godspeed

dla001 发表于 2013-5-29 10:15
别费劲分析了，把与数据库无关的服务都弄出去。
把tomcat弄走，没服务器用，那就找几个PC，这东西总会有吧 ...

那些个Tomcat确实导致太多不确定性的因素了。但刚起步的业务托管的费用（PC也没地方放）也比较受限。我现在在想发现问题的关键是不是在那4.5GB的incident文件上？

dla001

godspeed 发表于 2013-5-29 10:34
那些个Tomcat确实导致太多不确定性的因素了。但刚起步的业务托管的费用（PC也没地方放）也比较受限。我现 ...

先看系统监控，确认一下，内存交换是不是很严重。如果没，再做其它分析，把绑定变量什么的都处理了。如果有，那就加内存或减少tomcat。 先确定OS层的资源是够用的再做其它的。

Maclean Liu(刘相兵

grep -i dump YOUR_TRACE

godspeed

好像这4.5GB的trace文件里面有几十万行Dump内存

Maclean Liu(刘相兵

========= Dump for incident 173034 (ORA 4031) ========


--------------------- Binary Stack Dump ---------------------
Dump of memory from 0x7fff11804530 to 0x7fff11804540
Dump of memory from 0x7fff11804540 to 0x7fff118045f0
Dump of memory from 0x7fff118045f0 to 0x7fff11804740
========== FRAME [4] (dbkedDefDump()+2741 -> ksedst()) ==========
Dump of memory from 0x7fff11804810 to 0x7fff11804c10
========== FRAME [5] (ksedmp()+36 -> dbkedDefDump()) ==========
Dump of memory from 0x7fff11804c10 to 0x7fff11804c20
Dump of memory from 0x7fff11804c20 to 0x7fff11804cb0
Dump of memory from 0x7fff11808220 to 0x7fff118086a0
Dump of memory from 0x7fff1180bde0 to 0x7fff1180c1e0
'

怀疑当时分配了 很多PGA ，给出最近时段AWR和alert.log

godspeed

附件是上周三（5月8日也是个周三）的AWR和最新的alert文件。

无痕

在05/08 15:57:11 左右
这段时间内登录总次数60.10*60*4.4=15866.4，也应该算正常，
但是这个期间执行了PRO_POSITION_GPSONE，这个procedure是递归调用的插入语句，
每个递归都登陆了两次数据库（select /*+ connect_by_filtering */ privilege#, level from sysauth$ ，），又或未使用绑定变量，导致了大量cursor: pin S wait on X，引起了share pool的自增长。
这个硬解析，外加上插入操作出现了违反约束导致更多的系统开销（CPU+DB TIME),（select /*+ rule */ c.name, u.name from con$ c, cdef$ cd, user$ u whe）。
以下作业的交织导致了row cache的 争用，以及相关表如T_POSITION_GPSONE的竞争加剧，伴随了热点segment的出现。

可调查异常作业：
BEGIN PRO_POSITION_GPSONE(:1, :2, :3, :4, :5, :6, :7, :8, :9, :10, :11, :12, :13, :14, :15, :16, :17, :18, :19) ; END; 在8号和正常期间都有执行
BEGIN PROC_POSITION_GPSONE(:1, :2, :3, :4, :5, :6, :7, :8, :9, :10, :11, :12, :13, :14, :15, :16, :17) ; END;只在8号执行
DELETE FROM POSITION_LAST WHERE F_SIM = :B1 只在8号执行

godspeed

无痕 发表于 2013-5-29 15:25
在05/08 15:57:11 左右
这段时间内登录总次数60.10*60*4.4=15866.4，也应该算正常，
但是这个期间执行了PRO ...

感谢答复。
但是没看太明白，我看22日15:00到16:00正常时每秒硬解析10多个，8日15:00到16:00异常时每秒硬解析只有7.8个。
正常和异常时PRO_POSITION_GPSONE差不多都是在一个小时里面跑了4万多次。只是8日的时候有个PRO_POSITION_GPSONE只有17个变量。
DELETE FROM那个语句中的表应该相对是个比较小的表（好像是1万多行），正常情况下被删除的记录只有0或1条。这个删除操作按说不会构成什么威胁。

godspeed

今天（6月18日）系统出现了类似的故障。软件优化是一个方面，另一方面我还是怀疑服务器硬件有不正常的地方，特别是RAID卡的电池。今天彻底检查了RAID卡，发现5月8日和今天的问题确实是RAID卡电池失效导致的问题。服务器厂商已经计划过来升级RAID卡固件并更换电池了。
如果RAID卡电池失效，RAID卡的写入缓存策略会从WriteBack（WB）变成WriteThrough（WT），这对于高峰期的系统IO性能有很大的影响。
由于IO性能急剧下降，Oracle进程中堆积了大量的事务，这也导致ASMM机制被触发。
附件是RAID卡的日志，里面的时间好像是UTC时间，需要加8。
考虑到这个问题，下一步我们计划跟服务器厂商确认一下RAID卡电池AutoLearn机制的可控性，确保在业务高峰期，不再发生这样的问题。