客户的一套重要生产系统，出现了性能问题。这个问题涉及的信息如下：
- 数据库主机的CPU利用率长期在100%左右。
- 应用系统在晚上进行调整后，开始出现了问题。
- 数据库中出现大量的latch: shared pool、latch: library cache、cursor: pin S、latch: cache buffers chains和latch: cache buffers lru chain等各种等待。
- 由于系统较大，整个系统实际上被分成了2个部分，每个部分服务不同的用户。二者的应用基本相同，分别对应2套数据库，二者也同样在出问题之前进行了调整，而数据库的主机配置及参数也是相同的，同时均为10.2.0.5双节点RAC数据库。但是只有其中1套库有性能问题。
- 2套库的配置虽然没有差别，但是负载方式却有很大的区别，正常的那套库，2个节点的负载基本上是均衡的，而现在有性能问题的这套库，所有的负载基本上全部在第1个节点上（虽然已经多次要求开发商整改，不幸的是...这里不用说了）。
下面是AWR报告中的数据：
性能正常时间段的数据（采集时间2小时）：
Snap Id Snap Time Sessions Curs/Sess --------- ------------------- -------- --------- Begin Snap: 3408 19-Sep-11 09:00:21 4,690 39.5 End Snap: 3412 19-Sep-11 11:00:07 4,950 38.7 Elapsed: 119.76 (mins) DB Time: 2,900.95 (mins) Cache Sizes ~~~~~~~~~~~ Begin End ---------- ---------- Buffer Cache: 35,840M 35,840M Std Block Size: 8K Shared Pool Size: 6,144M 6,144M Log Buffer: 30,632K Load Profile ~~~~~~~~~~~~ Per Second Per Transaction --------------- --------------- Redo size: 1,968,314.84 6,360.04 Logical reads: 1,038,182.89 3,354.59 Block changes: 148,577.35 480.09 Physical reads: 3,541.98 11.44 Physical writes: 546.31 1.77 User calls: 7,811.87 25.24 Parses: 3,187.30 10.30 Hard parses: 10.07 0.03 Sorts: 6,258.90 20.22 Logons: 9.65 0.03 Executes: 24,100.52 77.87 Transactions: 309.48 Instance Efficiency Percentages (Target 100%) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Buffer Nowait %: 100.00 Redo NoWait %: 100.00 Buffer Hit %: 99.69 In-memory Sort %: 100.00 Library Hit %: 99.36 Soft Parse %: 99.68 Execute to Parse %: 86.77 Latch Hit %: 99.64 Parse CPU to Parse Elapsd %: 45.61 % Non-Parse CPU: 99.46 Shared Pool Statistics Begin End ------ ------ Memory Usage %: 95.44 94.46 % SQL with executions>1: 89.10 77.18 % Memory for SQL w/exec>1: 87.82 76.62 Top 5 Timed Events Avg %Total ~~~~~~~~~~~~~~~~~~ wait Call Event Waits Time (s) (ms) Time Wait Class ------------------------------ ------------ ----------- ------ ------ ---------- CPU time 114,107 65.6 db file sequential read 8,232,067 40,956 5 23.5 User I/O db file scattered read 929,509 2,392 3 1.4 User I/O log file sync 2,119,459 2,372 1 1.4 Commit SQL*Net message from dblink 1,375,619 1,576 1 0.9 Network ------------------------------------------------------------- ^LWait Events DB/Inst: CRM2DB/crm2db1 Snaps: 3408-3412 -> s - second -> cs - centisecond - 100th of a second -> ms - millisecond - 1000th of a second -> us - microsecond - 1000000th of a second -> ordered by wait time desc, waits desc (idle events last) -> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0 Avg %Time Total Wait wait Waits Event Waits -outs Time (s) (ms) /txn ---------------------------- -------------- ----- ----------- ------- --------- db file sequential read 8,232,067 N/A 40,956 5 3.7 db file scattered read 929,509 N/A 2,392 3 0.4 log file sync 2,119,459 0 2,372 1 1.0 SQL*Net message from dblink 1,375,619 N/A 1,576 1 0.6 SQL*Net more data from clien 1,871,442 N/A 1,428 1 0.8 control file sequential read 3,010,438 N/A 1,179 0 1.4 Backup: sbtbackup 12 N/A 1,167 97243 0.0 gc cr grant 2-way 3,688,572 N/A 993 0 1.7 log file parallel write 2,205,552 N/A 974 0 1.0 gc cr multi block request 2,378,748 N/A 721 0 1.1 gc current block 2-way 1,941,104 N/A 693 0 0.9 SQL*Net more data to client 5,142,664 N/A 498 0 2.3 gc buffer busy 166,717 0 428 3 0.1 direct path read 424,645 N/A 344 1 0.2 db file parallel read 61,816 N/A 298 5 0.0 enq: HW - contention 17,487 0 216 12 0.0 db file parallel write 221,865 N/A 210 1 0.1 Backup: sbtwrite2 36,271 N/A 145 4 0.0 gc current grant 2-way 445,456 N/A 115 0 0.2 enq: TM - contention 255 74 102 400 0.0
在应用调整第2天上午的awr数据（采集时长1小时）：
Load Profile ~~~~~~~~~~~~ Per Second Per Transaction --------------- --------------- Redo size: 2,420,236.58 6,734.48 Logical reads: 1,277,888.60 3,555.82 Block changes: 164,638.57 458.12 Physical reads: 1,208.59 3.36 Physical writes: 456.79 1.27 User calls: 8,785.42 24.45 Parses: 4,103.35 11.42 Hard parses: 12.87 0.04 Sorts: 8,052.30 22.41 Logons: 9.05 0.03 Executes: 32,573.41 90.64 Transactions: 359.38 % Blocks changed per Read: 12.88 Recursive Call %: 85.01 Rollback per transaction %: 0.19 Rows per Sort: 8.74 Instance Efficiency Percentages (Target 100%) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Buffer Nowait %: 99.97 Redo NoWait %: 100.00 Buffer Hit %: 99.92 In-memory Sort %: 100.00 Library Hit %: 99.92 Soft Parse %: 99.69 Execute to Parse %: 87.40 Latch Hit %: 99.33 Parse CPU to Parse Elapsd %: 29.94 % Non-Parse CPU: 99.17 Shared Pool Statistics Begin End ------ ------ Memory Usage %: 95.42 95.02 % SQL with executions>1: 61.41 72.38 % Memory for SQL w/exec>1: 60.04 73.07 Top 5 Timed Events Avg %Total ~~~~~~~~~~~~~~~~~~ wait Call Event Waits Time (s) (ms) Time Wait Class ------------------------------ ------------ ----------- ------ ------ ---------- CPU time 69,736 56.2 Backup: sbtwrite2 2,319,231 22,510 10 18.1 Administra db file sequential read 3,476,830 20,923 6 16.9 User I/O latch: shared pool 159,416 9,280 58 7.5 Concurrenc Backup: sbtbackup 28 2,746 98056 2.2 Administra ------------------------------------------------------------- ^LWait Events DB/Inst: CRM2DB/crm2db1 Snaps: 3602-3604 -> s - second -> cs - centisecond - 100th of a second -> ms - millisecond - 1000th of a second -> us - microsecond - 1000000th of a second -> ordered by wait time desc, waits desc (idle events last) -> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0 Avg %Time Total Wait wait Waits Event Waits -outs Time (s) (ms) /txn ---------------------------- -------------- ----- ----------- ------- --------- Backup: sbtwrite2 2,319,231 N/A 22,510 10 1.8 db file sequential read 3,476,830 N/A 20,923 6 2.7 latch: shared pool 159,416 N/A 9,280 58 0.1 Backup: sbtbackup 28 N/A 2,746 98056 0.0 log file sync 1,283,319 0 2,538 2 1.0 gc buffer busy 1,088,432 0 2,324 2 0.8 latch: library cache 31,278 N/A 1,328 42 0.0 control file sequential read 1,512,218 N/A 1,082 1 1.2 log file parallel write 1,157,491 N/A 1,045 1 0.9 SQL*Net message from dblink 952,956 N/A 987 1 0.7 SQL*Net more data from clien 962,454 N/A 837 1 0.7 kst: async disk IO 17,574 N/A 483 27 0.0 gc cr grant 2-way 1,539,289 N/A 439 0 1.2 gc current block 2-way 946,330 N/A 353 0 0.7 direct path read 291,853 N/A 313 1 0.2 db file parallel write 261,735 N/A 298 1 0.2 read by other session 92,451 0 270 3 0.1 cursor: pin S 304,676,088 N/A 233 0 235.1 db file scattered read 28,062 N/A 132 5 0.0 enq: TX - row lock contentio 466 52 123 263 0.0 direct path write 227,989 N/A 113 0 0.2
从Load profile数据对比来看，应用调整后系统负载有一定的提高，同时每事务逻辑读也有一定的增加（不足10%）。这会是个问题吗？
从第2份数据来看，latch: shared pool 和 latch: library cache有明显的增加。
下面的是性能问题更加严重的时候的AWR数据（采集时长为2小时）：
Snap Id Snap Time Sessions Curs/Sess --------- ------------------- -------- --------- Begin Snap: 3744 26-Sep-11 09:00:01 4,504 38.2 End Snap: 3748 26-Sep-11 11:00:26 4,916 52.7 Elapsed: 120.41 (mins) DB Time: 21,868.27 (mins) Cache Sizes ~~~~~~~~~~~ Begin End ---------- ---------- Buffer Cache: 35,840M 35,840M Std Block Size: 8K Shared Pool Size: 6,144M 6,144M Log Buffer: 30,632K Load Profile ~~~~~~~~~~~~ Per Second Per Transaction --------------- --------------- Redo size: 1,790,430.57 5,945.33 Logical reads: 1,162,875.15 3,861.46 Block changes: 154,064.15 511.59 Physical reads: 3,007.80 9.99 Physical writes: 337.21 1.12 User calls: 8,227.28 27.32 Parses: 3,603.24 11.96 Hard parses: 11.25 0.04 Sorts: 7,304.40 24.26 Logons: 11.27 0.04 Executes: 25,994.53 86.32 Transactions: 301.15 % Blocks changed per Read: 13.25 Recursive Call %: 82.87 Rollback per transaction %: 0.21 Rows per Sort: 8.14 Instance Efficiency Percentages (Target 100%) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Buffer Nowait %: 99.99 Redo NoWait %: 100.00 Buffer Hit %: 99.75 In-memory Sort %: 100.00 Library Hit %: 99.94 Soft Parse %: 99.69 Execute to Parse %: 86.14 Latch Hit %: 98.90 Parse CPU to Parse Elapsd %: 14.69 % Non-Parse CPU: 84.51 Shared Pool Statistics Begin End ------ ------ Memory Usage %: 95.48 94.33 % SQL with executions>1: 87.63 74.92 % Memory for SQL w/exec>1: 86.52 74.66 Top 5 Timed Events Avg %Total ~~~~~~~~~~~~~~~~~~ wait Call Event Waits Time (s) (ms) Time Wait Class ------------------------------ ------------ ----------- ------ ------ ---------- latch: shared pool 991,918 274,715 277 20.9 Concurrenc latch: library cache 941,443 232,344 247 17.7 Concurrenc CPU time 212,150 16.2 cursor: pin S ############ 115,049 0 8.8 Other latch: cache buffers lru chain 1,106,570 96,442 87 7.4 Other ------------------------------------------------------------- ^LWait Events DB/Inst: CRM2DB/crm2db1 Snaps: 3744-3748 -> s - second -> cs - centisecond - 100th of a second -> ms - millisecond - 1000th of a second -> us - microsecond - 1000000th of a second -> ordered by wait time desc, waits desc (idle events last) -> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0 Avg %Time Total Wait wait Waits Event Waits -outs Time (s) (ms) /txn ---------------------------- -------------- ----- ----------- ------- --------- latch: shared pool 991,918 N/A 274,715 277 0.5 latch: library cache 941,443 N/A 232,344 247 0.4 cursor: pin S 9,095,470,035 N/A 115,049 0 4,180.5 latch: cache buffers lru cha 1,106,570 N/A 96,442 87 0.5 db file sequential read 7,819,285 N/A 49,564 6 3.6 latch: cache buffers chains 511,936 N/A 35,753 70 0.2 latch free 95,257 0 14,609 153 0.0 latch: object queue header o 221,907 N/A 14,378 65 0.1 log file sync 2,156,343 1 11,496 5 1.0 cursor: pin S wait on X 422,320 100 4,603 11 0.2 gc cr grant 2-way 3,526,856 0 3,430 1 1.6 db file scattered read 624,480 N/A 3,083 5 0.3 enq: TX - row lock contentio 5,946 88 2,600 437 0.0 latch: row cache objects 16,983 N/A 2,281 134 0.0 SQL*Net message from dblink 1,284,487 N/A 2,179 2 0.6 gc buffer busy 353,228 0 2,054 6 0.2 gc cr multi block request 2,499,709 0 1,974 1 1.1 gc current block 2-way 1,969,516 0 1,920 1 0.9 SQL*Net more data from clien 1,667,513 N/A 1,914 1 0.8 control file sequential read 2,974,349 N/A 1,735 1 1.4 db file parallel read 230,795 N/A 1,645 7 0.1 log file parallel write 1,581,432 N/A 1,303 1 0.7 Backup: sbtbackup 14 N/A 730 52120 0.0 buffer busy waits 143,869 0 488 3 0.1 latch: library cache lock 5,058 N/A 378 75 0.0 enq: HW - contention 22,039 0 370 17 0.0 gc current grant 2-way 424,243 N/A 357 1 0.2 enq: SQ - contention 5,010 1 354 71 0.0 read by other session 50,153 0 339 7 0.0 direct path read 324,226 N/A 305 1 0.1 db file parallel write 207,793 N/A 274 1 0.1 row cache lock 175,301 0 263 1 0.1
从第3份数据来看，性能更为恶化，情形更为复杂。
那么针对这个性能现象，可以提出如下的问题：
- 最直观的，最容易想到的就是，性能问题的出现是否与应用调整有关，如果是，为什么另一套库没有出现问题？会不会是另一套库的负载在2个节点都有相对均衡的负担，而出问题的库，负载全部集中在1个节点上引起？
- 客户是在应用调整几天后才报告性能问题，这个问题会不会是一个逐渐出现的问题？如果一开始就有严重的性能问题，那么应该会很快报告。不过中间跨了一个周末，所以对于”逐渐出现问题“的判断又加了一些难度。
- 这么多的性能问题相关的现象中，哪个更贴近问题的原因？实际上在主机的CPU长期保持在100%左右时，会放大平时的一些轻微的问题，或者引起另一些问题。从等待来看，latch: cache buffers chains和cursor: pin S都会引起CPU的急剧增加，而其他的latch竞争同样也会引起CPU的上升，虽然上升没有前者大。到底是SQL执行效率不高引起CPU急剧增加然后引起了shared pool latch等与解析相关的资源争用还是因为解析相关的问题导致CPU急剧增加引起了cache buffers chains等与SQL执行相关的latch争用？或者是2者的共同作用？
下面首先来分析，会不会是应用调整引起的问题，也就是说，是不是由SQL引起的问题。如果是SQL引起的问题，会有几种可能，1是部分频繁执行的SQL执行效率变差；2是增加了很多的硬解析；3是并发增加或者说是SQL的执行次数有上升。仔细检查对比现在和以前的AWR数据，可以排除第1和2这种可能。至于第3种，可能略有增加，但是不一定跟应用调整有关，毕竟正常情况下业务量的变化也是有可能的。所以应用调整引起问题的可能性较小。
会不会是因为负载过大引起的问题，这个很容易验证。取业务低谷期，比如下班时间的数据，进行分析可以发现，既然在CPU在稍低(75%以下）的时候，仍然有大量的library cache latch的争用。下面是取自周日19:00-20:00的AWR数据（注：本文涉及故障的分析时间是在星期一）：
Top 5 Timed Events Avg %Total ~~~~~~~~~~~~~~~~~~ wait Call Event Waits Time (s) (ms) Time Wait Class ------------------------------ ------------ ----------- ------ ------ ---------- CPU time 49,224 48.3 latch: shared pool 185,951 41,178 221 40.4 Concurrenc latch: library cache 45,636 8,861 194 8.7 Concurrenc db file sequential read 815,066 4,763 6 4.7 User I/O cursor: pin S ############ 1,732 0 1.7 Other ------------------------------------------------------------- Avg %Time Total Wait wait Waits Event Waits -outs Time (s) (ms) /txn ---------------------------- -------------- ----- ----------- ------- --------- latch: shared pool 185,951 N/A 41,178 221 0.6 latch: library cache 45,636 N/A 8,861 194 0.2 db file sequential read 815,066 N/A 4,763 6 2.8 cursor: pin S 1,890,998,700 N/A 1,732 0 6,459.2 latch free 8,549 0 1,278 150 0.0 control file sequential read 1,507,789 N/A 466 0 5.2 Backup: sbtbackup 7 N/A 428 61096 0.0 log file sync 285,442 0 309 1 1.0 SQL*Net more data from clien 145,137 N/A 221 2 0.5 db file scattered read 67,716 N/A 173 3 0.2 gc buffer busy 56,842 0 135 2 0.2 gc cr grant 2-way 359,146 N/A 99 0 1.2 SQL*Net message from dblink 123,206 N/A 98 1 0.4 log file parallel write 289,048 N/A 91 0 1.0 SQL*Net more data to client 1,242,471 N/A 79 0 4.2 gc current block 2-way 179,654 N/A 66 0 0.6 direct path read 62,336 N/A 65 1 0.2 gc cr multi block request 228,693 N/A 52 0 0.8
至于性能问题是不是逐渐引起的，这个问题目前并不关键，暂时不考虑。只是做为后面分析问题的一个参考。
再看最后一个问题，这些性能现象中，哪一个更接近问题的原因？幸庆的是，从上面的业务低谷期数据可以看到，这个时候的等待主要是跟解析相关的等待，而其他的latch: cache buffers lru chain等与SQL执行期相关的等待已经不再明显。
所以到此阶段的结论是：性能并不是由于应用调整引起、与负载关系不是太大、主要是与shared pool latch等解析相关的争用有关。
进一步分析上面的数据，其实可以看到latch: shared pool的等待时间占主导地位，同时由于shared pool latch的争用也会一定程度上引起library cache latch的争用（请参考我的另一篇文章《shared pool latch和library cache latch》），所以我们这里主要考虑是什么引起了shared pool latch的争用。另外，cursor: pin S的等待是一个极少出现的等待，一般是由于bug或者高并发地执行同一条SQL引起。那么，cursor: pin S会跟shared pool latch的争用有所关联么？目前不得而知。或者这3者都是相关的？
基于上面的分析，下面重点来分析shared pool latch的争用。使用上面提及的业务低谷期的AWR数据，因为这个时候没有了其他的干扰，更容易分析：
^LLatch Miss Sources DB/Inst: CRM2DB/crm2db1 Snaps: 3716-3718 -> only latches with sleeps are shown -> ordered by name, sleeps desc NoWait Waiter Latch Name Where Misses Sleeps Sleeps ------------------------ -------------------------- ------- ---------- -------- library cache kglpndl: child: after proc 0 19,599 55 library cache kglpndl: child: before pro 0 12,653 1,969 library cache kglpnp: child 0 10,188 34,808 library cache kglLockCursor 0 632 1,539 library cache kglhdgn: child: 0 487 3,729 library cache kglobpn: child: 0 408 2,077 library cache kgldte: child 0 0 381 747 library cache kglukp: child 0 184 66 library cache kglati 0 52 1 library cache kqlmbpil: parent 0 52 4 library cache kglpin 0 38 9 library cache kgldti: 2child 0 32 0 library cache kglhdbrnl: child 0 13 29 library cache kglhdgc: child: 0 9 0 library cache kglobld 0 4 0 library cache kglic 0 2 7 library cache kglini: child 0 1 0 shared pool kghupr1 0 168,465 148,602 shared pool kghalo 0 9,881 23,589 shared pool kghfre 0 7,136 13,425 shared pool kghfrunp: clatch: nowait 0 470 0 shared pool kghalp 0 204 82 shared pool kghfrunp: alloc: wait 0 9 0 shared pool kghfrunp: clatch: wait 0 5 15 shared pool kghasp 0 4 0 shared pool kghfrh 0 3 0 shared pool simulator kglsim_unpin_simhp 0 319 70 shared pool simulator kglsim_scan_lru: scan 0 3 101 shared pool simulator kglsim_upd_newhp 0 3 89 shared pool simulator kglsim_chg_simhp_free 0 1 25 slave class create ksvcreate 0 2 0
那么从Latch Miss Source的数据可以看到，对于shared pool latch，绝大部分的sleep发生在kghupr1这个函数这里。在oracle中kghupr1这个函数是干什么的呢，简单来说就是un-pin recreatable内存块，其主要目的是要将creatable的内存块链接到shared pool的LRU链表中，在这个过程中要持有shared pool latch。这里我们可以确认不是由于在shared pool中的内存分配引起了latch的争用，而是在sql的execute阶段完成后才应该发生的争用。
从上面的数据同样可以看到，library cache latch的争用主要发生在kglpndl (KGL PiN DeLete)。
再来考虑cursor: pin S等待，这个等待通常发生在2个时间点，第1个是在SQL软解析对cursor进行PIN时增加mutex的引用计数时发生；第2个是在cursor执行完un-PIN时，减少mutex的引用计数时发生。
实际上在SQL整个执行过程中，除了parse阶段，在execute完成后（注意，可能是在fetch完成之前）同样会有shared pool latch、shared pool latch的获取。因为执行后要执行很多的操作，比如将recreated chunk链接到LRU链表中，更新sql的统计信息，un-pin cursor以及引用的某些对象等待。
以上三者，将线索都指向了SQL语句execute完成之后的阶段，这里execute指的是SQL语句的open-parse-execute-fetch-close等诸多步骤中的一个，而不是我们通常所讲的”执行“。
从出现性能问题后的几个不同时间段的AWR报告中，从数据上看现象是一致的，上述结论是可以成立的。
如果是一个问题的事后分析，到现在这里，如果再继续深入就非常困难了。还好在分析问题时，问题依然存在。
通过对数据库的实时分析，可以发现以下几点：
- latch: shared pool、latch: library cache、cursor: pin S这三种基本上都是同时出现，这也验证了前面的结论，这3者是相关的。
- 等待cursor: pin S的会话其当前的SQL通常为2条并发量很高的SQL，这几条SQL都是存储过程中的SQL，而执行存储过程并发量很高。latch: library cache等待的会话当前的SQL也类似此现象，当然这样的话library cache latch的争用就发生在极少数的child latch上。
- 等待latch: shared pool的会话其当前的SQL绝大部分为空，这似乎验证了之前提到的shared pool latch的争用发生在SQL执行完之后。同时shared pool latch争用全部发生在同一个child latch上，这个是极不寻常的。
然后使用来自Tanel Poder的脚本@latchprof进行更深入的分析：
SQL> @latchprofx sid,name,ksllwnam,ksllwlbl % library 10000 SID NAME KSLLWNAM KSLLWLBL Held Gets Held % Held ms ----- --------------- ----------------------------------- -------- ----- ---- ------- ----------- 3146 library cache kglpndl: child: after processing latch 2442 4 24.42 4595.844 3138 library cache kglpndl: child: after processing latch 2274 4 22.74 4279.668 694 library cache kglpndl: child: before processing latch 1443 2 14.43 2715.726 4198 library cache kglpndl: child: after processing latch 1214 2 12.14 2284.748 611 library cache kglpndl: child: after processing latch 1157 2 11.57 2177.474 638 library cache kglpndl: child: before processing latch 1123 2 11.23 2113.486 5949 library cache kglobpn: child: latch 1103 24 11.03 2075.846 5949 library cache kglukp: child child 1062 6 10.62 1998.684 584 library cache kglpndl: child: before processing latch 974 3 9.74 1833.068 5762 library cache kglpndl: child: before processing latch 960 2 9.60 1806.720 5204 library cache kgllkdl: child: no lock handle latch 923 1 9.23 1737.086 5949 library cache kghfrunp: clatch: nowait 888 17 8.88 1671.216 2338 library cache kglpndl: child: after processing latch 823 2 8.23 1548.886 6243 library cache kglpndl: child: before processing latch 822 2 8.22 1547.004 6184 library cache kglpndl: child: before processing latch 790 2 7.90 1486.780 4121 library cache kglpndl: child: after processing latch 684 2 6.84 1287.288 5601 library cache kglpndl: child: before processing latch 675 1 6.75 1270.350 3948 library cache kglpndl: child: before processing latch 657 1 6.57 1236.474 3277 library cache kglpndl: child: before processing latch 652 1 6.52 1227.064 SQL> @latchprofx sid,name,ksllwnam,ksllwlbl % shared 10000 SID NAME KSLLWNAM KSLLWLBL Held Gets Held % Held ms ---- ---------------------- ------------------- ------------- ---- ---------- ------- ----------- 2338 shared pool kghupr1 Chunk Header 2173 5 21.73 4343.827 2338 shared pool simulator kglsim_unpin_simhp 2172 4 21.72 4341.828 5710 shared pool kghalo 1107 15 11.07 2212.893 3423 shared pool simulator kglsim_unpin_simhp 1075 2 10.75 2148.925 3423 shared pool kghupr1 Chunk Header 1075 2 10.75 2148.925 5348 shared pool simulator kglsim_unpin_simhp 1025 2 10.25 2048.975 5348 shared pool kghupr1 Chunk Header 1025 2 10.25 2048.975 2895 shared pool kghupr1 Chunk Header 767 2 7.67 1533.233 2895 shared pool simulator kglsim_unpin_simhp 767 2 7.67 1533.233 4779 shared pool kghupr1 Chunk Header 609 1 6.09 1217.391 2602 shared pool kghupr1 Chunk Header 551 2 5.51 1101.449 2602 shared pool simulator kglsim_unpin_simhp 550 1 5.50 1099.450 4591 shared pool kghupr1 Chunk Header 523 1 5.23 1045.477 5164 shared pool simulator kglsim_unpin_simhp 518 1 5.18 1035.482 5164 shared pool kghupr1 Chunk Header 518 1 5.18 1035.482 3677 shared pool kghupr1 Chunk Header 493 1 4.93 985.507 3040 shared pool kghalo 329 1 3.29 657.671 2146 shared pool kghupr1 Chunk Header 272 1 2.72 543.728 2146 shared pool simulator kglsim_unpin_simhp 272 1 2.72 543.728 5949 shared pool kghalo 63 63 .63 125.937 5949 shared pool simulator kglsim_unpin_simhp 28 3 .28 55.972 5949 shared pool kghupr1 Chunk Header 28 3 .28 55.972 5949 shared pool simulator kglsim_upd_newhp 5 5 .05 9.995 0 shared pool kghalo 5 5 .05 9.995 1558 shared pool kghalo 3 3 .03 5.997 682 shared pool kghalo 2 2 .02 3.998
实际上在处理问题时，还查询了v$mutex_sleep的数据，不过在写这篇文章时，已经找不到了:)
当然latchprof这个脚本反复执行多次，以确认不会只是一个偶然的结果。从数据上来看，跟AWR的数据是相吻合的。然而，在shared pool latch请求的数据上有了新的发现，同一个会话，在kghupr1过程中请求和持有shared pool latch的时间，与kglsim_unpin_simhp过程中请求和持有shared pool simulator latch的时间几乎是一致的。这是一个很重要的发现!
查看shared pool simulator latch的level，发现其比shared pool latch的level高，这就是说，完全有可能shared pool latch的持有之后又去请求shared pool simulator latch，而由于shared pool simulator latch的竞争，而最终导致了shared pool latch的竞争。
shared pool simulator latch用于保护shared pool simulator相关的内存区域。那么shared pool simulator是干什么的呢？简单地说就是用于shared pool advisor。当library cache object被刷出shared pool时，将这个对象的关键信息比如hash value记录下来，当对象load时，会查找这个对象在之前是否存在过，以此来计算shared pool增加一定数量的内存时，会使Shared pool 增加多少命中率。可参考”KGL simulator, shared pool simulator and buffer cache simulator – what are these?“和http://stackoverflow.com/questions/183963/what-is-the-oracle-kgl-simulator。
而在MOS上，使用shared pool simulator为关键字搜索，可以找到一些BUG，比如”TST PERF _LIBRARY_CACHE_ADVICE CAUSES MORE SHARED POOL AND SIMULATOR LATCH GETS“，这个BUG虽然在10.2.0.5中已经修复，但其描述的现象至少证明了当shared pool simulator争用时，将导致shared pool latch的争用。
那么这个问题，到现在为止，大体上可以判断为shared pool simulator latch的争用引起了问题，接下来在业务不太繁忙时间将"_library_cache_advice"参数在线修改为FALSE，观察系统，发现系统有短暂的时间负载冲高，但是很快就恢复到以往的正常水平，长时间的观察发现性能问题已经解决。
虽然性能问题已经解决，但是留下来需要更深入的问题还有：
- cursor: pin S这个等待，在shared pool simulator latch争用时，是如何产生的？
- share pool simulator latch的争用是如何产生的，为什么之前没有，是什么引起的？是BUG吗？如果是BUG又是怎么触发的？实际上后面尝试将"_library_cache_advice"参数改回为TRUE，但是该性能问题并没有再次出现。
不幸的是，上述的问题都不容易回答。
写到这里，不得不写一点与trouble shooting方法相关的话题。对于一个问题，有的人喜欢找到问题的根源，然后去彻底解决它；有的人喜欢想办法先解决问题再说，至于找原因，事后再找。实际上我是介于二者之间。对于问题，首先尝试去分析产生的原因，即root cause，如果在某个时间点上，能够得到解决办法，或者寻找原因的时间过长，那么就会先偏向于解决问题。实际上针对这个案例，在问题解决之后其根源还没找到，但是如果只是一味去寻找原因，那毫无疑问，时间将会很长，即便是有原厂参与，这已经涉及到比较internal的东西。但是客户的系统能等那么久吗？显然不能。另外，对于一些解决方案，比如这个案例，修改隐含参数，因为没有找到根源，实际上当时并没有100%的把握，然而我是幸运的，因为客户信任我，才让实施这种不会100%能解决问题的方案。在不能100%保证能解决问题的情况下，可以做以下评估：就算不能解决问题，会不会有负面影响？针对这个案例来说，首先实施是在业务低谷期，负载不是最高的时候；其二，对于这个参数相对应的功能有相当的了解，比如shared pool advisor和db cache advisor我一直认为是比较鸡肋的功能，关闭之后对系统基本没什么影响。
解决问题，有时称之为排除问题，实际上就是排除一个个可能存在问题的点。而有时候的排除，需要一定的试验性质。有的客户总是希望什么问题只有在100%完全能够证明的情况下才允许对系统进行更改，不幸的是，很多复杂的问题，这样做几乎是不可能完成的任务。
同时，对于这个案例，如果仅从AWR很难发现这个问题，与shared pool simulator latch的争用有关，这个latch的等待时间与shared pool latch、library cache latch、cursor: pin S的等待相比，是如此的短。比如在分析问题的当天，性能问题最突出的2小时内，shared pool latch的等待时间为274,715秒，而shared pool simulator latch的等待时间只不过1555秒，甚至还不及row cache objects latch等待的2316秒。而shared pool simulator latch的miss percent也只不过0.1%，远远小于shared pool latch和library cache latch的miss percent。但是通过AWR分析给我们指明了方向，然后通过数据库的实时数据分析，最终找到了解决办法。
--后面有点乱，写好几个小时，思绪有点乱了....
--the end.
好长好长啊。。。。
这问题貌似非常怪异啊 那个隐含参数重新改成true后也不能复现问题？
估计也是再某些特定的情况下才能重现，能搞定问题就好，写的精辟啊！
[回复]
good！纠正一个笔误——“查看shared pool simulator latch的level，发现其比shared pool latch的level低”，这里应该是高。
[回复]
老熊 回复:
10月 8th, 2011 at 1:40 下午
@dbsnake, thanks.
[回复]
写的很好，受教了
从改回去问题仍然没有出现来看，有可能是bug，在某个特殊的情况下触发了
这种情况下想找到root cause非常困难
[回复]
感觉对于修改隐含参数这样的事，必须谨慎对待。
[回复]
受教了，谢谢
[回复]
老熊，
这句话怎么理解，是因为这两个latch获取的次数多？ latch: cache buffers chains是不是应该是 latch:cache buffers lru chain?
从等待来看，latch: cache buffers chains和cursor: pin S都会引起CPU的急剧增加，而其他的latch竞争同样也会引起CPU的上升，虽然上升没有前者大
[回复]
老熊，
想再问一个问题，recreatable内存块unpin的时候需要链接到shared pool，所以需要获取shared pool latch。这个地方有什么oracle 文档说明吗，或者是否有实验可以证明？
虽然这样的解释很自然，但是这样意味着sql开始执行，需要把cursor pin住，所以要获取一次shared pool latch, 执行结束的时候，unpin cursor，又需要再获取一次shared pool latch。代价可能太大了。
我们做一个oradebug dump heapdump 2的时候，打印出来的LRU List都是unpinned的recreatable的内存快，我很好奇，被pinned住的内存块是不是真的不在LRU list上面，还是实事上一直在LRU list上面，仅仅是dump的时候被跳过而已。另外的一种可能性是，share pool里的LRU List采取了类似buffer poo里面LRU+TCH的算法，share pool latch只是去更新TCH，当然，这只是猜测而已。Jonathan Lewis在他的新书“Oracle Core”提到这个问题
如果我在一个pl/sql做一个循环，把一条使用绑定变量的sql执行1000次，shared pool latch获取的次数只有72次。
最后，下面的creatable应该是recreatable :-)
—quote—
在oracle中kghupr1这个函数是干什么的呢，简单来说就是un-pin recreatable内存块，其主要目的是要将creatable的内存块链接到shared pool的LRU链表中，在这个过程中要持有shared pool latch。
[回复]
老熊， 请问为何这两个等待会比其他latch竞争更加消耗资源：
从等待来看，latch: cache buffers chains和cursor: pin S都会引起CPU的急剧增加，而其他的latch竞争同样也会引起CPU的上升，虽然上升没有前者大
谢谢
[回复]
熊哥分析的真详细，我们的营业库上也出现这样类似的问题，我们的库上没有出现library cache lock以及buffer cache cahin的等待，两个等待很明显，latch free， cursor：pin s wait x；latch free主要是：simulator lru latch。最后发现是bug：5918642
[回复]
跟我们系统这里一个系统差不多嘛。。
[回复]