TX争用导致处理缓慢问题分析

Liu Maclean(刘相兵

TX争用导致处理缓慢问题分析


mode=4的TX enqueue是由于INDEX上的row lock/index split引起的，这与普通数据表上的mode=6的TX enqueue不同。INX2_READWRITE_LOG索引上的mode=4的TX enqueue是一直存在的，之所以在问题时段其enqueue争用如此显性，是因为IO写性能下降的缘故。

显著的I/O写出能力下降，特别是日志文件写的能力下降，导致commit变慢。对于存在潜在行锁等待的INX2_READWRITE_LOG索引，由于commit明显变慢，引发了剧烈的enqueue争用。


建议：

1.  请主机和存储侧协助调查为何22日白天redo log所在存储单元的I/O写出能力明显下降

2. 考虑将redo log移动到性能更好的独立存储单元上，以便提升其吞吐量和响应时间

3.  建议在确保I/O性能的前提下，重建INX2_READWRITE_LOG索引，不建议设置过大的initrans，一个ITL要占用24 bytes的空间，160个ITL占用3840 bytes，对于8192 bytes的block而言这么多的ITL的开销太大了，且如以下论证ITL并非问题的关键。 若要设置ITL 建议为20~60之间。

4. "mac"."indx"索引的DDL中启用了Parallel并行属性，虽然这不是本例中的关键问题，但仍建议将该索引设回NOPARALLEL。其DDL见附录




5. 考虑将READWRITE_LOG表改造为RANGE+HASH分区，HASH分区有助打散热快、缓解INSERT争用等问题，INX2_READWRITE_LOG作为本地分区同样受益。



6. 建议安装OSW 监控工具


3.        enqueue TX问题分析

以下列出BILL库多个时间点上的主要性能指标对比：


　        2月20日10点~11点        2月22日 10~11点        2月22日 17:00 ~17:26        2月24日 8点~11点
log file parallel write平均等待        4ms        110ms        83ms        4ms
log file sync        15ms        449ms        313ms        14ms
db file parallel write        9ms        149ms        153ms        8ms
db file sequential read等待        5ms        8ms        2ms        7ms
log file switch completion        77ms 无超时        326ms 超时107次        526ms 超时373次        45ms 无超时
redo blocks written/s        4,595        3,548        2547        3584
user commits/s        605        248        78.8        305
ITL等待        极少        极少        极少        极少
INX2_READWRITE_LOG上的Row Lock Waits        4,287/3600        56,494/3600        84,320/26*60        该索引已被drop
SQL:2434669063 insert into readwrite_log        buffer gets:10.8 elapsed <<0.1s        elapsed=0.16s        buffer gets:85.2 elapsed =3.39s        buffer gets:7.5 elapsed <<0.1s
SQL:2217190923 UPDATE READWRITE_LOG         buffer gets:8.4 elapsed<<0.1s        elapsed=0.12s        buffer gets:24.4 elapsed=0.8s        不是TOP SQL
SQL:3186662912 declare      v_flag        buffer gets:8.4 elapsed<<0.1s        buffer gets:10 elapsed=0.12s        buffer gets:24.3 elapsed=0.8s        不是TOP SQL
Max Concurcy最大事务数        23        291        298        16
TX wait        35s        128,244s        148,471s        18s


   2月20日10点~11点的运行的业务类型较为典型，且其各项指标较为健康，我们将该快照视为基线快照与2月22日10点~11点和17:00~17:26问题时段的快照进行对比，可以得出以下结论：

1. INX2_READWRITE_LOG索引上的Row Lock Waits是一直存在的，而不是问题快照时段才出现。该索引上的行锁等待在健康的基线快照中为每秒1.19次，而在问题快照中分别为每秒15次和每秒54次。该索引上的行锁等待明显增长了





2.enqueue TX在9i中可以分为 enq:TX row lock和enq:TX ITL等待，由于9i Oracle wait interface中没有将TX的row lock和ITL明显区分，所以判断具体是row lock还是ITL的主要依据是statspack中的segment statistics。 这些segment statistics来源于V$segment_statistics，未发现关于V$segment_statistics中row lock数据不可信的相关Bug，所以我们在这里认为V$segment_statistics提供的row lock数据是可信的。

statspack中实际显示不管是健康基线快照还是问题快照中的index ITL wait都非常少，另在指定INITTRANS=160并重建该索引后，enqueue TX问题并未减少。这均说明mode=4 的TX enqueue并不因为无法获得ITL而产生的，可以排除ITL导致该问题的可能性。


3. 问题发生的22日的I/O写性能对比20日有明显的下降， 健康基线快照中db file parallel write 平均等待9ms、log file parallel write平均等待4ms、log file sync 平均等待 15ms，每秒commit 605次。 而问题快照中db file parallel write 平均等待149ms，153ms、log file parallel write平均等待110 ms，83 ms、log file sync 平均等待449ms，313ms，每秒commit 78.8次。 另I/O读能力没有明显变坏。

另一个指标是健康快照中log file switch completion平均等待77ms ， 而问题快照为300ms以上且多次超时，这说明日志切换缓慢，结合上述I/O写性能现象，可知引起日志切换的是数据库检查点迟迟无法完成，也说明了写出能力存在瓶颈。


4. SQL:2434669063 insert into readwrite_log、SQL:2217190923 UPDATE READWRITE_LOG(使用ROWID作为条件)等核心SQL的特点是，它们都是只插入一行、或者更新一行的典型OLTP SQL。 这类SQL的主要特征是，它们均产生少量的buffer get，物理读的影响几乎可以忽略不计(缓存在buffer cache中)，主要的瓶颈往往是enqueue队列和commit产生的log file sync等待事件，在健康快照中log file sync即为第一位的等待事件，这也说明了commit的速度对于该类高并发的OLTP操作极为重要。

健康快照中commit为每秒605次，而问题快照中commit为每秒248和78次。

关于commit和I/O的关系讨论详见下文。



4.        commit和I/O的讨论


对于上文中问题快照提交指标commit次数/s远小于健康基线的情况，主要有2种可能性：

1.        由于enqueue TX造成进程大多阻塞在commit前的阶段，这导致单位时间的commit需求变少
2.        由于commit操作本身变慢，导致单位时间内完成的commit减少

对于可能性1，由于进程均阻塞在enqueue上导致commit变少，如果是这种情况，则单位时间redo block写出要求应当变少，因为Oracle的enqueue内存中的队列锁是不会直接影响I/O性能的，所以在I/O request变少的情况下，I/O响应时间应当维持其原有水平15ms以内； 这显然与事实不符。


对于可能性2，commit操作的等待事件表现为log file sync，而其后台LGWR写redo日志的等待事件表现为log file parallel write； log file parallel write的响应时间明显变慢，说明redo log所在存储的I/O瓶颈，这直接影响到commit的速度，而commit的速度对于高并发的OLTP十分重要。


5.        commit和enqueue的关系

commit与enqueue TX是有直接关系的，这是因为commit若慢了，则本应当快速释放的行锁就慢了。而且enqueue存在排队效应，并发的进程数越多，排队效应越明显。


举例来说若有20个进程对潜在存在row lock争用的行数据发起并发DML更新时，以下为一个数学模型：

若一次commit耗时0.001s，则这20个进程总的enqueue TX等待时间为( 0.001+ 0.001*2+0.001*3+0.001*4+0.001*5....0.001*19)=0.19s；

若一次commit耗时0.1s，则这20个进程总的enqueue TX等待时间为19s，commit本身总耗时 0.1*20= 2s

若一次commit耗时0.3s，则这20个进程总的enqueue TX等待时间为57s，commit本身总耗时 0.3*20= 6s


在这里commit时间越长，则总的等待事件越长；并发争用的进程越多则总的等待事件越长。

在正常情况下 log file sync的等待时间大于 enqueue TX的， 而在commit较慢、且并发量较大的情况下enqueue TX的等待时间大于log file sync的，成为Top 1的等待事件。

6.        row lock和index split的讨论

由于9i中enqueue TX等待事件没有像10g以后那样细分为：
        enq: TX row lock contention ==》 行锁争用
        enq:TX index contention    ==》 常见为索引块分裂导致的争用
        enq:TX allocate ITL entry  ==》ITL无法分配
        enq: TX - contention
也缺少failed probes on index block reclamation、recursive aborts on index block reclamation等索引块分裂的重要统计指标，所以本例中也不能完全排除mode=4的TX enqueue lock是由于INX2_READWRITE_LOG索引split缓慢引起的。






通过对READWRITE_LOG表的数据分组后发现，INX2_READWRITE_LOG (DATASTORE_NAME, AUDITFLAG, BYDATE)索引对应的三个字段数据分布存在DATASTORE_NAME存在220左右个不同的值,AUDITFLAG, BYDATE的值只有0和1，此种数据分布会加剧leaf node splits的可能性。IO性能的下降也可能导致index split变慢，进而引发剧烈的enqueue等待。
虽然statspack中branch/leaf index split 2个索引块分裂指标在问题时段未明显增多，但由于版本9i中enq:TX等待事件无法细分，和缺少其他重要衡量分裂的指标信息，所以无法区分究竟是row lock还是index split。



7.        分析结论




mode=4的TX enqueue是由于INDEX上的row lock/index split引起的，这与普通数据表上的mode=6的TX enqueue不同。INX2_READWRITE_LOG索引上的mode=4的TX enqueue是一直存在的，之所以在问题时段其enqueue争用如此显性，是因为IO写性能下降的缘故。

显著的I/O写出能力下降，特别是日志文件写的能力下降，导致commit变慢。对于存在潜在行锁等待的INX2_READWRITE_LOG索引，由于commit明显变慢，引发了剧烈的enqueue争用。








8.        建议

1.  请主机和存储侧协助调查为何22日白天redo log所在存储单元的I/O写出能力明显下降

2. 考虑将redo log移动到性能更好的独立存储单元上，以便提升其吞吐量和响应时间

3.  建议在确保I/O性能的前提下，重建INX2_READWRITE_LOG索引，不建议设置过大的initrans，一个ITL要占用24 bytes的空间，160个ITL占用3840 bytes，对于8192 bytes的block而言这么多的ITL的开销太大了，且如上述论证ITL并非问题的关键。 若要设置ITL 建议为20~60之间。

4. "mac"."indx"索引的DDL中启用了Parallel并行属性，虽然这不是本例中的关键问题，但仍建议将该索引设回NOPARALLEL。其DDL见附录




5. 考虑将READWRITE_LOG表改造为RANGE+HASH分区，HASH分区有助打散热快、缓解INSERT争用等问题，INX2_READWRITE_LOG作为本地分区同样受益。



6. 建议安装OSW 监控工具：

OSWatcher系统资源监控工具介绍


OSWatcher(OS Watcher Black Box)是Oracle标准的Support工具，该工具通过一系列的SHELL脚本来收集多方面的OS信息，包括CPU、内存、网络等。

OSWatcher不会给系统带来较重的性能负载，OSWatcher本质上是调用最常见的OS命令如ps、vmstat、netstat。

通过大量广泛的OSW使用，已经证明了OSW是一套安全、可靠的资源监控工具。


更多OSW的信息可以参考以下Metalink文档：

OSW 用户手册：OSWatcher Black Box User Guide.

What Is The OSWATCHER Black Box Effect On The Server Performance And What Are The Alternative Commands? [ID 946107.1]

中文：OSWatcher Black Box: How to improve performance and monitor your system automatically (Mandarin) [ID 1492202.1]

OSWatcher Black Box Analyzer User Guide [ID 461053.1]

cargoo

好文章一定要顶起

不了峰

顶一把　　　~