时间：2021-07-01 10:21:17 帮助过：12人阅读
客户一套很重要的数据库，一直运行正常，一大早接到告警，发现出现大量的enq:SQ-contention和row cache lock等待事件，我们立马登上去做检查。出现这种情况，我们一般会先做hang analyze分析，找出堵塞的源头，进行杀掉阻塞的进程，然后堵塞会话会自行解开。
客户一套很重要的数据库，一直运行正常，一大早接到告警，发现出现大量的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报告做了一个输出，发现了下面的问题。
| 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。
对比两份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)
原文地址：大量enq:SQ-contention和row cache lock,LCK进程等待latch Fr, 感谢原作者分享。