本节是关于Shared Pool的一个诊断案例,案例本身可能并不重要,重要的是给大家一个解决问题的思路,并且通过这个案例可以进一步了解Oracle的工作原理。
问题起因是公司要进行短信群发,群发的时候每隔一段时间就会发生一次消息队列拥堵的情况。在数据库内部实际上是向一个数据表中记录发送日志,数据库版本是Oracle 8.1.5。
在一个拥堵时段开始诊断,检查数据库端可能存在的问题,首先查询V$SESSION_WAIT视图,列出当前发生的等待:
SQL> select sid,event,p1,p1raw from v$session_wait; SID EVENT P1 P1RAW ---------- ---------------------------------------------------------------- 76 latch free 2147535824 8000CBD0 83 latch free 2147535824 8000CBD0 148 latch free 3415346832 CB920E90 288 latch free 2147535824 8000CBD0 285 latch free 2147535824 8000CBD0 196 latch free 2147535824 8000CBD0 317 latch free 2147535824 8000CBD0 3 log file parallel write 1 00000001 13 log file sync 2705 00000A91 60 SQL*Net message to client 1413697536 54435000 239 SQL*Net message to client 1413697536 54435000 ...ignore some idle waiting here... 11 SQL*Net message from client 675562835 28444553 12 SQL*Net message from client 1413697536 54435000 170 rows selected.
在这次查询中,发现存在大量的latch free等待,再次查询时这些等待消失,应用也恢复了正常:
SQL> select sid,event,p1,p1raw from v$session_wait where event not like 'SQL*Net%'; SID EVENT P1 P1RAW ---------- ------------------------------------------------------- 2 pmon timer 300 0000012C 1 rdbms ipc message 300 0000012C 4 rdbms ipc message 300 0000012C 6 rdbms ipc message 180000 0002BF20 18 rdbms ipc message 6000 00001770 102 rdbms ipc message 6000 00001770 178 rdbms ipc message 6000 00001770 194 rdbms ipc message 6000 00001770 311 rdbms ipc message 6000 00001770 3 log file parallel write 1 00000001 148 log file sync 2547 000009F3 273 log file sync 2544 000009F0 190 log file sync 2545 000009F1 5 smon timer 300 0000012C 14 rows selected.
接下来通过V$LATCH视图判断是哪些Latch竞争消耗了最多的等待时间:
SQL> select addr,latch#,name,gets,spin_gets from v$latch order by spin_gets; ADDR LATCH# NAME GETS SPIN_GETS -------- ---------- ---------------------------------------------------------------- 80001398 3 session switching 111937 0 80002010 6 longop free list 37214 0 ..... 80001330 2 session allocation 261826230 428312 800063E0 64 multiblock read objects 1380614923 1366278 800026B8 11 messages 207935758 1372606 80001218 0 latch wait list 203479569 1445342 80006310 62 cache buffers chains 3.8472E+10 2521699 8000A17C 92 row cache objects 1257586714 2555872 80007F80 74 redo writing 264722932 4458044 80006700 67 cache buffers lru chain 5664313769 30046921 8000CBD0 98 shared pool 122433688 59070585 8000CC38 99 library cache 4414533796 1037032730 142 rows selected.
通过查询输出注意到,在当前数据库中竞争最严重的两个Latch是Shared Pool和Library Cache。这两个Latch是Shared Pool管理中最重要也是最常见的Latch竞争。
Shared Pool Latch用于共享池中内存空间的分配和回收,如果SQL没有充分共享,反复解析,那么将会不断请求Shared Pool Latch在共享池中分配空间,由此可能造成非常严重的CPU消耗,前面曾经论述过这个问题。
而Library Cache Latch用于保护Cache在内存中的SQL以及执行计划等,当需要向Library Cache中增加新的SQL时,Library Cache Latch必须被获得。在解析SQL过程中,Oracle需要搜索Library Cache查找匹配的SQL,如果没有可共享的SQL代码,Oracle将全新解析SQL,获得Library Cache Latch向Library Cache中插入新的SQL代码。Library Cache Latch的数量受一个隐含参数_kgl_latch_count控制,其缺省值为大于或等于CPU_COUNT的最小素数,最大值不能超过67。
可以简化一下SQL的执行过程,以说明这两个Latch在SQL解析过程中所起的作用。
(1)首先需要获得Library Cache Latch,根据SQL的HASH_VALUE值在Library Cache中寻找是否存在可共享代码。如果找到则为软解析,Server进程获得该SQL执行计划,转向第(4)步;如果找不到共享代码则执行硬解析。
(2)释放Library Cache Latch,获取Shared Pool Latch,查找并锁定自由空间。
(3)释放Shared Pool Latch,重新获得Library Cache Latch,将SQL及执行计划插入到Library Cache中。
(4)释放Library Cache Latch,保持Null模式的Library Cache Pin/Lock。
(5)开始执行。
通过以上过程可以看到,如果系统中存在过度的硬解析,系统的性能必然受到反复解析、Latch争用的折磨。通过查询V$SYSSTAT视图获得关于数据库解析的详细信息:
SQL> select name,value from v$sysstat where name like 'parse%'; NAME VALUE ------------------------------ ------ parse time cpu 66 parse time elapsed 505 parse count (total) 801 parse count (hard) 193 parse count (failures) 0
通过(parse count (total)-parse count (hard))/parse count (total)得出的软解析率经常被用作衡量数据库性能的一个重要指标。
现在回到我们这个问题上来,过多的Shared Pool和library Cache竞争,显然极有可能是SQL的过度解析造成的。进一步检查v$sqlarea,来查找可能存在问题的SQL语句,发现了以下异常SQL:
SQL> select sql_text,VERSION_COUNT,INVALIDATIONS,PARSE_CALLS, 2 OPTIMIZER_MODE,PARSING_USER_ID PUI,PARSING_SCHEMA_ID PSI,ADDRESS,HASH_VALUE 3 from v$sqlarea where version_count >1000; SQL_TEXT ----------------------------------------------------------------------------------------- VERSION_COUNT INVALIDATIONS PARSE_CALLS OPTIMIZER_MODE PUI PSI ADDRESS HASH_VALUE ------------- ------------- ----------- ------------------------- --- --- ------- ------- insert into sms_log (MSGDATE,MSGTIME,MSGID,MSGKIND,MSGTYPE,MSGTYPE_MOMT,MSGLEN,MSGSTATUS, AREAID,IFIDDEST,IFIDSRC,ADDRSRC,ADDRDEST,ADDRFEE,ADDRUSER,SERVICECODE,PLANID,FEETYPE,FEEVALUE,DATACODING,FLAGS,SMLEN,SMCONT) values :b0,:b1,:b2,:b3,:b4,:b5,:b6,:b7,:b8,:b9,:b10, :b11,:b12,:b13,:b14,:b15,:b16,:b17,:b18,:b19,:b20,:b21,:b22) 7023 0 1596 MULTIPLE CHILDREN PRESENT 36 36 C82AF1C8 3974744754
这就是写日志记录的代码,这段代码使用了绑定变量,但是version_count却有7023个。也就是说这个SQL有7023个子指针,这是不可想象的。
通过前面几节的研究可以知道,如果这个SQL有7023个子指针,那么意味着这些子指针都将存在于同一个Bucket的链表上。这也就意味着,如果同样SQL再次执行,Oracle将不得不搜索这个链表以寻找可以共享的SQL。这将导致大量的Library Cache Latch的竞争。
应该注意数据库中version_count过多的SQL语句,version_count过高通常会导致Library Cache Latch的长时间持有,从而影响性能,所以很多时候我们应该尽量避免这种情况的出现。
继续问题研究,这时候我们开始推测原因,可能的情况有:
l 可能代码存在问题,在每次执行之前程序修改某些Session参数,导致SQL不能共享;
l 可能是Oracle 8i的v$sqlarea记录存在问题,看到的结果是假象;
u 由于Oracle的Bug导致了SQL无法共享。
根据以上判断,继续诊断,最直接的可以将Shared Pool转储出来,看一看真实的内存结构:
SQL> ALTER SESSION SET EVENTS 'immediate trace name LIBRARY_CACHE level 4';
查看trace文件得到如下结果(摘录包含该段代码的片断),注意在BUCKET 21049上记录了这条SQL语句,而且的确存在7023个子指针:
BUCKET 21049: LIBRARY OBJECT HANDLE: handle=c82af1c8 name=insert into sms_log (MSGDATE,MSGTIME,MSGID,MSGKIND,MSGTYPE,MSGTYPE_MOMT,MSGLEN, MSGSTATUS,AREAID,IFIDDEST,IFIDSRC,ADDRSRC,ADDRDEST,ADDRFEE,ADDRUSER,SERVICECODE,PLANID,FEETYPE,FEEVALUE,DATACODING,FLAGS,SMLEN,SMCONT) values (:b0,:b1,:b2,:b3,:b4,:b5,:b6, :b7,:b8,:b9,:b10,:b11,:b12,:b13,:b14,:b15,:b16,:b17,:b18,:b19,:b20,:b21,:b22) hash=ece9cab2 timestamp=09-09-2004 12:51:29 namespace=CRSR flags=RON/TIM/PN0/LRG/[10010001] kkkk-dddd-llll=0000-0001-0001 lock=N pin=S latch=5 lwt=c82af1e0[c82af1e0,c82af1e0] ltm=c82af1e8[c82af1e8,c82af1e8] pwt=c82af1f8[c82af1f8,c82af1f8] ptm=c82af250[c82af250,c82af250] ref=c82af1d0[c82af1d0,c82af1d0] LIBRARY OBJECT: object=c1588e84 type=CRSR flags=EXS[0001] pflags= [00] status=VALD load=0 CHILDREN: size=7024 child# table reference handle ------ -------- --------- -------- 0 c1589040 c1589008 c668c2bc 1 c1589040 bfd179c4 c6ec9ee8 2 c1589040 bfd179e0 c2dd9b3c 3 c1589040 bfd179fc c5a46614 ........................................... .....ignore losts of child cursor here..... ........................................... 7016 c641fcb8 c0ae4f2c c60196d0 7017 c641fcb8 c0ae4f48 c4675d2c 7018 c641fcb8 c0ae4f64 bd5e2750 7019 c641fcb8 c0ae4f80 c09b1bb0 7020 c641fcb8 c0ae4f9c bf2d6044 7021 c641fcb8 c0ae4fb8 c332c1c4 7022 c641fcb8 c0ae4fd4 cbdde0f8 DATA BLOCKS: data# heap pointer status pins change ----- -------- -------- ------ ---- ------ 0 c3ef2c50 c1588f08 I/P/A 0 NONE
转储的数据与查询V$SQL得到的结果相同:
SQL> select CHILD_NUMBER,EXECUTIONS,OPTIMIZER_MODE OM,OPTIMIZER_COST OC, 2 PARSING_USER_ID PUID,PARSING_SCHEMA_ID,ADDRESS,HASH_VALUE 3 from v$sql where HASH_VALUE='3974744754'; CHILD_NUMBER EXECUTIONS OM OC PUID PARSING_SCHEMA_ID ADDRESS HASH_VALUE ------------ ---------- ---------- ------ --- ----------------- -------- ---------- 0 12966 CHOOSE 238150 36 36 C82AF1C8 3974744754 1 7111 CHOOSE 238150 36 36 C82AF1C8 3974744754 ..... 7020 625 CHOOSE 237913 36 36 C82AF1C8 3974744754 7021 10101 CHOOSE 237913 36 36 C82AF1C8 3974744754 7022 7859 CHOOSE 237913 36 36 C82AF1C8 3974744754 7023 rows selected.
这里确实存在7023个子指针,第2种猜测被否定了,同时研发发过来的代码也不存在第1种情况。那么只能是第3种情况了,Oracle的Bug,搜索Oracle的官方支持站点Metalink,发现Bug 1210242。该Bug描述如下:
On certain SQL statements cursors are not shared when TIMED_STATISTICS is enabled.
碰巧这个数据库的TIMED_STATISTICS设置为True。修改TIMED_STATISTICS为False以后,观察v$sql,发现有效子指针很快下降到2个:
SQL> select CHILD_NUMBER,OPTIMIZER_COST,OPTIMIZER_MODE,EXECUTIONS,ADDRESS from v$sql where hash_value=3974744754 and OPTIMIZER_MODE='CHOOSE'; CHILD_NUMBER OPTIMIZER_COST OPTIMIZER_ EXECUTIONS ADDRESS ------------ -------------- ---------- ---------- -------- 0 238167 CHOOSE 63943 C82AF1C8 1 238300 CHOOSE 28915 C82AF1C8
第2天下降到只有1个:
SQL> select CHILD_NUMBER,OPTIMIZER_COST,OPTIMIZER_MODE,EXECUTIONS,ADDRESS from v$sql where hash_value=3974744754 and OPTIMIZER_MODE='CHOOSE';
CHILD_NUMBER OPTIMIZER_COST OPTIMIZER_ EXECUTIONS ADDRESS
------------ -------------- ---------- ---------- --------
0 238702 CHOOSE 578124 C82AF1C8
此时,相关业务恢复正常。
对于这个问题,另外一个可选的方法是设置一个隐含参数_sqlexec_progression_cost = 0,这个参数的具体含义为SQL execution progression monitoring cost threshold,即SQL执行进度监控成本阀值。
这个参数根据COST来决定需要监控的SQL,执行进度监控会引入额外的函数调用和Row Sources,这可能导致SQL的执行计划或成本发生改变,从而产生不同的子指针。_sqlexec_progression_cost的缺省值为1000,成本大于1000的所有SQL都会被监控。如果该参数设置为0,那么SQL的执行进度将不会被跟踪。
执行进度监控信息会被记录到V$SESSION_LONGOPS视图中,如果time_statistics参数设置为False,那么这个信息就不会被记录。所以time_statistics参数和_sqlexec_progression_cost是解决问题的两个途径。
通过查询也可以看到,在这个数据库中,OPTIMIZER_COST >1000的SQL主要有以下5个:
SQL> select distinct(sql_text) from v$sql where OPTIMIZER_COST >1000; SQL_TEXT -------------------------------------------------------------------------------- insert into sms_detail_error (msgdate,addruser,msgid,areaid,reason,spnumber,msgt ime,ifiddest,msqkey,servicecode,planid,feetype,feevalue,smcont,submittimes,submi tdate,submittime,msgstate_resp,errorcode_resp,msgstate_rept,errorcode_rept) valu es (:b0,:b1,:b2,:b3,:b4,:b5,:b6,:b7,:b8,:b9,:b10,:b11,:b12,:b13,:b14,:b15,:b16,: b17,:b18,:b19,:b20) insert into sms_detail_success (msgdate,addruser,msgid,areaid,spnumber,msgtime,i fiddest,servicecode,planid,feetype,feevalue,smcont,submittimes,submitdate,submit time,respdate,resptime,reptdate,repttime,msqkey) values (:b0,:b1,:b2,:b3,:b4,:b5 ,:b6,:b7,:b8,:b9,:b10,:b11,:b12,:b13,:b14,:b15,:b16,:b17,:b18,:b19) insert into sms_log (MSGDATE,MSGTIME,MSGID,MSGKIND,MSGTYPE,MSGTYPE_MOMT,MSGLEN,M SGSTATUS,AREAID,IFIDDEST,IFIDSRC,ADDRSRC,ADDRDEST,ADDRFEE,ADDRUSER,SERVICECODE,P LANID,FEETYPE,FEEVALUE,DATACODING,FLAGS,SMLEN,SMCONT) values (:b0,:b1,:b2,:b3,:b 4,:b5,:b6,:b7,:b8,:b9,:b10,:b11,:b12,:b13,:b14,:b15,:b16,:b17,:b18,:b19,:b20,:b2 1,:b22) insert into sms_resprept_error (msgdate,areaid,addruser,msgid,submittimes,submit date,submittime,msgid_gw,msgstate_resp,errorcode_resp,msgstate_rept,errorcode_re pt,servicecode) values (:b0,:b1,:b2,:b3,:b4,:b5,:b6,:b7,:b8,:b9,:b10,:b11,:b12) insert into sms_statusrept (reptdate,addruser,msgid_gw,repttime,statustype,msgid _stus,msgstate,errorcode) values (:b0,:b1,:b2,:b3,:b4,:b5,:b6,:b7)
而这5个SQL中,在v$sqlarea中有4个version_count都在10以上:
SQL> select sql_text,version_count from v$sqlarea where version_count>10; SQL_TEXT -------------------------------------------------------------------------------- VERSION_COUNT ------------- insert into sms_detail_error (msgdate,addruser,msgid,areaid,reason,spnumber,msgt ime,ifiddest,msqkey,servicecode,planid,feetype,feevalue,smcont,submittimes,submi tdate,submittime,msgstate_resp,errorcode_resp,msgstate_rept,errorcode_rept) valu es (:b0,:b1,:b2,:b3,:b4,:b5,:b6,:b7,:b8,:b9,:b10,:b11,:b12,:b13,:b14,:b15,:b16,: b17,:b18,:b19,:b20) 42 insert into sms_log (MSGDATE,MSGTIME,MSGID,MSGKIND,MSGTYPE,MSGTYPE_MOMT,MSGLEN,M SGSTATUS,AREAID,IFIDDEST,IFIDSRC,ADDRSRC,ADDRDEST,ADDRFEE,ADDRUSER,SERVICECODE,P LANID,FEETYPE,FEEVALUE,DATACODING,FLAGS,SMLEN,SMCONT) values (:b0,:b1,:b2,:b3,:b 4,:b5,:b6,:b7,:b8,:b9,:b10,:b11,:b12,:b13,:b14,:b15,:b16,:b17,:b18,:b19,:b20,:b2 1,:b22) 7026 insert into sms_resprept_error (msgdate,areaid,addruser,msgid,submittimes,submit date,submittime,msgid_gw,msgstate_resp,errorcode_resp,msgstate_rept,errorcode_re pt,servicecode) values (:b0,:b1,:b2,:b3,:b4,:b5,:b6,:b7,:b8,:b9,:b10,:b11,:b12) 301 insert into sms_statusrept (reptdate,addruser,msgid_gw,repttime,statustype,msgid _stus,msgstate,errorcode) values (:b0,:b1,:b2,:b3,:b4,:b5,:b6,:b7) 41
具体可以参考Metalink: Note 62143,至此这个关于Shared Pool的问题找到了原因,并得以及时解决。
最近在Oracle 9i中遇到过另外一个类似案例,同样是Library Cache Latch和Shared Pool Latch竞争,类似的在v$sqlarea中发现大量高version_count的SQL。
对于version_count过高的问题,可以查询V$SQL_SHARED_CURSOR视图,这个视图会给出SQL不能共享的具体原因,如果是正常因素导致的,相应的字段会被标记为“Y”;对于异常的情况(如本案例),查询结果可能显示的都是“N”,这就表明Oracle认为这种行为是正常的,在当前系统设置下,这些SQL不应该被共享,那么可以判断是某个参数设置引起的。和SQL共享关系最大的一个初始化参数就是cursor_sharing,在这个案例中cursor_sharing参数被设置为similar,正是这个设置导致了大量子指针不能共享。
搜索Metalink可以获得相关说明,当cursor_sharing参数设置为similar,并且数据库存在相关柱状图(histograms)信息时,对于每一条新执行的SQL,Oracle都通过硬解析以获得更为精确的执行计划,这最终导致了version_count过高,这是cursor_sharing = similar的正常行为,并非Bug。
了解了这个行为之后,解决这个问题也就并不复杂了,可以将cursor_sharing设置为Exact 或者Force以避免此问题,或者通过删除柱状图信息(Histograms)来防止不必要的硬解析,实际上,如果数据不存在失衡分布,我们也不必要收集柱状图信息。
这两个案例给我们的另外一个启示就是,当需要设置某些特殊的参数来影响数据库的行为时,必须了解这些设置会给数据库带来的影响,这样一方面可以避免问题的出现,另一方面在问题出现时,我们可以快速地发现问题根源并解决问题。