数据库凌晨3点至4点异常繁忙，大量cursor: pin S wait on X等待

syp4869

RAC数据库中的2号实例，3月8号、3月9号两天凌晨3点至4点期间，出现了大量的cursor: pin S wait on X等待事件。AWR报告中显示如下SQL耗时过长。

select decode(failover_method, NULL, 0 , 'BASIC', 1, 'PRECONNECT', 2 , 'PREPARSE', 4 , 0), decode(failover_type, NULL, 1 , 'NONE', 1 , 'SESSION', 2, 'SELECT', 4, 1), failover_retries, failover_delay, flags from service$ where name = :1

上网查询了一下该SQL应该是Oracle在登录阶段会执行的SQL语句，和Oracle内部的递归调用有关，正常应该是很快会执行完的。

AWR报告中发现了一点异常是3点至4点期间共享池中各组件的大小发生了很大的变化（两天都是），貌似进行了flush的操作，不知这是否和该问题的产生有关。

烦请大侠指点迷津！附件为问题时段的AWR报告（也包括实例1的）

Maclean Liu(刘相兵

上传 alert.log 和 当时的 diag 进程的  trace文件， 打包压缩后上传

Maclean Liu(刘相兵

Elapsed:                 59.68 (mins)                  
DB Time:                 840.33 (mins)

DB负载 负载很高 ：

Parses:        2.10        1.92
Hard parses:        0.24        0.22

解析和硬解析数并不多

Event        Waits        Time(s)        Avg Wait(ms)        % Total Call Time        Wait Class
cursor: pin S wait on X        2,676,490        26,174        10        51.9        Concurrency
rdbms ipc reply        6,946        13,103        1,886        26.0        Other
row cache lock        7,039        10,578        1,503        21.0        Concurrency
CPU time                 4,648                 9.2         
latch: row cache objects        31,261        2,493        80        4.9        Concurrency

TOP 5 包括 cursor: pin S wait on X 和row cache lock         ， 怀疑 row cache lock 造成 cursor pin 争用

        Begin        End               
Buffer Cache:        7,168M        7,168M        Std Block Size:        16K
Shared Pool Size:        4,096M        4,096M        Log Buffer:        14,324K

Shared Pool Size 和 Buffer Cache的大小在 快照时段内没有变化，且 sga_target=0 排除因为 ASMM 自动SGA管理造成 shared pool shrink 收缩造成 dictionary/row cache 被清理 而造成 row cache lock的可能性。


Dictionary Cache Stats (RAC)   ==>RAC 的dictionary  cache stats 冲突很少

Cache        GES Requests        GES Conflicts        GES Releases
dc_awr_control         3         2         1
dc_database_links         1         0         1
dc_files         85         0         85
dc_global_oids         17         0         26
dc_histogram_defs         1,921         0         409,727
dc_object_ids         382         0         8,056
dc_objects         392         0         8,069
dc_profiles         1         0         1
dc_segments         453         1         15,187
dc_sequences         82         3         3
dc_table_scns         1         0         0
dc_tablespace_quotas         2         1         1
dc_tablespaces         20         0         20
dc_usernames         12         0         15
dc_users         11         0         13
outstanding_alerts         215         61         2


Dictionary Cache Stats

    "Pct Misses" should be very low (< 2% in most cases)
    "Final Usage" is the number of cache entries being used

Cache        Get Requests        Pct Miss        Scan Reqs        Pct Miss        Mod Reqs        Final Usage
dc_awr_control         25         12.00         0                   0         1
dc_database_links         60         1.67         0                   0         1
dc_files         1,785         4.76         0                   0         85
dc_global_oids         64         26.56         0                   0         17
dc_histogram_data         5,810         20.12         0                   0         1,195
dc_histogram_defs         5,325         36.08         0                   0         1,722
dc_object_grants         52         30.77         0                   0         16
dc_object_ids         5,939         6.42         0                   0         442
dc_objects         2,536         15.34         0                   2         448
dc_profiles         91         1.10         0                   0         1
dc_rollback_segments         1,864         0.00         0                   0         158
dc_segments         958         40.08         0                   36         381
dc_sequences         41         17.07         0                   41         4
dc_table_scns         1         100.00         0                   0         0
dc_tablespace_quotas         1         100.00         0                   1         1
dc_tablespaces         24,583         0.08         0                   0         17
dc_usernames         1,494         0.80         0                   0         10
dc_users         26,474         0.07         0                   0         30
outstanding_alerts         112         83.93         0                   7         30


主要造成 Dictionary/row  Cache contention 的是 dc_histogram_data 和 dc_histogram_defs的字典缓存.

SQL ordered by Elapsed Time

    Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
    % Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100

Elapsed Time (s)        CPU Time (s)        Executions         Elap per Exec (s)         % Total DB Time        SQL Id        SQL Module        SQL Text
19,609         33         24         817.06         38.89         5ur69atw3vfhj                   select decode(failover_method,...

最耗时的语句是  
”        select decode(failover_method, NULL, 0 , 'BASIC', 1, 'PRECONNECT', 2 , 'PREPARSE', 4 , 0), decode(failover_type, NULL, 1 , 'NONE', 1 , 'SESSION', 2, 'SELECT', 4, 1), failover_retries, failover_delay, flags from service$ where name = :1“

row cache objects         kqrbip         0         1,010         27,928
row cache objects         kqrpre: find obj         0         70         263
row cache objects         kqrigt         0         47         2,753
row cache objects         kqreqd: reget         0         18         2
row cache objects         kqreqd         0         11         6
row cache objects         ksucallcbksafely: kqrhngc         0         5         0
row cache objects         kqrso         0         1         13
shared pool         kghfrunp: clatch: nowait         0         27,993         0
shared pool         kghfrunp: alloc: wait         0         4,863         0
shared pool         kghfrunp: clatch: wait         0         3,046         428
shared pool         kghfre         0         931         5,099
shared pool         kghdmp         0         184         0
shared pool         kghupr1         0         104         596
shared pool         kghalo         0         39         343
shared pool         kghalp         0         7         82
shared pool         kghasp         0         2         12
shared pool         kghfrh         0         2         1
shared pool         kghfsh         0         1         0
slave class create         ksvcreate         0         1         0


Latch 方面 造成sleep 的主要是  kghfrunp: clatch: nowait =》　shared pool　latch 和 kqrbip         =》row cache objects  2个闩

kghfrunp    KGH: Ask client to free unpinned space

KQRBIP   是row /dictionary cache 管理的相关函数

kqr         dict/rowcache         row cache management. The row cache consists of a set of facilities to provide fast access to table definitions and locking capabilities.


说明发生过激烈的 Free shared pool 操作：

SGA breakdown difference

    ordered by Pool, Name
    N/A value for Begin MB or End MB indicates the size of that Pool/Name was insignificant, or zero in that snapshot

Pool        Name        Begin MB        End MB        % Diff
java         free memory         256.00         256.00         0.00
large         free memory         256.00         256.00         0.00
shared         CCursor         123.67                   -100.00
shared         KGLS heap         137.92                   -100.00
shared         KQR L PO         430.87                   -100.00
shared         PCursor         55.17                   -100.00
shared         free memory         1,793.02         3,195.91         78.24
shared         gcs resources         83.36         83.36         0.00
shared         gcs shadows         49.83         49.83         0.00
shared         ges enqueues         165.27         165.27         0.00
shared         ges resource         437.91         332.79         -24.00
shared         library cache         105.66                   -100.00
shared         sql area         372.42                   -100.00
shared         sql area:PLSQL         84.87                   -100.00
streams         free memory         16.00         16.00         0.00
          buffer_cache         7,680.00         7,680.00         0.00
          fixed_sga         2.01         2.01         0.00
          log_buffer         13.99         13.99         0.00


shared         free memory         1,793.02         3,195.91         78.24

shared pool的Free memory 水平大幅上升 ，从 1793MB  上升到 3195M

既有可能是 Flush shared_pool 或者类似的操作引发了短期的 剧烈的row cache lock ，进而导致了 cursor pin S on X 的游标pin等待。


建议你通过 ALERT.LOG 确认该时段是否有 "ALTER SYSTEM FLUSH SHARED_POOL" 之类的操作。