一个简单的优化例子(锁问题)
前一阵刚给同事做完一个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
********************************************************************************
