連番で大量にINSERTされるカラムのインデックスで待機イベント「enq: TX - index contention」が発生しやすい件と対策・検証（Oracle 12c）

# はじめに

よく利用されるBツリーインデックスは、リーフブロックがフルになるとブロックを分割するスプリットが発生します。特にインデックスがシーケンスだと、最後のリーフブロックに挿入されるためスプリットが発生しやすくなります。

対策は以下があげられます。

1. 逆キーインデックスにする。
2. パーティション化する。
3. コミットの回数を減らす。

ただし、逆キーインデックスは範囲検索ができなくなるので、対策として実施できないことが多い。コミット回数もアプリケーションの作りによっては減らすことが難しい場合もあり、パーティション化するという対策が一番用いられやすいかと思います。

これらの対策が有効かどうかを検証してみます（検証といっても簡単＆若干雑な実験ですが）。
検証にはOracle 12cを用いていますが、他のバージョンでも近い結果になると想定しています（検証した方が良いですけど）。


# 準備

まず、以下の3つのテーブルを作成。

1. 通常のテーブル（log_tbl）
2. ハッシュパーティション（log_tbl_hash）＋ローカルインデックス
3. 通常のテーブル（log_tbl_rev）＋逆キーインデックス

```
CREATE TABLE log_tbl
 (
 id number NOT NULL,
 msg1 varchar2(128),
 msg2 varchar2(128),
 insert_time timestamp
 );

CREATE UNIQUE INDEX idx_log_tbl1 ON log_tbl(id);
ALTER TABLE log_tbl ADD CONSTRAINT pk_log_tbl PRIMARY KEY (id) USING INDEX idx_log_tbl1;
CREATE INDEX idx_log_tbl2 ON log_tbl(msg1);
CREATE INDEX idx_log_tbl3 ON log_tbl(msg2);

CREATE TABLE log_tbl_hash
 (
 id number NOT NULL,
 msg1 varchar2(128),
 msg2 varchar2(128),
 insert_time timestamp
 )
PARTITION BY HASH (id)
(
    PARTITION P1
  , PARTITION P2
  , PARTITION P3
  , PARTITION P4
  , PARTITION P5
  , PARTITION P6
  , PARTITION P7
  , PARTITION P8
  , PARTITION P9
  , PARTITION P10
  , PARTITION P11
  , PARTITION P12
  , PARTITION P13
  , PARTITION P14
  , PARTITION P15
  , PARTITION P16
);

CREATE UNIQUE INDEX idx_log_tbl1_hash ON log_tbl_hash(id) LOCAL;
ALTER TABLE log_tbl_hash ADD CONSTRAINT pk_log_tbl_hash PRIMARY KEY (id) USING INDEX idx_log_tbl1_hash;
CREATE INDEX idx_log_tbl2_hash ON log_tbl_hash(msg1) LOCAL;
CREATE INDEX idx_log_tbl3_hash ON log_tbl_hash(msg2) LOCAL;

CREATE TABLE log_tbl_rev
 (
 id number NOT NULL,
 msg1 varchar2(128),
 msg2 varchar2(128),
 insert_time timestamp
 );

CREATE UNIQUE INDEX idx_log_tbl1_rev ON log_tbl_rev(id) REVERSE;
ALTER TABLE log_tbl_rev ADD CONSTRAINT pk_log_tbl_rev PRIMARY KEY (id) USING INDEX idx_log_tbl1_rev;
CREATE INDEX idx_log_tbl2_rev ON log_tbl_rev(msg1);
CREATE INDEX idx_log_tbl3_rev ON log_tbl_rev(msg2);

CREATE SEQUENCE logkey_seq START WITH 1 INCREMENT BY 1 MINVALUE 1 NOCYCLE CACHE 100;
```

# 実験

## 通常のテーブル

10万件を200スレッドで1件ずつインサート・コミットする。

SPレポートで待機イベントを見ると以下のとおり。
「enq: TX - index contention」が17,550回、合計303秒の待機が発生。
「buffer busy waits」も44,536回、合計932秒と多い。
「log file sync」は1回ごとにコミットしているのでやむなし。

```
                                                             Avg          %Total
                                          %Tim Total Wait   wait    Waits   Call
Event                               Waits  out   Time (s)   (ms)     /txn   Time
---------------------------- ------------ ---- ---------- ------ -------- ------
log file sync                     100,222    0      4,026     40      1.0   56.4
buffer busy waits                  44,536    0        932     21      0.4   13.1
latch: In memory undo latch        17,138    0        391     23      0.2    5.5
resmgr:cpu quantum                 19,782    0        349     18      0.2    4.9
enq: TX - index contention         17,550    0        303     17      0.2    4.2
```


