修改隐含参数_library_cache_advice解决性能问题一例

客户的一套重要生产系统，出现了性能问题。这个问题涉及的信息如下：

数据库主机的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小时）：

​​view plain​​​​copy to clipboard​​​​print​​​​?​​

1. Time
2. --------- ------------------- -------- ---------
3. Begin
4. End
5.    Elapsed:              119.76 (mins)  
6. Time:            2,900.95 (mins)  
7.   
8. Cache Sizes  
9. ~~~~~~~~~~~                       Begin        End
10. ---------- ----------
11. Size:         8K  
12. Size:     6,144M     6,144M      Log Buffer:    30,632K  
13.   
14. Load
15. ~~~~~~~~~~~~                            Per Second       Per Transaction
16. ---------------       ---------------
17. size:          1,968,314.84              6,360.04  
18.               Logical reads:          1,038,182.89              3,354.59  
19.               Block changes:            148,577.35                480.09  
20.              Physical reads:              3,541.98                 11.44  
21.             Physical writes:                546.31                  1.77  
22. User
23.                      Parses:              3,187.30                 10.30  
24.                 Hard parses:                 10.07                  0.03  
25.                       Sorts:              6,258.90                 20.22  
26.                      Logons:                  9.65                  0.03  
27.                    Executes:             24,100.52                 77.87  
28.                Transactions:                309.48  
29. Instance Efficiency Percentages (Target 100%)  
30. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  
31.             Buffer Nowait %:  100.00       Redo NoWait %:  100.00  
32. In-memory Sort %:  100.00  
33.             Library Hit   %:   99.36        Soft Parse %:   99.68  
34. Execute to
35. Parse CPU to
36.   
37. Statistics        Begin    End
38. ------  ------
39.              Memory Usage %:   95.44   94.46  
40. with
41. for SQL w/exec>1:   87.82   76.62  
42. 
    
43. Top 5 Timed Events
44. ~~~~~~~~~~~~~~~~~~ 
45. 
    
46. Event     Waits      Time(s)    Avg Wait(ms) % Total Call  Time   Wait Class  

1. ------------------------------ ------------ ----------- ------ ------ ----------  
2. CPU time
3. db file sequential read           8,232,067      40,956      5   23.5   User
4. db file scattered read              929,509       2,392      3    1.4   User
5. log file sync                     2,119,459       2,372      1    1.4     Commit
6. SQL*Net message from
7. -------------------------------------------------------------
8. ^LWait Events                         DB/Inst: CRM2DB/crm2db1  Snaps: 3408-3412  
9. -> s  - second
10. -> cs - centisecond -     100th of a second
11. -> ms - millisecond -    1000th of a second
12. -> us - microsecond - 1000000th of a second
13. -> ordered by wait time desc, waits desc (idle events last)  
14. -> %Timeouts: value of 0 indicates value was <  .5%.  Value of null is
15.   
16.  Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn
17. ---------------------------- -------------- ----- ----------- ------- ---------
18. db file sequential read
19. db file scattered read
20. log file sync                     2,119,459     0       2,372       1       1.0  
21. SQL*Net message from
22. SQL*Net more data from
23. control file sequential read
24. Backup: sbtbackup                        12   N/A       1,167   97243       0.0  
25. gc cr grant
26. log file parallel write           2,205,552   N/A         974       0       1.0  
27. gc cr multi block request         2,378,748   N/A         721       0       1.1  
28. gc current
29. SQL*Net more data to
30. gc buffer busy                      166,717     0         428       3       0.1  
31. direct path read
32. db file parallel read
33. enq: HW - contention                 17,487     0         216      12       0.0  
34. db file parallel write              221,865   N/A         210       1       0.1  
35. Backup: sbtwrite2                    36,271   N/A         145       4       0.0  
36. gc current grant
37. enq: TM - contention                    255    74         102     400       0.0  
38.                          

在应用调整第2天上午的awr数据（采集时长1小时）：

​​view plain​​​​copy to clipboard​​​​print​​​​?​​

