大量enq:SQ-contention和row cache lock,LCK进程等待latch Free

客户一套很重要的数据库,一直运行正常,一大早接到告警,发现出现大量的enq:SQ-contention和row cache lock等待事件,我们立马登上去做检查。出现这种情况,我们一般会先做hang analyze分析,找出堵塞的源头,进行杀掉阻塞的进程,然后堵塞会话会自行解开。从一般经验上来看,我们觉得是seqnence出现了一些争用。我们做了几个hang分析,找到了源头,确实是在申请相关序列,我们杀完之后,发现系统仍然存在大量的enq:SQ-contention锁和row cache lock等待事件,而我们做hang分析的源头每一次是不尽相同的。不是这个seqnence出问题,就是那个sequence出现问题。在我们杀了大概40-50分钟没有效果的情况下,经过客户的允许,把问题较严重的实例down掉进行了重启,然后顺利的恢复了这次故障。

TO_CHAR(SAMPLE_T EVENT                                                              COUNT(1)
---------------- ---------------------------------------------------------------- ----------
2014-04-23 08:34 enq: SQ - contention                                                      2
2014-04-23 08:40 enq: SQ - contention                                                      3
2014-04-23 08:43 enq: SQ - contention                                                     42
2014-04-23 08:44 enq: SQ - contention                                                     93
2014-04-23 08:45 enq: SQ - contention                                                    180
2014-04-23 08:46 enq: SQ - contention                                                    137
2014-04-23 08:47 enq: SQ - contention                                                     29
2014-04-23 08:48 enq: SQ - contention                                                    171
2014-04-23 08:49 enq: SQ - contention                                                    249
2014-04-23 08:50 enq: SQ - contention                                                    369
2014-04-23 08:51 enq: SQ - contention                                                    292
2014-04-23 08:52 enq: SQ - contention                                                    244
2014-04-23 08:53 enq: SQ - contention                                                    235
2014-04-23 08:54 enq: SQ - contention                                                    108
2014-04-23 08:55 enq: SQ - contention                                                    368
2014-04-23 08:56 enq: SQ - contention                                                    284
2014-04-23 08:57 enq: SQ - contention                                                    261
2014-04-23 08:58 enq: SQ - contention                                                    367
2014-04-23 08:59 enq: SQ - contention                                                    151
2014-04-23 09:00 enq: SQ - contention                                                    221
2014-04-23 09:01 enq: SQ - contention                                                    528
2014-04-23 09:02 enq: SQ - contention                                                    366
2014-04-23 09:03 enq: SQ - contention                                                    477
2014-04-23 09:04 enq: SQ - contention                                                    251
2014-04-23 09:05 enq: SQ - contention                                                     47
2014-04-23 09:06 enq: SQ - contention                                                     21
2014-04-23 09:07 enq: SQ - contention                                                     29
2014-04-23 09:08 enq: SQ - contention                                                     37
2014-04-23 09:09 enq: SQ - contention                                                     32
2014-04-23 09:10 enq: SQ - contention                                                    141
2014-04-23 09:11 enq: SQ - contention                                                    201

SQL> select * from v$rowcache where cache# =13;
CACHE# TYPE  SUBORDINATE# PARAMETER     COUNT USAGE FIXED GETS  GETMISSES SCANS SCANMISSES SCANCOMPLETES MODIFICATIONS FLUSHES  DLM_REQUESTS DLM_CONFLICTS DLM_RELEASES
------ ------------------ ------------------- ----- ----- ---- ---------- ----- ---------- ------------- ------------- -------  ------------ ------------- ------------
    13 PARENT             dc_sequences    42     42     0  1974      1315     0          0             0          1974    1974          3938          1241           32

我一直有一个观点,就是故障处理第一要素就是快速的恢复业务,不管你用什么手段,杀会话也好,重启也好,一定要保障业务的连续性,等业务能正常的访问和操作了,我们在进行问题的一个分析。我们试着想一下,如果系统出现故障,此时此刻你在那里查问题的原因(原因可能没那么好查清楚),而不是进行快速有效的恢复的话,很可能引来很多的投诉。因为有些关键性业务是非常重要的,一分一秒都是不能有耽搁的。只要一分钟,客户可能就会丢失多比订单业务。

在重启之前,我们做了一下AWR快照,把相关的信息进行了一个储存。这是一个关键的操作,因为有了这部分快照信息,我们能够更好的输出AWR和ASH的信息,这一次很幸运,我们通过ASH定位出了最终的问题。我们把出问题时间点的ASH报告做了一个输出,发现了下面的问题。

Top Sessions

  • ‘# Samples Active’ shows the number of ASH samples in which the session was found waiting for that particular event. The percentage shown in this column is calculated with respect to wall clock time and not total database activity.
  • ‘XIDs’ shows the number of distinct transaction IDs sampled in ASH when the session was waiting for that particular event
  • For sessions running Parallel Queries, this section will NOT aggregate the PQ slave activity into the session issuing the PQ. Refer to the ‘Top Sessions running PQs’ section for such statistics.
Sid, Serial# % Activity Event % Event User Program # Samples Active XIDs
13154, 1 1.33 latch free 1.33 SYS oracle@w25k01db (LCK0) 54/60 [ 90%] 0

我们可以看到在出问题的时间点,我们的LCK0进程是Top Sessoion,它在等待Latch Free,那么它等待的Latch从何时开始,究竟是在等什么呢?我们通过dba_hist_active_sess_history进行查询。查到下列信息。

select to_char(SAMPLE_TIME,'YYYY-MM-DD HH24:MI'),event,count(1) from dba_hist_active_sess_history where snap_id between 37775 and 37776
and instance_number=1  and event='latch free'
group by to_char(SAMPLE_TIME,'YYYY-MM-DD HH24:MI'),event 
order by 1;

TO_CHAR(SAMPLE_T EVENT                                                              COUNT(1)
---------------- ---------------------------------------------------------------- ----------
2014-04-23 07:09 latch free                                                                1
2014-04-23 07:19 latch free                                                                1
2014-04-23 07:29 latch free                                                                1
2014-04-23 07:36 latch free                                                                1
2014-04-23 07:37 latch free                                                                1
2014-04-23 07:46 latch free                                                                1
2014-04-23 07:48 latch free                                                                1
2014-04-23 07:50 latch free                                                                1
2014-04-23 07:54 latch free                                                                2
2014-04-23 07:55 latch free                                                                1
2014-04-23 07:56 latch free                                                                1
2014-04-23 07:57 latch free                                                                1
2014-04-23 07:58 latch free                                                                2
2014-04-23 08:00 latch free                                                                3
2014-04-23 08:01 latch free                                                                1
2014-04-23 08:03 latch free                                                                2
2014-04-23 08:05 latch free                                                                2
2014-04-23 08:06 latch free                                                                2
2014-04-23 08:10 latch free                                                                3
2014-04-23 08:11 latch free                                                                2
2014-04-23 08:12 latch free                                                                5
2014-04-23 08:13 latch free                                                                2
2014-04-23 08:14 latch free                                                                5
2014-04-23 08:15 latch free                                                                1
2014-04-23 08:16 latch free                                                                7
2014-04-23 08:17 latch free                                                                9
2014-04-23 08:19 latch free                                                                6
2014-04-23 08:20 latch free                                                                5
2014-04-23 08:21 latch free                                                                6
2014-04-23 08:22 latch free                                                                8
2014-04-23 08:23 latch free                                                                7
2014-04-23 08:24 latch free                                                                5
2014-04-23 08:25 latch free                                                                6
2014-04-23 08:26 latch free                                                               15
2014-04-23 08:27 latch free                                                                5
2014-04-23 08:28 latch free                                                                9
2014-04-23 08:29 latch free                                                               17
2014-04-23 08:30 latch free                                                               22
2014-04-23 08:31 latch free                                                               20
2014-04-23 08:32 latch free                                                               13
2014-04-23 08:33 latch free                                                               13
2014-04-23 08:34 latch free                                                               15
2014-04-23 08:35 latch free                                                                7
2014-04-23 08:36 latch free                                                                4
2014-04-23 08:37 latch free                                                               13
2014-04-23 08:38 latch free                                                               22
2014-04-23 08:39 latch free                                                               10
2014-04-23 08:40 latch free                                                               26
2014-04-23 08:41 latch free                                                               28
2014-04-23 08:42 latch free                                                               29
2014-04-23 08:43 latch free                                                               39
2014-04-23 08:44 latch free                                                               74
2014-04-23 08:45 latch free                                                               99
2014-04-23 08:46 latch free                                                               88
2014-04-23 08:47 latch free                                                               43
2014-04-23 08:48 latch free                                                              121
2014-04-23 08:49 latch free                                                              138
2014-04-23 08:50 latch free                                                              152
2014-04-23 08:51 latch free                                                              101
2014-04-23 08:52 latch free                                                              103
2014-04-23 08:53 latch free                                                               96
2014-04-23 08:54 latch free                                                              121
2014-04-23 08:55 latch free                                                               89
2014-04-23 08:56 latch free                                                              117
2014-04-23 08:57 latch free                                                               83
2014-04-23 08:58 latch free                                                               96
2014-04-23 08:59 latch free                                                               87
2014-04-23 09:00 latch free                                                              113

SQL> select to_char(SAMPLE_TIME,'YYYY-MM-DD HH24:MI') st ,sql_id,event,program,p1,p2,p3 from dba_hist_active_sess_history where snap_id between 37775 and 37776 and instance_number=1 and program like '%LCK%';
ST               SQL_ID        EVENT                                    PROGRAM                                   P1         P2         P3
---------------- ------------- ---------------------------------------- ------------------------------ ------------- ---------- ----------
2014-04-23 07:09               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:19               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:29               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:36               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:37               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:45                                                        oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:45                                                        oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:45                                                        oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:46               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:48                                                        oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:48                                                        oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:48                                                        oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:50                                                        oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:50               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:51                                                        oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:54               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:54               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:55                                                        oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:56               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:57               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:58               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0
2014-04-23 07:58               latch free                               oracle@w25k01db (LCK0)           77597734168         37          0

SQL> select * from v$latchname where latch#=37;
 
    LATCH# NAME                                                     HASH
---------- -------------------------------------------------- ----------
        37 channel operations parent latch                    3794363110

可以看到LCK0进程是从7点09分出问题的,而它所等待的是37号latch,37号latch代表的是channel operations parent latch。

image

image

对比两份AWR报告,发现这个latch相关的函数上处理特别的慢。通过开SR反映了这一信息,最终确定是Bug 7801939 – Contention for "channel operations parent latch" child latch 引起的。打完这个补丁之后,该问题就在也没出现过。那么我们的一个疑问是LCK进程为何会导致sequence数据字典的争用。它们之间的关系是什么?LCK进程又叫lock process(LCK),它是用来管理实例间资源请求和跨实例调用操作,调用操作包括数据字典等对象的访问;并处理非CACEH FUSION的CHACE资源请求(例如:DICTIONARY CACHE或row cache的请求).如果LCK进程出现异常并且有阻塞现象,将导致我们的跨实例的数据字典对象访问失败,而我们的Seqnence是存放在数据字典里面的。所以间接造成了所以的sequence的访问出现enq:SQ和row cache lock的等待。最终影响了我们的数据库正常使用。而LCK进程的阻塞者是谁?谁影响了LCK,根据我们对LCK进程的Blocking Session的分析,发现LCK的阻塞者是应用进程,且时刻在变化,这点也就解释了我们在做Hang Analyze的时候为什么没有发现最上层阻塞会话。而只是发现了部分应用的会话。而BUG的描述有下列信息,显示进程之间消息传递机制有些问题。The interprocess messaging mechanism may exhibit high latch contention under certain workloads.

参考文档:Bug 7801939 – Contention for "channel operations parent latch" child latch (文档 ID 7801939.8)

分享到: 更多