关于shared pool的深入探讨六（转）

关于shared pool的深入探讨六[@more@]

研究了几天shared pool，没想到忽然就撞到问题上来了。作为一个案例写出来给大家参考一下吧。

问题起因是公司做短信群发,就是那个18万买的4000字的短信小说(嘘,小声点,我也没看过...)。群发的时候每隔一段时间就会发生一次消息队列拥堵的情况，在数据库内部实际上是向一个数据表中记录发送日志。

我们介入来检查数据库的问题,在一个拥堵时段我开始诊断:

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 2 pmon timer 300 0000012C 1 rdbms ipc message 300 0000012C 4 rdbms ipc message 300 0000012C 6 rdbms ipc message 180000 0002BF20 SID EVENT P1 P1RAW ---------- ---------------------------------------------------------------- ---------- -------- 18 rdbms ipc message 6000 00001770 102 rdbms ipc message 6000 00001770 311 rdbms ipc message 6000 00001770 194 rdbms ipc message 6000 00001770 178 rdbms ipc message 6000 00001770 3 log file parallel write 1 00000001 13 log file sync 2705 00000A91 16 log file sync 2699 00000A8B 104 log file sync 2699 00000A8B 308 log file sync 2694 00000A86 262 log file sync 2705 00000A91 SID EVENT P1 P1RAW ---------- ---------------------------------------------------------------- ---------- -------- 172 log file sync 2689 00000A81 169 log file sync 2705 00000A91 108 log file sync 2694 00000A86 38 log file sync 2707 00000A93 34 db file scattered read 63 0000003F 5 smon timer 300 0000012C 27 SQL*Net message to client 1413697536 54435000 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 SID EVENT P1 P1RAW ---------- ---------------------------------------------------------------- ---------- -------- 273 log file sync 2544 000009F0 190 log file sync 2545 000009F1 5 smon timer 300 0000012C 14 rows selected.

接下来我们来看这些latch free等待的是哪些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 800023A0 7 cached attr list 0 0 80002628 10 event group latch 2391668 0 ..... 80003F3C 28 message pool operations parent latch 3 0 ..... 80006030 60 mostly latch-free SCN 19 0 80005F8C 59 file number translation table 68 0 80005F14 58 dlm cr bast queue latch 0 0 80005E8C 57 name-service request 0 0 80005E14 56 name-service memory objects 0 0 80005DA0 55 name-service namespace bucket 0 0 ADDR LATCH# NAME GETS SPIN_GETS -------- ---------- ------------------------------------------------ ---------- 80005D2C 54 name-service pending queue 0 0 80005CB4 53 name-service request queue 0 0 80004E08 52 name-service entry 0 0 80008AB0 76 KCL lock element parent latch 0 0 80008A48 75 KCL instance latch 0 0 80007F18 73 redo copy 816 0 80007BBC 71 archive process latch 0 0 80007B54 70 archive control 1 0 80006A10 68 Active checkpoint queue latch 2003308 0 800064B0 66 large memory latch 0 0 80006448 65 cache protection latch 0 0 ADDR LATCH# NAME GETS SPIN_GETS -------- ---------- ------------------------------------------------ ---------- 800060EC 61 batching SCNs 0 0 8000CAB0 96 global transaction 6833807 0 8000CA48 95 global tx free list 58258 0 8000C238 93 cost function 0 0 80009FCC 91 temp lob duration state obj allocation 0 0 8000995C 87 ktm global data 8118 0 80009228 84 transaction branch allocation 282388 0 80008EC4 80 begin backup scn array 6968 0 80008D54 79 loader state object freelist 42712 0 80008B80 78 KCL freelist latch 0 0 80008B18 77 KCL name table latch 0 0 ADDR LATCH# NAME GETS SPIN_GETS -------- ---------- ------------------------------------------------ ---------- 8000D484 118 presentation list 0 0 8000D41C 117 session timer 855944 0 ..... 8000E9D0 129 process queue 44 0 8000E900 127 query server freelists 66 0 8000FC84 140 AQ Propagation Scheduling System Load 0 0 8000E898 126 query server process 10 0 8000E27C 125 job_queue_processes parameter latch 111937 0 8000DA1C 124 NLS data objects 2 0 ADDR LATCH# NAME GETS SPIN_GETS -------- ---------- ------------------------------------------------ ---------- 8000D95C 123 ncodef allocation latch 111937 0 8000D674 122 virtual circuits 0 0 8000D60C 121 virtual circuit queues 159877 0 8000D5A4 120 virtual circuit buffers 0 0 8000D4EC 119 address list 2 0 ..... 8000CD70 102 Direct I/O Adaptor 2 0 ..... 80002408 8 GDS latch 30 0 800092E4 85 sort extent pool 69834 1 8000EC38 132 parallel query alloc buffer 80 1 8000E968 128 error message lists 22 1 80001400 4 process group creation 2615542 2 8000EAA0 131 parallel query stats 14 2 ADDR LATCH# NAME GETS SPIN_GETS -------- ---------- ------------------------------------------------ ---------- 8000CD08 101 Token Manager 1151107 2 8000CB18 97 global tx hash mapping 507846 2 80006378 63 cache buffer handles 315924 4 8000EA38 130 process queue reference 190993 5 80003E3C 26 channel handle pool latch 2391680 18 80003EAC 27 channel operations parent latch 4783425 24 80009B90 89 intra txn parallel recovery 32654 33 8000FCF8 141 fixed table rows for x$hs_session 161368 41 800012C8 1 process allocation 2391688 154 80009B28 88 parallel txn reco latch 174519 271 8000CCA0 100 library cache load lock 14947545 5958 ADDR LATCH# NAME GETS SPIN_GETS -------- ---------- ------------------------------------------------ ---------- 8000C8D0 94 user lock 13086412 6078 8000914C 82 list of block allocation 120650357 12024 80006A78 69 Checkpoint queue latch 154361751 17686 80009D34 90 sequence cache 64611720 32027 80009090 81 dml lock allocation 234465024 45351 800091C0 83 transaction allocation 214227648 48345 800096AC 86 undo global data 188271244 49641 800028A0 13 enqueue hash chains 373244264 131322 80007E04 72 redo allocation 439389808 201498 80001468 5 session idle bit 2039097976 204969 80002838 12 enqueues 471338482 273695 ADDR LATCH# NAME GETS SPIN_GETS -------- ---------- ------------------------------------------------ ---------- 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. SQL> select startup_time from v$instance; STARTUP_T --------- 13-AUG-04 检查数据库启动时间