1. Load
2. ~~~~~~~~~~~~                            Per Second       Per Transaction
3. ---------------       ---------------
4. size:          2,420,236.58              6,734.48  
5.               Logical reads:          1,277,888.60              3,555.82  
6.               Block changes:            164,638.57                458.12  
7.              Physical reads:              1,208.59                  3.36  
8.             Physical writes:                456.79                  1.27  
9. User
10.                      Parses:              4,103.35                 11.42  
11.                 Hard parses:                 12.87                  0.04  
12.                       Sorts:              8,052.30                 22.41  
13.                      Logons:                  9.05                  0.03  
14.                    Executes:             32,573.41                 90.64  
15.                Transactions:                359.38  
16.   
17. Read:   12.88    Recursive Call %:    85.01  
18. Rollback per transaction %:    0.19       Rows
19.   
20. Instance Efficiency Percentages (Target 100%)  
21. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  
22.             Buffer Nowait %:   99.97       Redo NoWait %:  100.00  
23. In-memory Sort %:  100.00  
24.             Library Hit   %:   99.92        Soft Parse %:   99.69  
25. Execute to
26. Parse CPU to
27.   
28. Statistics        Begin    End
29. ------  ------
30.              Memory Usage %:   95.42   95.02  
31. with
32. for SQL w/exec>1:   60.04   73.07  
33. 
    
34. Top 5 Timed Events
35. ~~~~~~~~~~~~~~~~~~ 
36. 
    
37. Event     Waits      Time(s)    Avg Wait(ms) % Total Call  Time   Wait Class  

1. ------------------------------ ------------ ----------- ------ ------ ----------  

1. CPU time
2. Backup: sbtwrite2                 2,319,231      22,510     10   18.1 Administra  
3. db file sequential read           3,476,830      20,923      6   16.9   User
4. latch: shared pool                  159,416       9,280     58    7.5 Concurrenc  
5. Backup: sbtbackup                        28       2,746  98056    2.2 Administra  
6. -------------------------------------------------------------
7. ^LWait Events                         DB/Inst: CRM2DB/crm2db1  Snaps: 3602-3604  
8. -> s  - second
9. -> cs - centisecond -     100th of a second
10. -> ms - millisecond -    1000th of a second
11. -> us - microsecond - 1000000th of a second
12. -> ordered by wait time desc, waits desc (idle events last)  
13. -> %Timeouts: value of 0 indicates value was <  .5%.  Value of null is
14.   
15.  Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn
16. ---------------------------- -------------- ----- ----------- ------- --------- 

1. Backup: sbtwrite2                 2,319,231   N/A      22,510      10       1.8  
2. db file sequential read
3. latch: shared pool                  159,416   N/A       9,280      58       0.1  
4. Backup: sbtbackup                        28   N/A       2,746   98056       0.0  
5. log file sync                     1,283,319     0       2,538       2       1.0  
6. gc buffer busy                    1,088,432     0       2,324       2       0.8  
7. latch: library cache                 31,278   N/A       1,328      42       0.0  
8. control file sequential read
9. log file parallel write           1,157,491   N/A       1,045       1       0.9  
10. SQL*Net message from
11. SQL*Net more data from
12. kst: async disk IO                   17,574   N/A         483      27       0.0  
13. gc cr grant
14. gc current
15. direct path read
16. db file parallel write              261,735   N/A         298       1       0.2  
17. read by
18. cursor: pin S                   304,676,088   N/A         233       0     235.1  
19. db file scattered read
20. enq: TX - row lock contentio            466    52         123     263       0.0  
21. direct path write                   227,989   N/A         113       0       0.2  
22.          

从Load profile数据对比来看，应用调整后系统负载有一定的提高，同时每事务逻辑读也有一定的增加（不足10%）。这会是个问题吗？

从第2份数据来看，latch: shared pool 和 latch: library cache有明显的增加。

下面的是性能问题更加严重的时候的AWR数据（采集时长为2小时）：

​​view plain​​​​copy to clipboard​​​​print​​​​?​​

