修改隐含参数_library_cache_advice解决性能问题一例(转)_csdn909034的博客-程序员宅基地

技术标签: 数据结构与算法  数据库  

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

  • 数据库主机的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小时):

  1.               Snap Id      Snap Time      Sessions Curs/Sess  
  2.             --------- ------------------- -------- ---------  
  3. Begin Snap:      3408 19-Sep-11 09:00:21     4,690      39.5  
  4.   End Snap:      3412 19-Sep-11 11:00:07     4,950      38.7  
  5.    Elapsed:              119.76 (mins)  
  6.    DB Time:            2,900.95 (mins)  
  7.   
  8. Cache Sizes  
  9. ~~~~~~~~~~~                       Begin        End  
  10.                              ---------- ----------  
  11.                Buffer Cache:    35,840M    35,840M  Std Block Size:         8K  
  12.            Shared Pool Size:     6,144M     6,144M      Log Buffer:    30,632K  
  13.   
  14. Load Profile  
  15. ~~~~~~~~~~~~                            Per Second       Per Transaction  
  16.                                    ---------------       ---------------  
  17.                   Redo 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 calls:              7,811.87                 25.24  
  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.             Buffer  Hit   %:   99.69    In-memory Sort %:  100.00  
  33.             Library Hit   %:   99.36        Soft Parse %:   99.68  
  34.          Execute to Parse %:   86.77         Latch Hit %:   99.64  
  35. Parse CPU to Parse Elapsd %:   45.61     % Non-Parse CPU:   99.46  
  36.   
  37.  Shared Pool Statistics        Begin    End  
  38.                               ------  ------  
  39.              Memory Usage %:   95.44   94.46  
  40.     % SQL with executions>1:   89.10   77.18  
  41.   % Memory for SQL w/exec>1:   87.82   76.62  
  42.   
  43. Top 5 Timed Events                                         Avg %Total  
  44. ~~~~~~~~~~~~~~~~~~                                        wait   Call  
  45. Event                                 Waits    Time (s)   (ms)   Time Wait Class  
  46. ------------------------------ ------------ ----------- ------ ------ ----------  
  47. CPU time                                        114,107          65.6  
  48. db file sequential read           8,232,067      40,956      5   23.5   User I/O  
  49. db file scattered read              929,509       2,392      3    1.4   User I/O  
  50. log file sync                     2,119,459       2,372      1    1.4     Commit  
  51. SQL*Net message from dblink       1,375,619       1,576      1    0.9    Network  
  52.           -------------------------------------------------------------  
  53. ^LWait Events                         DB/Inst: CRM2DB/crm2db1  Snaps: 3408-3412  
  54. -> s  - second  
  55. -> cs - centisecond -     100th of a second  
  56. -> ms - millisecond -    1000th of a second  
  57. -> us - microsecond - 1000000th of a second  
  58. -> ordered by wait time desc, waits desc (idle events last)  
  59. -> %Timeouts: value of 0 indicates value was of null is truly 0  
  60.   
  61.                                                                   Avg  
  62.                                             %Time  Total Wait    wait     Waits  
  63. Event                                 Waits -outs    Time (s)    (ms)      /txn  
  64. ---------------------------- -------------- ----- ----------- ------- ---------  
  65. db file sequential read           8,232,067   N/A      40,956       5       3.7  
  66. db file scattered read              929,509   N/A       2,392       3       0.4  
  67. log file sync                     2,119,459     0       2,372       1       1.0  
  68. SQL*Net message from dblink       1,375,619   N/A       1,576       1       0.6  
  69. SQL*Net more data from clien      1,871,442   N/A       1,428       1       0.8  
  70. control file sequential read      3,010,438   N/A       1,179       0       1.4  
  71. Backup: sbtbackup                        12   N/A       1,167   97243       0.0  
  72. gc cr grant 2-way                 3,688,572   N/A         993       0       1.7  
  73. log file parallel write           2,205,552   N/A         974       0       1.0  
  74. gc cr multi block request         2,378,748   N/A         721       0       1.1  
  75. gc current block 2-way            1,941,104   N/A         693       0       0.9  
  76. SQL*Net more data to client       5,142,664   N/A         498       0       2.3  
  77. gc buffer busy                      166,717     0         428       3       0.1  
  78. direct path read                    424,645   N/A         344       1       0.2  
  79. db file parallel read                61,816   N/A         298       5       0.0  
  80. enq: HW - contention                 17,487     0         216      12       0.0  
  81. db file parallel write              221,865   N/A         210       1       0.1  
  82. Backup: sbtwrite2                    36,271   N/A         145       4       0.0  
  83. gc current grant 2-way              445,456   N/A         115       0       0.2  
  84. enq: TM - contention                    255    74         102     400       0.0  
  85.                            

