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

  • 数据库主机的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.