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

 前一阵刚给同事做完一个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   Max. Wait  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 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








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   Max. Wait  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(p1, 16711680))/65535) "Lock",


     to_char( bitand(p1, 65535) )    "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=: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








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   Max. Wait  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


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