现在的位置: 首页 > 综合 > 正文

一个简单的优化例子(锁问题)

2013年01月04日 ⁄ 综合 ⁄ 共 7775字 ⁄ 字号 评论关闭

 前一阵刚给同事做完一个tuning的培训,顺便把以前做过的case重新整理了一下,今天发出来。

case的开始是客户开始抱怨一个批量处理的操作现在变得很慢,在开发的帮助下,我们可以在生产环境中轻易的测试这个操作,而且发现响应时间确实是比以前慢了。这一般是个好的开始,因为我们至少知道问题是什么。

首先,我们通过session级别的trace,发现这个批处理在执行的过程中存在最多的等待事件是enqueue:

PHP code:


OVERALL TOTALS 
FOR ALL NON-RECURSIVE STATEMENTS



call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse       28      0.01       0.00          0          0          0           0

Execute     28      0.10      19.76          0        257        125          14

Fetch       14      0.00       0.00          0         56          0          14

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total       70      0.11      19.78          0        313        125          28



Misses in library cache during parse
0



Elapsed times 
include waiting on following events:

  
Event waited on                             Times   MaxWait  Total Waited

  
----------------------------------------   Waited  ----------  ------------

  
SQL*Net message to client                     184        0.00          0.00

  SQL
*Net message from client                   184       18.75        220.84

  enqueue                                        14        2.62         17.64

  log file sync                                  14        0.02          0.08

  SQL
*Net break/reset to client                  14        0.29          2.03

  buffer busy waits                               4        0.02          0.03



而引起最多enqueue等待的SQL是
:



select rowidbsr.* 

from

 BATCH_SUB_REQUEST bsr where bsr
.BSR_REQUEST_ID=:and bsr.BSR_item=(select 

  bsr2
.BSR_ITEM from BATCH_SUB_REQUEST bsr2 /*+ INDEX (bsr2 

  idx_batch_sub_request) */ 
where (bsr2.BSR_STATUS='new' )  and 

  
bsr2.BSR_request_id bsr.BSR_request_id  and rownum=1) for update





call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse        7      0.00       0.00          0          0          0           0

Execute      7      0.06      17.70          0        229         41           0

Fetch        7      0.00       0.00          0         35          0           7

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total       21      0.06      17.71          0        264         41           7



Misses in library cache during parse
0

Optimizer goal
CHOOSE

Parsing user id
54  



Rows     Row Source Operation

-------  ---------------------------------------------------

      
1  FOR UPDATE  (cr=5 r=0 w=0 time=947 us)

      
3   TABLE ACCESS BY INDEX ROWID BATCH_SUB_REQUEST (cr=25 r=0 w=0 time=3205 us)

      
3    INDEX RANGE SCAN PK_BATCH_SUB_REQUEST (cr=22 r=0 w=0 time=3141 us)(object id 40913)

      
2     COUNT STOPKEY (cr=10 r=0 w=0 time=477 us)

      
2      TABLE ACCESS BY INDEX ROWID BATCH_SUB_REQUEST (cr=10 r=0 w=0 time=437 us)

      
2       INDEX RANGE SCAN IDX_BATCH_SUB_REQUEST (cr=6 r=0 w=0 time=305 us)(object id 43816)





Elapsed times include waiting on following events:

  
Event waited on                             Times   MaxWait  Total Waited

  
----------------------------------------   Waited  ----------  ------------

  
SQL*Net message to client                      42        0.00          0.00

  SQL
*Net message from client                    42        0.31         12.25

  enqueue                                        14        2.62         17.64

  buffer busy waits                               4        0.02          0.03

********************************************************************************



在进行测试的时候,我通过v$session_wait检查了enqueue类型,是mode6的TX锁,也就是由dml操作引起的行级锁:

SQL
SELECT chr(to_char(bitand(p1,-16777216))/16777215)||

     
chr(to_char(bitand(p116711680))/65535) "Lock",

     
to_charbitand(p165535) )    "Mode"

     
FROM v$session_wait

     WHERE event 
'enqueue' and sid=31;



Lock   Mode

------ ----------------------------------------

TX     6




所有的迹象都指向了一个SQL的lock问题,让我们看看这个SQL:

select rowid, bsr.*
from
BATCH_SUB_REQUEST bsr where bsr.BSR_REQUEST_ID=:1 and bsr.BSR_item=(select
  bsr2.BSR_ITEM from BATCH_SUB_REQUEST bsr2 /*+ INDEX (bsr2
  idx_batch_sub_request) */ where (bsr2.BSR_STATUS='new' )  and
  bsr2.BSR_request_id = bsr.BSR_request_id  and rownum=1) for update

这是一个select ... for update的语句,目的是为了从batch_sub_request这个表里面选出一行,这里面的条件rownum=1引起了我的注意,因为这会使select锁定这张表的地一样,我知道系统上一般会有10个左右进程会一起运行这个同样的select,按照这种写法,同一时间只能有一个select ... for update可以成功,其他的进程必须等待,而等待事件就是enqueue。这显然是有问题的。