在应用调整第2天上午的awr数据(采集时长1小时):

  1. Load Profile  
  2. ~~~~~~~~~~~~                            Per Second       Per Transaction  
  3.                                    ---------------       ---------------  
  4.                   Redo 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 calls:              8,785.42                 24.45  
  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.   % Blocks changed per Read:   12.88    Recursive Call %:    85.01  
  18.  Rollback per transaction %:    0.19       Rows per Sort:     8.74  
  19.   
  20. Instance Efficiency Percentages (Target 100%)  
  21. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  
  22.             Buffer Nowait %:   99.97       Redo NoWait %:  100.00  
  23.             Buffer  Hit   %:   99.92    In-memory Sort %:  100.00  
  24.             Library Hit   %:   99.92        Soft Parse %:   99.69  
  25.          Execute to Parse %:   87.40         Latch Hit %:   99.33  
  26. Parse CPU to Parse Elapsd %:   29.94     % Non-Parse CPU:   99.17  
  27.   
  28.  Shared Pool Statistics        Begin    End  
  29.                               ------  ------  
  30.              Memory Usage %:   95.42   95.02  
  31.     % SQL with executions>1:   61.41   72.38  
  32.   % Memory for SQL w/exec>1:   60.04   73.07  
  33.   
  34. Top 5 Timed Events                                         Avg %Total  
  35. ~~~~~~~~~~~~~~~~~~                                        wait   Call  
  36. Event                                 Waits    Time (s)   (ms)   Time Wait Class  
  37. ------------------------------ ------------ ----------- ------ ------ ----------  
  38. CPU time                                         69,736          56.2  
  39. Backup: sbtwrite2                 2,319,231      22,510     10   18.1 Administra  
  40. db file sequential read           3,476,830      20,923      6   16.9   User I/O  
  41. latch: shared pool                  159,416       9,280     58    7.5 Concurrenc  
  42. Backup: sbtbackup                        28       2,746  98056    2.2 Administra  
  43.           -------------------------------------------------------------  
  44. ^LWait Events                         DB/Inst: CRM2DB/crm2db1  Snaps: 3602-3604  
  45. -> s  - second  
  46. -> cs - centisecond -     100th of a second  
  47. -> ms - millisecond -    1000th of a second  
  48. -> us - microsecond - 1000000th of a second  
  49. -> ordered by wait time desc, waits desc (idle events last)  
  50. -> %Timeouts: value of 0 indicates value was of null is truly 0  
  51.   
  52.                                                                   Avg  
  53.                                             %Time  Total Wait    wait     Waits  
  54. Event                                 Waits -outs    Time (s)    (ms)      /txn  
  55. ---------------------------- -------------- ----- ----------- ------- ---------  
  56. Backup: sbtwrite2                 2,319,231   N/A      22,510      10       1.8  
  57. db file sequential read           3,476,830   N/A      20,923       6       2.7  
  58. latch: shared pool                  159,416   N/A       9,280      58       0.1  
  59. Backup: sbtbackup                        28   N/A       2,746   98056       0.0  
  60. log file sync                     1,283,319     0       2,538       2       1.0  
  61. gc buffer busy                    1,088,432     0       2,324       2       0.8  
  62. latch: library cache                 31,278   N/A       1,328      42       0.0  
  63. control file sequential read      1,512,218   N/A       1,082       1       1.2  
  64. log file parallel write           1,157,491   N/A       1,045       1       0.9  
  65. SQL*Net message from dblink         952,956   N/A         987       1       0.7  
  66. SQL*Net more data from clien        962,454   N/A         837       1       0.7  
  67. kst: async disk IO                   17,574   N/A         483      27       0.0  
  68. gc cr grant 2-way                 1,539,289   N/A         439       0       1.2  
  69. gc current block 2-way              946,330   N/A         353       0       0.7  
  70. direct path read                    291,853   N/A         313       1       0.2  
  71. db file parallel write              261,735   N/A         298       1       0.2  
  72. read by other session                92,451     0         270       3       0.1  
  73. cursor: pin S                   304,676,088   N/A         233       0     235.1  
  74. db file scattered read               28,062   N/A         132       5       0.0  
  75. enq: TX - row lock contentio            466    52         123     263       0.0  
  76. direct path write                   227,989   N/A         113       0       0.2  
  77.             

