客户一套很重要的数据库，一直运行正常，一大早接到告警，发现出现大量的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报告做了一个输出，发现了下面的问题。
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。
对比两份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)
2011
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