我们注意到,在当前数据库中竞争最严重的两个latch是shared pool和library cache.显然这极有可能是SQL的过度解析造成的。进一步我们检查v$sqlarea发现:

SQL> select sql_text,VERSION_COUNT,INVALIDATIONS,PARSE_CALLS,OPTIMIZER_MODE, PARSING_USER_ID,PARSING_SCHEMA_ID,ADDRESS,HASH_VALUE from v$sqlarea where version_count >1000; 2 SQL_TEXT ------------------------------------------------------------------------------------------------------------------------ VERSION_COUNT INVALIDATIONS PARSE_CALLS OPTIMIZER_MODE PARSING_USER_ID PARSING_SCHEMA_ID 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的竞争。

这时候我开始猜测原因:

1.可能代码存在问题,在每次执行之前程序修改某些session参数,导致sql不能共性

2.可能是8.1.5的v$sqlarea记录存在问题,我们看到的结果是假象:)

3.Bug

Ok,我们的诊断不能停。最直接的我dump内存来看:

SQL> ALTER SESSION SET EVENTS 'immediate trace name LIBRARY_CACHE level 4';

察看trace文件得到如下结果(摘录包含该段代码的片断):

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 4 c1589040 bfd17a18 c35f1388 5 c1589040 bfd17a34 c77401bc 6 c1589040 bfd17a50 c4092838 7 c1589040 bfddb310 c6cd5258 8 c1589040 bfddb32c c63c6650 9 c1589040 bfddb348 c7e4e3d0 10 c1589040 bfddb364 c4c4b110 11 c1589040 bfddb380 c5950348 12 c1589040 bfddb39c c6c33aa4 13 c1589040 bfddb3b8 c672b0bc ........................................... .....ignore losts of child cursor here..... ........................................... 7001 bf595bc8 c641fba0 c6467890 7002 bf595bc8 c641fbbc c3417168 7003 bf595bc8 c641fbd8 c3417bb0 7004 bf595bc8 c641fbf4 c2fdccbc 7005 bf595bc8 c641fc10 c7f7ca50 7006 bf595bc8 c641fc2c c7f508ec 7007 bf595bc8 c641fc48 c268d8d8 7008 c641fcb8 c641fc64 bec61ed8 7009 c641fcb8 c641fc80 c4a6cc5c 7010 c641fcb8 c641fc9c c1a8aa34 7011 c641fcb8 c0ae4ea0 c0ae4ddc 7012 c641fcb8 c0ae4ebc bd55fe60 7013 c641fcb8 c0ae4ed8 c226914c 7014 c641fcb8 c0ae4ef4 c51dd2e0 7015 c641fcb8 c0ae4f10 c480c468 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