从Load profile数据对比来看,应用调整后系统负载有一定的提高,同时每事务逻辑读也有一定的增加(不足10%)。这会是个问题吗?
从第2份数据来看,latch: shared pool 和 latch: library cache有明显的增加。

下面的是性能问题更加严重的时候的AWR数据(采集时长为2小时):

  1.               Snap Id      Snap Time      Sessions Curs/Sess  
  2.             --------- ------------------- -------- ---------  
  3. Begin Snap:      3744 26-Sep-11 09:00:01     4,504      38.2  
  4.   End Snap:      3748 26-Sep-11 11:00:26     4,916      52.7  
  5.    Elapsed:              120.41 (mins)  
  6.    DB Time:           21,868.27 (mins)  
  7.   
  8. Cache Sizes  
  9. ~~~~~~~~~~~                       Begin        End  
  10.                              ---------- ----------  
  11.                Buffer Cache:    35,840M    35,840M  Std Block Size:         8K  
  12.            Shared Pool Size:     6,144M     6,144M      Log Buffer:    30,632K  
  13.   
  14. Load Profile  
  15. ~~~~~~~~~~~~                            Per Second       Per Transaction  
  16.                                    ---------------       ---------------  
  17.                   Redo 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 calls:              8,227.28                 27.32  
  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.   % Blocks changed per Read:   13.25    Recursive Call %:    82.87  
  31.  Rollback per transaction %:    0.21       Rows per Sort:     8.14  
  32.   
  33. Instance Efficiency Percentages (Target 100%)  
  34. ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~  
  35.             Buffer Nowait %:   99.99       Redo NoWait %:  100.00  
  36.             Buffer  Hit   %:   99.75    In-memory Sort %:  100.00  
  37.             Library Hit   %:   99.94        Soft Parse %:   99.69  
  38.          Execute to Parse %:   86.14         Latch Hit %:   98.90  
  39. Parse CPU to Parse Elapsd %:   14.69     % Non-Parse CPU:   84.51  
  40.   
  41.  Shared Pool Statistics        Begin    End  
  42.                               ------  ------  
  43.              Memory Usage %:   95.48   94.33  
  44.     % SQL with executions>1:   87.63   74.92  
  45.   % Memory for SQL w/exec>1:   86.52   74.66  
  46.   
  47. Top 5 Timed Events                                         Avg %Total  
  48. ~~~~~~~~~~~~~~~~~~                                        wait   Call  
  49. Event                                 Waits    Time (s)   (ms)   Time Wait Class  
  50. ------------------------------ ------------ ----------- ------ ------ ----------  
  51. latch: shared pool                  991,918     274,715    277   20.9 Concurrenc  
  52. latch: library cache                941,443     232,344    247   17.7 Concurrenc  
  53. CPU time                                        212,150          16.2  
  54. cursor: pin S                  ############     115,049      0    8.8      Other  
  55. latch: cache buffers lru chain    1,106,570      96,442     87    7.4      Other  
  56.           -------------------------------------------------------------  
  57. ^LWait Events                         DB/Inst: CRM2DB/crm2db1  Snaps: 3744-3748  
  58. -> s  - second  
  59. -> cs - centisecond -     100th of a second  
  60. -> ms - millisecond -    1000th of a second  
  61. -> us - microsecond - 1000000th of a second  
  62. -> ordered by wait time desc, waits desc (idle events last)  
  63. -> %Timeouts: value of 0 indicates value was of null is truly 0  
  64.   
  65.                                                                   Avg  
  66.                                             %Time  Total Wait    wait     Waits  
  67. Event                                 Waits -outs    Time (s)    (ms)      /txn  
  68. ---------------------------- -------------- ----- ----------- ------- ---------  
  69. latch: shared pool                  991,918   N/A     274,715     277       0.5  
  70. latch: library cache                941,443   N/A     232,344     247       0.4  
  71. cursor: pin S                 9,095,470,035   N/A     115,049       0   4,180.5  
  72. latch: cache buffers lru cha      1,106,570   N/A      96,442      87       0.5  
  73. db file sequential read           7,819,285   N/A      49,564       6       3.6  
  74. latch: cache buffers chains         511,936   N/A      35,753      70       0.2  
  75. latch free                           95,257     0      14,609     153       0.0  
  76. latch: object queue header o        221,907   N/A      14,378      65       0.1  
  77. log file sync                     2,156,343     1      11,496       5       1.0  
  78. cursor: pin S wait on X             422,320   100       4,603      11       0.2  
  79. gc cr grant 2-way                 3,526,856     0       3,430       1       1.6  
  80. db file scattered read              624,480   N/A       3,083       5       0.3  
  81. enq: TX - row lock contentio          5,946    88       2,600     437       0.0  
  82. latch: row cache objects             16,983   N/A       2,281     134       0.0  
  83. SQL*Net message from dblink       1,284,487   N/A       2,179       2       0.6  
  84. gc buffer busy                      353,228     0       2,054       6       0.2  
  85. gc cr multi block request         2,499,709     0       1,974       1       1.1  
  86. gc current block 2-way            1,969,516     0       1,920       1       0.9  
  87. SQL*Net more data from clien      1,667,513   N/A       1,914       1       0.8  
  88. control file sequential read      2,974,349   N/A       1,735       1       1.4  
  89. db file parallel read               230,795   N/A       1,645       7       0.1  
  90. log file parallel write           1,581,432   N/A       1,303       1       0.7  
  91. Backup: sbtbackup                        14   N/A         730   52120       0.0  
  92. buffer busy waits                   143,869     0         488       3       0.1  
  93. latch: library cache lock             5,058   N/A         378      75       0.0  
  94. enq: HW - contention                 22,039     0         370      17       0.0  
  95. gc current grant 2-way              424,243   N/A         357       1       0.2  
  96. enq: SQ - contention                  5,010     1         354      71       0.0  
  97. read by other session                50,153     0         339       7       0.0  
  98. direct path read                    324,226   N/A         305       1       0.1  
  99. db file parallel write              207,793   N/A         274       1       0.1  
  100. row cache lock                      175,301     0         263       1       0.1  
  101.             

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

  1. Top 5 Timed Events                                         Avg %Total  
  2. ~~~~~~~~~~~~~~~~~~                                        wait   Call  
  3. Event                                 Waits    Time (s)   (ms)   Time Wait Class  
  4. ------------------------------ ------------ ----------- ------ ------ ----------  
  5. CPU time                                         49,224          48.3  
  6. latch: shared pool                  185,951      41,178    221   40.4 Concurrenc  
  7. latch: library cache                 45,636       8,861    194    8.7 Concurrenc  
  8. db file sequential read             815,066       4,763      6    4.7   User I/O  
  9. cursor: pin S                  ############       1,732      0    1.7      Other  
  10.           -------------------------------------------------------------  
  11.   
  12.                                                                   Avg  
  13.                                             %Time  Total Wait    wait     Waits  
  14. Event                                 Waits -outs    Time (s)    (ms)      /txn  
  15. ---------------------------- -------------- ----- ----------- ------- ---------  
  16. latch: shared pool                  185,951   N/A      41,178     221       0.6  
  17. latch: library cache                 45,636   N/A       8,861     194       0.2  
  18. db file sequential read             815,066   N/A       4,763       6       2.8  
  19. cursor: pin S                 1,890,998,700   N/A       1,732       0   6,459.2  
  20. latch free                            8,549     0       1,278     150       0.0  
  21. control file sequential read      1,507,789   N/A         466       0       5.2  
  22. Backup: sbtbackup                         7   N/A         428   61096       0.0  
  23. log file sync                       285,442     0         309       1       1.0  
  24. SQL*Net more data from clien        145,137   N/A         221       2       0.5  
  25. db file scattered read               67,716   N/A         173       3       0.2  
  26. gc buffer busy                       56,842     0         135       2       0.2  
  27. gc cr grant 2-way                   359,146   N/A          99       0       1.2  
  28. SQL*Net message from dblink         123,206   N/A          98       1       0.4  
  29. log file parallel write             289,048   N/A          91       0       1.0  
  30. SQL*Net more data to client       1,242,471   N/A          79       0       4.2  
  31. gc current block 2-way              179,654   N/A          66       0       0.6  
  32. direct path read                     62,336   N/A          65       1       0.2  
  33. gc cr multi block request           228,693   N/A          52       0       0.8  
  34.             

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

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

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

  1. SQL> @latchprofx sid,name,ksllwnam,ksllwlbl % library 10000  
  2.   SID NAME            KSLLWNAM                            KSLLWLBL  Held Gets  Held %     Held ms  
  3. ----- --------------- ----------------------------------- -------- ----- ---- ------- -----------  
  4.  3146 library cache   kglpndl: child: after processing    latch     2442    4   24.42    4595.844  
  5.  3138 library cache   kglpndl: child: after processing    latch     2274    4   22.74    4279.668  
  6.   694 library cache   kglpndl: child: before processing   latch     1443    2   14.43    2715.726  
  7.  4198 library cache   kglpndl: child: after processing    latch     1214    2   12.14    2284.748  
  8.   611 library cache   kglpndl: child: after processing    latch     1157    2   11.57    2177.474  
  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.  5204 library cache   kgllkdl: child: no lock handle      latch      923    1    9.23    1737.086  
  15.  5949 library cache   kghfrunp: clatch: nowait                       888   17    8.88    1671.216  
  16.  2338 library cache   kglpndl: child: after processing    latch      823    2    8.23    1548.886  
  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.  4121 library cache   kglpndl: child: after processing    latch      684    2    6.84    1287.288  
  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.  SID NAME                   KSLLWNAM            KSLLWLBL      Held       Gets  Held %     Held ms  
  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.

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/25380220/viewspace-709713/,如需转载,请注明出处,否则将追究法律责任。