1. Time
2. --------- ------------------- -------- ---------
3. Begin
4. End
5.    Elapsed:              120.41 (mins)  
6. Time:           21,868.27 (mins)  
7.   
8. Cache Sizes  
9. ~~~~~~~~~~~                       Begin        End
10. ---------- ----------
11. Size:         8K  
12. Size:     6,144M     6,144M      Log Buffer:    30,632K  
13.   
14. Load
15. ~~~~~~~~~~~~                            Per Second       Per Transaction
16. ---------------       ---------------
17. size:          1,790,430.57              5,945.33  
18.               Logical reads:          1,162,875.15              3,861.46  
19.               Block changes:            154,064.15                511.59  
20.              Physical reads:              3,007.80                  9.99  
21.             Physical writes:                337.21                  1.12  
22. User
23.                      Parses:              3,603.24                 11.96  
24.                 Hard parses:                 11.25                  0.04  
25.                       Sorts:              7,304.40                 24.26  
26.                      Logons:                 11.27                  0.04  
27.                    Executes:             25,994.53                 86.32  
28.                Transactions:                301.15  
29.   
30. Read:   13.25    Recursive Call %:    82.87  
31. Rollback per transaction %:    0.21       Rows
32.   
33. Instance Efficiency Percentages (Target 100%)  
34. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  
35.             Buffer Nowait %:   99.99       Redo NoWait %:  100.00  
36. In-memory Sort %:  100.00  
37.             Library Hit   %:   99.94        Soft Parse %:   99.69  
38. Execute to
39. Parse CPU to
40.   
41. Statistics        Begin    End
42. ------  ------
43.              Memory Usage %:   95.48   94.33  
44. with
45. for SQL w/exec>1:   86.52   74.66  
46.   
47. Top 5 Timed Events
48. ~~~~~~~~~~~~~~~~~~ 
49. 
    
50. Event    Waits Time(s)    Avg Wait(ms) % Total Call  Time   Wait Class  

1. ------------------------------ ------------ ----------- ------ ------ ----------
2. latch: shared pool                  991,918     274,715    277   20.9 Concurrenc  
3. latch: library cache                941,443     232,344    247   17.7 Concurrenc  
4. CPU time
5. cursor: pin S                  ############     115,049      0    8.8      Other  
6. latch: cache buffers lru chain    1,106,570      96,442     87    7.4      Other  
7. -------------------------------------------------------------
8. ^LWait Events                         DB/Inst: CRM2DB/crm2db1  Snaps: 3744-3748  
9. -> s  - second
10. -> cs - centisecond -     100th of a second
11. -> ms - millisecond -    1000th of a second
12. -> us - microsecond - 1000000th of a second
13. -> ordered by wait time desc, waits desc (idle events last)  
14. -> %Timeouts: value of 0 indicates value was < .5%.  Value of null is
15.   
16.   
17.  Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn

1. ---------------------------- -------------- ----- ----------- ------- ---------
2. latch: shared pool                  991,918   N/A     274,715     277       0.5  
3. latch: library cache                941,443   N/A     232,344     247       0.4  
4. cursor: pin S                 9,095,470,035   N/A     115,049       0   4,180.5  
5. latch: cache buffers lru cha      1,106,570   N/A      96,442      87       0.5  
6. db file sequential read
7. latch: cache buffers chains         511,936   N/A      35,753      70       0.2  
8. latch free
9. latch: object queue header o        221,907   N/A      14,378      65       0.1  
10. log file sync                     2,156,343     1      11,496       5       1.0  
11. cursor: pin S wait on
12. gc cr grant
13. db file scattered read
14. enq: TX - row lock contentio          5,946    88       2,600     437       0.0  
15. latch: row cache objects             16,983   N/A       2,281     134       0.0  
16. SQL*Net message from
17. gc buffer busy                      353,228     0       2,054       6       0.2  
18. gc cr multi block request         2,499,709     0       1,974       1       1.1  
19. gc current
20. SQL*Net more data from
21. control file sequential read
22. db file parallel read
23. log file parallel write           1,581,432   N/A       1,303       1       0.7  
24. Backup: sbtbackup                        14   N/A         730   52120       0.0  
25. buffer busy waits                   143,869     0         488       3       0.1  
26. latch: library cache lock             5,058   N/A         378      75       0.0  
27. enq: HW - contention                 22,039     0         370      17       0.0  
28. gc current grant
29. enq: SQ - contention                  5,010     1         354      71       0.0  
30. read by
31. direct path read
32. db file parallel write              207,793   N/A         274       1       0.1  
33. row cache lock                      175,301     0         263       1       0.1  
34.             

从第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数据（注：本文涉及故障的分析时间是在星期一）：