# ハッシュパーティション（log_tbl_hash）＋ローカルインデックス

ハッシュパーティションは16パーティションに分けています。
10万件を200スレッドで1件ずつインサート・コミットした結果です。

「enq: TX - index contention」が17,550回→169回と激減。
「buffer busy waits」も44,536回→1,424回と激減。

```
                                                              Avg          %Total
                                          %Tim Total Wait   wait    Waits   Call
Event                               Waits  out   Time (s)   (ms)     /txn   Time
---------------------------- ------------ ---- ---------- ------ -------- ------
log file sync                     100,989    0      5,114     51      1.0   62.0
resmgr:cpu quantum                 26,065    0        694     27      0.3    8.4
library cache: mutex X             17,006    0        366     22      0.2    4.4
buffer busy waits                   1,424    0         18     13      0.0     .2
enq: TX - index contention            169    0          3     16      0.0     .0
```

# 通常のテーブル（log_tbl_rev）＋逆キーインデックス

10万件を200スレッドで1件ずつインサート・コミットした結果です。

「enq: TX - index contention」が17,550回→346回と激減。
「buffer busy waits」も44,536回→7,664回と激減。

```
                                                             Avg          %Total
                                          %Tim Total Wait   wait    Waits   Call
Event                               Waits  out   Time (s)   (ms)     /txn   Time
---------------------------- ------------ ---- ---------- ------ -------- ------
log file sync                     100,755    0      4,475     44      1.0   68.4
resmgr:cpu quantum                 26,659    0        675     25      0.3   10.3
buffer busy waits                   7,664    0        109     14      0.1    1.7
enq: TX - index contention            346    0          9     27      0.0     .1
```


# コミット回数を減らす

SQLを50回ごとにコミットするように変更しコミット回数を削減。件数は同じ10万件で試しています。

「enq: TX - index contention」が17,550回→613回と激減。
「buffer busy waits」も44,536回→3,858回と激減。
おまけに「log file sync」も激減。

```
                                            Avg          %Total
                                          %Tim Total Wait   wait    Waits   Call
Event                               Waits  out   Time (s)   (ms)     /txn   Time
---------------------------- ------------ ---- ---------- ------ -------- ------
enq: SQ - contention                9,282    0        433     47      3.4   15.0
enq: TX - index contention            613    0        406    662      0.2   14.0
resmgr:cpu quantum                  8,330    0        230     28      3.1    7.9
buffer busy waits                   3,858    0        141     37      1.4    4.9
enq: RO - fast object reuse            38    0         91   2382      0.0    3.1
log file sync                       2,157    0         79     37      0.8    2.7
```

# 検証結果まとめ

待機イベントが発生した回数は下表のとおり。
どの対策でも、「enq: TX - index contention」と「buffer busy waits」が激減しているのが分かります。


|                            | 通常のテーブル |  ハッシュパーティション（log_tbl_hash） ＋ローカルインデックス |  通常のテーブル（log_tbl_rev） ＋逆キーインデックス | コミット回数を減らす |
|----------------------------|----------------|----------------------------------------------------------------|-----------------------------------------------------|----------------------|
| enq: TX - index contention | 17,550         | 169                                                            |  346                                                | 613                  |
| buffer busy waits          | 44,536         | 1,424                                                          | 7,664                                               | 3,858                |
| log file sync              | 100,222        | 100,989                                                        | 100,755                                             | 2,157                |


# 検証プログラム

プログラムは雑ですが以下のように作成。Apache CamelフレームワークとコネクションプールライブラリにHikariCPを利用しています。