转载于:http://blog.itpub.net/25380220/viewspace-709713/

版权声明:本文为博主原创文章,遵循 CC 4.0 BY-SA 版权协议,转载请附上原文出处链接和本声明。
本文链接:https://blog.csdn.net/csdn909034/article/details/100321421

智能推荐

数据持久化之preference_iteye_18480的博客-程序员宅基地

preference(偏好设置)是数据持久化的几个方法中最简单的一个,常用于保存少量数据代码如下://// ViewController.m// preference(利用偏好设置保存数据)//// Created by Rio.King on 13-9-22.// Copyright (c) 2013年 Rio.King. All rights reserved....

linux终端分屏显示tmux,screen和tmux分屏_圆山中庸的博客-程序员宅基地

LINUX下有两个比较常用的终端工具:screen和tmux,两者都是支持分屏操作的。不过screen只支持上下分屏,而tmux支持上下左右分屏。这里记录下两者分屏的操作方法。一、screen分屏1,输入命令screen使用工具2,上下分屏:ctrl + a 再按shift + s3,切换屏幕:ctrl + a 再按tab键4,新建一个终端:ctrl + a 再按c5,关闭一个终端:ctrl...

HDFS相关命令_qq_41890501的博客-程序员宅基地

HDFS相关命令:(1)启动hadoop,在HDFS中创建用户目录(现在已经在hadoop目录/usr/local/hadoop)hdfs dfs -mkdir -p /user/hadoop8(2)接着在此用户目录下创建test文件夹,并查看文件列表hdfs dfs -mkdir testhdfs dfs -ls .(3)将~/.bashrc文件上传到HDFS的test文...

