暂无图片
暂无图片
暂无图片
暂无图片
暂无图片

诊断案例一:version_count过高造成的Latch竞争解决

原创 Eygle 2019-07-24
1228

本节是关于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)来防止不必要的硬解析,实际上,如果数据不存在失衡分布,我们也不必要收集柱状图信息。

这两个案例给我们的另外一个启示就是,当需要设置某些特殊的参数来影响数据库的行为时,必须了解这些设置会给数据库带来的影响,这样一方面可以避免问题的出现,另一方面在问题出现时,我们可以快速地发现问题根源并解决问题。


「喜欢这篇文章,您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容,转载时必须标注文章的来源(墨天轮),文章链接,文章作者等基本信息,否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容,欢迎发送邮件至:contact@modb.pro进行举报,并提供相关证据,一经查实,墨天轮将立刻删除相关内容。

评论