这里确实存在7023个子指针

查询v$sql得到相同的结果:

SQL> select CHILD_NUMBER,EXECUTIONS,OPTIMIZER_MODE,OPTIMIZER_COST,PARSING_USER_ID, 2 PARSING_SCHEMA_ID,ADDRESS,HASH_VALUE 3 from v$sql where HASH_VALUE='3974744754'; CHILD_NUMBER EXECUTIONS OPTIMIZER_ OPTIMIZER_COST PARSING_USER_ID PARSING_SCHEMA_ID ADDRESS HASH_VALUE ------------ ---------- ------ ---------- ------------- ------------ -------- ---------- 0 12966 CHOOSE 238150 36 36 C82AF1C8 3974744754 1 7111 CHOOSE 238150 36 36 C82AF1C8 3974744754 2 9160 CHOOSE 238150 36 36 C82AF1C8 3974744754 3 9127 CHOOSE 238150 36 36 C82AF1C8 3974744754 4 8109 CHOOSE 238150 36 36 C82AF1C8 3974744754 5 4386 CHOOSE 238150 36 36 C82AF1C8 3974744754 6 4913 CHOOSE 238150 36 36 C82AF1C8 3974744754 7 3764 CHOOSE 238150 36 36 C82AF1C8 3974744754 8 3287 CHOOSE 238150 36 36 C82AF1C8 3974744754 9 3156 CHOOSE 238150 36 36 C82AF1C8 3974744754 ..... 7015 1 CHOOSE 238150 36 36 C82AF1C8 3974744754 7016 1 CHOOSE 238150 36 36 C82AF1C8 3974744754 7017 0 CHOOSE 238150 36 36 C82AF1C8 3974744754 7018 9396 NONE 0 0 C82AF1C8 3974744754 7019 5008 CHOOSE 237913 36 36 C82AF1C8 3974744754 来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/9417382/viewspace-937434/，如需转载，请注明出处，否则将追究法律责任。 0 0 分享到： 上一篇： 关于shared pool的深入探讨五（转） 下一篇： 使用ERRORSTACK进行错误跟踪及诊断（转） 请登录后发表评论 登录 全部评论 <%=items[i].createtime%> <%=items[i].content%> <%if(items[i].items.items.length) { %> <%for(var j=0;j <%=items[i].items.items[j].createtime%> 回复 <%=items[i].items.items[j].username%>   回复   <%=items[i].items.items[j].tousername%>： <%=items[i].items.items[j].content%> <%}%> <%if(items[i].items.total > 5) { %> 还有<%=items[i].items.total-5%>条评论 ) data-count=1 data-flag=true>点击查看 <%}%> <%}%> <%}%> Rounders 博文量 115 访问量 475861 最新文章 Linux操作系统中备份恢复技术的应用（转） [Oracle]分布式系统的数据复制技术（转） 数据备份方法及灾难恢复探讨(转) Unix备份与压缩命令实践（转） Linux系统在存储技术中的几项应用（转） 在遭遇破坏前对企业数据进行安全防护(转) 红帽Linux平台：虚拟化技术发展详解(2)（转） Linux下多线程编程与信号处理易疏忽的一个例子(转) 简述 Linux 文件系统的目录结构（转） Linux上glibc的man手册关于timeval结构解释的错误(转) 支持我们 作者招募 用户协议 FAQ Contact Us 北京盛拓优讯信息技术有限公司. 版权所有  京ICP备09055130号-4  北京市公安局海淀分局网监中心备案编号：11010802021510 广播电视节目制作经营许可证(京) 字第1234号 中国互联网协会会员

转载于:http://blog.itpub.net/9417382/viewspace-937434/