数据结构单链表(带头结点)_张淑芬~的博客-程序员宅基地

因为头结点的数据成员只有一个:指针域,而有效数据节点里的数据成员不仅有数据域还有指针域,所以,直接用有效数据节点当做头结点单链表结构体设计(包含了两种方法)://有效数据节点结构体设计(头结点借用)typedef struct Node{ ELEM_TYPE data;//数据域 (1.头结点:不保存任何数据 2.有效数据节点:保存有效值) struct Node* next;//指针域 (1.头结点:保存第一个元素的地址 2.有效数据节点:保存下一个有效元素的..

mysql读写分离实例_SpringBoot+MyBatis+MySQL读写分离(实例)_weixin_39940788的博客-程序员宅基地

https://mp.weixin.qq.com/s/1vTbllmZkHRnuk7_xR2DIg1. 引言读写分离要做的事情就是对于一条SQL该选择哪个数据库去执行,至于谁来做选择数据库这件事儿,无非两个,要么中间件帮我们做,要么程序自己做。因此,一般来讲,读写分离有两种实现方式。第一种是依靠中间件(比如:MyCat),也就是说应用程序连接到中间件,中间件帮我们做SQL分离;第二种是应用程序自己...

powerBuilder 双击window没有出现窗口_日和公主的博客-程序员宅基地_powerbuilder编辑面板不见了