```java
package sample;

import java.sql.Connection;
import java.sql.PreparedStatement;
import java.sql.ResultSet;
import java.sql.SQLException;
import java.util.Locale;

import javax.annotation.Resource;

import org.apache.camel.CamelContext;
import org.apache.camel.Exchange;
import org.apache.camel.Processor;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;

import com.github.javafaker.Faker;
import com.zaxxer.hikari.HikariDataSource;

@Component
public class InsertSql implements Processor {

	@Resource
	private CamelContext context;

	private Logger logger = LoggerFactory.getLogger("sample.CreateDataProcessor");

	private String sql = "insert into log_tbl(id, msg1, msg2, insert_time) values(logkey_seq.NEXTVAL, ?, ?, current_timestamp)";
	//private String sql = "insert into log_tbl_hash(id, msg1, msg2, insert_time) values(logkey_seq.NEXTVAL, ?, ?, current_timestamp)";
	//private String sql = "insert into log_tbl_rev(id, msg1, msg2, insert_time) values(logkey_seq.NEXTVAL, ?, ?, current_timestamp)";

	private Faker faker = new Faker(new Locale("ja_JP"));

    @Override
    public void process(Exchange exchange) throws Exception {

    	HikariDataSource ds = (HikariDataSource)context.getRegistry().lookupByName("dataSource");

		try (Connection con = ds.getConnection();
				PreparedStatement ps = con.prepareStatement(sql);) {
			ps.setString(1, faker.lorem().sentence(3));
			ps.setString(2, faker.lorem().sentence(5));

			logger.info("insert process");
			try (ResultSet rs = ps.executeQuery();) {
				con.commit();
			}
		} catch (SQLException e) {
			logger.error(e.getMessage(), e);
		}
    }
}
```

```camel-context.xml
<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
	xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
	xmlns:camel="http://camel.apache.org/schema/spring"
	xmlns:util="http://www.springframework.org/schema/util"
	xmlns:context="http://www.springframework.org/schema/context"
	xmlns:jaxrs="http://cxf.apache.org/jaxrs"
	xmlns:cxf="http://cxf.apache.org/core"
	xsi:schemaLocation="http://www.springframework.org/schema/beans
          http://www.springframework.org/schema/beans/spring-beans-4.2.xsd
          http://camel.apache.org/schema/spring
          http://camel.apache.org/schema/spring/camel-spring.xsd
          http://www.springframework.org/schema/context
          http://www.springframework.org/schema/context/spring-context-4.2.xsd
          http://cxf.apache.org/jaxrs
          http://cxf.apache.org/schemas/jaxrs.xsd
          http://www.springframework.org/schema/util
          http://www.springframework.org/schema/util/spring-util-4.2.xsd">

	<context:component-scan base-package="sample" />

	<bean id="hikariConfig" class="com.zaxxer.hikari.HikariConfig">
		<property name="jdbcUrl" value="jdbc:oracle:thin:@192.168.10.232:1521:testdb" />
		<property name="driverClassName" value="oracle.jdbc.OracleDriver" />
		<property name="minimumIdle" value="100" />
		<property name="maximumPoolSize" value="200" />
		<property name="connectionTimeout" value="30000" />
		<property name="idleTimeout" value="600000" />
		<property name="maxLifetime" value="1800000" />
		<property name="username" value="hr" />
		<property name="password" value="hr" />
		<property name="connectionInitSql" value="select 1 from dual" />
		<property name="autoCommit" value="false" />
		<!-- <property name="connectionTestQuery" value="SELECT 1" />  --><!-- connectionTestQueryは非推奨 -->
		<property name="validationTimeout" value="5000" />
		<property name="registerMbeans" value="true" />
		<property name="poolName" value="testHikariPool" />
	</bean>

	<bean id="dataSource" class="com.zaxxer.hikari.HikariDataSource"
		destroy-method="close">
		<constructor-arg ref="hikariConfig" />
	</bean>

	<bean id="sqlComponent" class="org.apache.camel.component.sql.SqlComponent">
		<property name="dataSource" ref="dataSource" />
	</bean>

	<bean id="insertData" class="sample.InsertSql" />
	<bean id="insertData50" class="sample.InsertSql50Commit" />
	<bean id="createData" class="sample.CreateDataProcessor" />

	<bean id="testDataSet"
		class="org.apache.camel.component.dataset.SimpleDataSet">
		<property name="size" value="2000" />
		<property name="reportCount" value="2000" />
	</bean>

	<camelContext xmlns="http://camel.apache.org/schema/spring"
		id="quartzCluster">

		<threadPoolProfile id="customThreadPoolProfile"
			poolSize="300" maxPoolSize="300" maxQueueSize="50000"
			keepAliveTime="60" rejectedPolicy="CallerRuns" />

		<route id="quartzTest2">
			<from uri="dataset:testDataSet?produceDelay=-1" />

			<split parallelProcessing="true" executorServiceRef="customThreadPoolProfile">
				<simple>${body}</simple>
				<to uri="seda:test?size=100000" />
			</split>
		</route>
		<route id="seda2">
			<from uri="seda:test?concurrentConsumers=200" />
			<process ref="insertData50" />
			<log message="insertData end" />
			<to	uri="log:test_thread?level=INFO&amp;groupInterval=1000&amp;groupDelay=200&amp;groupActiveOnly=false" />
		</route>
	</camelContext>
</beans>
```