​​view plain​​​​copy to clipboard​​​​print​​​​?​​

1. Top 5 Timed Events
2. ~~~~~~~~~~~~~~~~~~ 
3. 
   
4. Event    Waits Time(s)    Avg Wait(ms) % Total Call  Time   Wait Class  

1. ------------------------------ ------------ ----------- ------ ------ ----------
2. CPU time
3. latch: shared pool                  185,951      41,178    221   40.4 Concurrenc  
4. latch: library cache                 45,636       8,861    194    8.7 Concurrenc  
5. db file sequential read             815,066       4,763      6    4.7   User
6. cursor: pin S                  ############       1,732      0    1.7      Other  
7. ------------------------------------------------------------- 
8.   
9.  Event Waits %Time -outs Total Wait Time (s) Avg wait (ms) Waits /txn

1. ---------------------------- -------------- ----- ----------- ------- ---------
2. latch: shared pool                  185,951   N/A      41,178     221       0.6  
3. latch: library cache                 45,636   N/A       8,861     194       0.2  
4. db file sequential read
5. cursor: pin S                 1,890,998,700   N/A       1,732       0   6,459.2  
6. latch free
7. control file sequential read
8. Backup: sbtbackup                         7   N/A         428   61096       0.0  
9. log file sync                       285,442     0         309       1       1.0  
10. SQL*Net more data from
11. db file scattered read
12. gc buffer busy                       56,842     0         135       2       0.2  
13. gc cr grant
14. SQL*Net message from
15. log file parallel write             289,048   N/A          91       0       1.0  
16. SQL*Net more data to
17. gc current
18. direct path read
19. gc cr multi block request           228,693   N/A          52       0       0.8  
20.             

至于性能问题是不是逐渐引起的，这个问题目前并不关键，暂时不考虑。只是做为后面分析问题的一个参考。

再看最后一个问题，这些性能现象中，哪一个更接近问题的原因？幸庆的是，从上面的业务低谷期数据可以看到，这个时候的等待主要是跟解析相关的等待，而其他的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数据，因为这个时候没有了其他的干扰，更容易分析：

​​view plain​​​​copy to clipboard​​​​print​​​​?​​

1. ^LLatch Miss Sources                  DB/Inst: CRM2DB/crm2db1  Snaps: 3716-3718  
2. -> only latches with
3. -> ordered by name, sleeps desc
4.   
5.  Latch Name Where NoWait Misses Sleeps Waiter Sleeps
6. ------------------------ -------------------------- ------- ---------- --------
7. library cache            kglpndl: child: after
8. library cache            kglpndl: child: before pro       0     12,653    1,969  
9. library cache            kglpnp: child                    0     10,188   34,808  
10. library cache            kglLockCursor                    0        632    1,539  
11. library cache            kglhdgn: child:                  0        487    3,729  
12. library cache            kglobpn: child:                  0        408    2,077  
13. library cache            kgldte: child 0                  0        381      747  
14. library cache            kglukp: child                    0        184       66  
15. library cache            kglati                           0         52        1  
16. library cache            kqlmbpil: parent                 0         52        4  
17. library cache            kglpin                           0         38        9  
18. library cache            kgldti: 2child                   0         32        0  
19. library cache            kglhdbrnl: child                 0         13       29  
20. library cache            kglhdgc: child:                  0          9        0  
21. library cache            kglobld                          0          4        0  
22. library cache            kglic                            0          2        7  
23. library cache            kglini: child                    0          1        0  
24. shared pool              kghupr1                          0    168,465  148,602  
25. shared pool              kghalo                           0      9,881   23,589  
26. shared pool              kghfre                           0      7,136   13,425  
27. shared pool              kghfrunp: clatch: nowait         0        470        0  
28. shared pool              kghalp                           0        204       82  
29. shared pool              kghfrunp: alloc: wait            0          9        0  
30. shared pool              kghfrunp: clatch: wait           0          5       15  
31. shared pool              kghasp                           0          4        0  
32. shared pool              kghfrh                           0          3        0  
33. shared pool simulator    kglsim_unpin_simhp               0        319       70  
34. shared pool simulator    kglsim_scan_lru: scan            0          3      101  
35. shared pool simulator    kglsim_upd_newhp                 0          3       89  
36. shared pool simulator    kglsim_chg_simhp_free            0          1       25  
37. slave class create