我就这个问题和开发组的同事交流了一下,开发的同事一方面同意这个SQL是有问题,但另一方面也向我提出了另一个费解的问题,同样的设计,为什么在测试环境下性能就是好的呢?
这确实是个很奇怪的问题,我们通过在测试环境下重做这个批处理的操作,并且trace下来,发现测试环境下虽然最大的等待事件还是enqueue,但每次等待的时间都是很短的,只需要零点几秒,而在生产环境中每次enqueue的等待时间是2秒以上。

我仔细的看了生产上的trace文件的每一个环节,发现select ... for update之后应该马上做一个update并且commit,从而释放锁。从这个角度来看,其他进程等待lock的时间应该取决于这个update的速度,但是当我兴高采烈的检查update的性能的时候,发现这个update只需要0.01秒都不到的时间。在10个左右的并发情况下,等待最长的那个进程也不应该等待超过0.1秒!
到底我们遗漏什么?最后的可能性是select ... for update和update之间有些东西被我们忽略了,带着这个问题我和开发再次对整个流程交流了一下,终于发现原来当我们做完select ... for update之后,系统还要做一件事情,那就是把select出来的结果发到前端服务器的java程序,前端的java程序要做一些处理。“但是,”开发说,“我们肯定前端的这个处理是很快的,绝不会超过0.1秒”。如果数据库和应用都很快,那慢的的东西就只能有一个了--------网络。

在我们的环境了,有9太前端服务器,3台在美国,3台在亚洲,3台在欧洲,为了提高这个批处理操作的性能,我们允许所有的9台前端服务器帮助处理一个批处理操作,这本来是个好的想法,但是当亚洲的前端成功的做完了select ... for update, 把结果发回给亚洲的前端,亚洲的前端处理好之后再返回下一条指令给数据库,这个过程中如果网络很慢的话可能需要5秒以上,要知道,在这5秒里,所有的其他8台前端的进程都在等待enqueue,这就是enqueue很大的原因!在我们的情况里,本来希望更多的server可以提高性能,但由于网络原因导致部分网络比较差的server堵塞了好的server。

之后我们单独用美国的前端,亚洲的前端,欧洲的前端做测试,发现只用美国前端的时候性能很好,而只用亚洲或欧洲的前端的时候性能都很差,因此问题就是慢的网络导致了大量的enqueue。

这个案例其实很简单,关键是:
1, 开始和开发沟通不充分,漏掉了很重要的环节,主要我自己没多少开发经验。
2, 我自己也有点思维定势,看到SQL*Net message from client很高也没在意,看到enqueue就一头扑上去了。其实如果我们在系统级别监控如果发现SQL*Net message from client很高,可能是很难判断到底应不应该忽略,但如果是在session级别监控到,就要具体分析了。
3,设计还是很重要,这里如果在设计阶段就把lock的影响考虑进去,也不会最后在生产上由于网络不好导致问题。

只用AM的前端监控到的性能:

PHP code:


select rowid
bsr.* 

from

 BATCH_SUB_REQUEST bsr where bsr
.BSR_REQUEST_ID=:and bsr.BSR_item=(select 

  bsr2
.BSR_ITEM from BATCH_SUB_REQUEST bsr2 /*+ INDEX (bsr2 

  idx_batch_sub_request) */ 
where (bsr2.BSR_STATUS='new' )  and 

  
bsr2.BSR_request_id bsr.BSR_request_id  and rownum=1) for update





call     count       cpu    elapsed       disk      query    current        rows

------- ------  -------- ---------- ---------- ---------- ----------  ----------

Parse       36      0.00       0.00          0          0          0           0

Execute     36      0.05       0.11          0        521         89           0

Fetch       36      0.05       0.04          0        180          0          36

------- ------  -------- ---------- ---------- ---------- ----------  ----------

total      108      0.10       0.16          0        701         89          36



Misses in library cache during parse
0

Optimizer goal
CHOOSE

Parsing user id
54  



Rows     Row Source Operation

-------  ---------------------------------------------------

      
1  FOR UPDATE  (cr=5 r=0 w=0 time=798 us)

      
2   TABLE ACCESS BY INDEX ROWID BATCH_SUB_REQUEST (cr=15 r=0 w=0 time=1888 us)

      
2    INDEX RANGE SCAN PK_BATCH_SUB_REQUEST (cr=13 r=0 w=0 time=1856 us)(object id 40913)

      
1     COUNT STOPKEY (cr=5 r=0 w=0 time=160 us)

      
1      TABLE ACCESS BY INDEX ROWID BATCH_SUB_REQUEST (cr=5 r=0 w=0 time=144 us)

      
1       INDEX RANGE SCAN IDX_BATCH_SUB_REQUEST (cr=4 r=0 w=0 time=115 us)(object id 43816)





Elapsed times include waiting on following events:

  
Event waited on                             Times   MaxWait  Total Waited

  
----------------------------------------   Waited  ----------  ------------

  
SQL*Net message from client                   218        0.04          0.20

  SQL
*Net message to client                     217        0.00          0.00

  enqueue                                         8        0.00          0.04

********************************************************************************

 

抱歉!评论已关闭.