powerBuilder双击window没有出现编辑窗口,按以下步骤点击:1. view -> layouts -> (default)2. windoes

随便推点

程序化广告交易中的点击率预估_weixin_34049948的博客-程序员宅基地

原文:http://www.cnblogs.com/Matrix_Yao/p/4773221.html程序化广告交易中的点击率预估指标 广告点击率预估是程序化广告交易框架的非常重要的组件,点击率预估主要有两个层次的指标: 1. 排序指标。排序指标是最基本的指标,它决定了我们有没有能力把最合适的广告找出来去呈现给最合适的用户。这个是变现的基础,从技术上,我们用AUC来度...

java的动态绑定机制与静态绑定机制_惬意的下雨天的博客-程序员宅基地

Java的动态绑定是上转型对象的实例方法与子类绑定,即子类重写后实例方法。Java的静态绑定是上转型的成员变量的和静态方法与声明类型绑定。

AJAX学习笔记_▲有光,飞蛾才会扑火的博客-程序员宅基地

AJAX学习笔记1 什么是AJAX?AJAX = 异步 JavaScript 和 XMLAJAX 是一种用于创建快速动态网页的技术。通过在后台与服务器进行少量数据交换,AJAX 可以使网页实现异步更新。可以在不重新加载整个网页的情况下,对网页的某部分进行更新。传统的网页(不使用 AJAX)如果需要更新内容,必需重载整个网页面。2 AJAX工作原理3 AJAX是基于现有的Internet标准AJAX是基于现有的Internet标准,并且联合使用它们:XMLHttpRequest 对象 (异

next_permutation函数_liluoyu_1016的博客-程序员宅基地

next_permutation函数 ,可以把n个元素共n!中不同的排列方式生成出来。是求下一个排列的函数。他的头文件是 #include跟此函数相反的还有prev_permutation函数,是求上一个排列的函数转载:https://wenku.baidu.com/view/ef6bf1b67fd5360cbb1adb97.html(1) int类型的next

^   $   .*   []   综合运用_weixin_34128237的博客-程序员宅基地

创建环境mkdir /ccat >/c/oldboy.txt<<EOFo ^word zhaodaoyi word kai tou de hango m$ yi m jie wei de hang^$ biaoshi kong hang,bushi kong geo .biaoshi qie zhi neng dai biao ren yi yi ge zi...

php怎么ajax接收json数据,ThinkPHP中使用ajax接收json数据的方法_weixin_39608988的博客-程序员宅基地

本文实例讲述了ThinkPHP中使用ajax接收json数据的方法。分享给大家供大家参考。具体分析如下:这里通过ThinkPHP+jquery实现ajax,扩展了下,写了个查询,前台代码如下:首先需要引入jquery.js,主要代码如下:代码如下:function ajax(id,pic){//由于ThinkPHP不解析JavaScript里的ThinkPHP常量,所以需要先在这里定义。var U...

推荐文章

热门文章

相关标签