那么从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进行更深入的分析：

​​view plain​​​​copy to clipboard​​​​print​​​​?​​

1. SQL> @latchprofx sid,name,ksllwnam,ksllwlbl % library 10000  
2. NAME
3. ----- --------------- ----------------------------------- -------- ----- ---- ------- -----------
4. after
5. after
6.   694 library cache   kglpndl: child: before processing   latch     1443    2   14.43    2715.726  
7. after
8. after
9.   638 library cache   kglpndl: child: before processing   latch     1123    2   11.23    2113.486  
10.  5949 library cache   kglobpn: child:                     latch     1103   24   11.03    2075.846  
11.  5949 library cache   kglukp: child                       child     1062    6   10.62    1998.684  
12.   584 library cache   kglpndl: child: before processing   latch      974    3    9.74    1833.068  
13.  5762 library cache   kglpndl: child: before processing   latch      960    2    9.60    1806.720  
14. no
15.  5949 library cache   kghfrunp: clatch: nowait                       888   17    8.88    1671.216  
16. after
17.  6243 library cache   kglpndl: child: before processing   latch      822    2    8.22    1547.004  
18.  6184 library cache   kglpndl: child: before processing   latch      790    2    7.90    1486.780  
19. after
20.  5601 library cache   kglpndl: child: before processing   latch      675    1    6.75    1270.350  
21.  3948 library cache   kglpndl: child: before processing   latch      657    1    6.57    1236.474  
22.  3277 library cache   kglpndl: child: before processing   latch      652    1    6.52    1227.064  
23.   
24. SQL> @latchprofx sid,name,ksllwnam,ksllwlbl % shared 10000  
25. NAME
26. ---- ---------------------- ------------------- ------------- ---- ---------- ------- -----------
27. 2338 shared pool            kghupr1             Chunk Header  2173          5   21.73    4343.827  
28. 2338 shared pool simulator  kglsim_unpin_simhp                2172          4   21.72    4341.828  
29. 5710 shared pool            kghalo                            1107         15   11.07    2212.893  
30. 3423 shared pool simulator  kglsim_unpin_simhp                1075          2   10.75    2148.925  
31. 3423 shared pool            kghupr1             Chunk Header  1075          2   10.75    2148.925  
32. 5348 shared pool simulator  kglsim_unpin_simhp                1025          2   10.25    2048.975  
33. 5348 shared pool            kghupr1             Chunk Header  1025          2   10.25    2048.975  
34. 2895 shared pool            kghupr1             Chunk Header   767          2    7.67    1533.233  
35. 2895 shared pool simulator  kglsim_unpin_simhp                 767          2    7.67    1533.233  
36. 4779 shared pool            kghupr1             Chunk Header   609          1    6.09    1217.391  
37. 2602 shared pool            kghupr1             Chunk Header   551          2    5.51    1101.449  
38. 2602 shared pool simulator  kglsim_unpin_simhp                 550          1    5.50    1099.450  
39. 4591 shared pool            kghupr1             Chunk Header   523          1    5.23    1045.477  
40. 5164 shared pool simulator  kglsim_unpin_simhp                 518          1    5.18    1035.482  
41. 5164 shared pool            kghupr1             Chunk Header   518          1    5.18    1035.482  
42. 3677 shared pool            kghupr1             Chunk Header   493          1    4.93     985.507  
43. 3040 shared pool            kghalo                             329          1    3.29     657.671  
44. 2146 shared pool            kghupr1             Chunk Header   272          1    2.72     543.728  
45. 2146 shared pool simulator  kglsim_unpin_simhp                 272          1    2.72     543.728  
46. 5949 shared pool            kghalo                              63         63     .63     125.937  
47. 5949 shared pool simulator  kglsim_unpin_simhp                  28          3     .28      55.972  
48. 5949 shared pool            kghupr1             Chunk Header    28          3     .28      55.972  
49. 5949 shared pool simulator  kglsim_upd_newhp                     5          5     .05       9.995  
50.    0 shared pool            kghalo                               5          5     .05       9.995  
51. 1558 shared pool            kghalo                               3          3     .03       5.997  
52.  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.