Mysql Batch Insert Test

結論

使用 @Transactional annotation 可以加速大筆 insert 動作
使用 BatchMode
- 不會加速大筆 Insert 動作 (跟使用 @Transactional 是差不多的速度)
- 過大或過小的 Batch Size 都會造成速度降低, 或標準差過大
- batch size = 100 是比較好的設定
以連續 insert 10000 筆資料 10 次, 看不出 mysql 有降低 insert 速度的趨勢

實驗方法

打開 Ebean logger

在 logback.xml 加入

  <logger name="org.avaje.ebean.SQL" level="TRACE" />

2017-04-06 2 35 09

Test Case 定義

callApi() 測試該 API 需要多久時間完成
每一個 @Test 之前都要先清除該 table (在這個測試使用 Receipt 這個 Model 為例)
第一次呼叫 API 都會需要比較長的時間
- 不確定是否因為 Play 的 Action 第一次被呼叫需要比較多時間初始化, 或是因為第二次呼叫 API 有 keep-alive 所以 response 時間較短
- 所以每個 @Test 的第一次 callApi() 的數值先忽略不計
為了測試資料庫已存在多筆資料是否影響 insert 速度, 所以沒有每次執行完 callApi() 都清除資料庫
```
package models;
```

import com.avaje.ebean.Ebean; import controllers.TestUtils; import org.junit.Test; import play.Logger; import play.test.WithApplication;

import java.io.UnsupportedEncodingException; import java.util.Calendar;

public class Bean extends WithApplication { static final String URL_BASIC = "/testBean"; static final String URL_BATCH = "/testBeanBatch"; static final String URL_TRANS = "/testBeanTrans";

private void callApi(String url) throws UnsupportedEncodingException {
    long start = Calendar.getInstance().getTimeInMillis();
    TestUtils.get(url);
    long end = Calendar.getInstance().getTimeInMillis();
    Logger.debug("end - start = " + String.valueOf(end - start));
}

@Test
public void testTran() throws UnsupportedEncodingException {
    Logger.debug("testTran()");
    Ebean.createSqlUpdate("delete from receipt").execute();
    callApi(URL_TRANS);
    callApi(URL_TRANS);
    callApi(URL_TRANS);
}

@Test
public void testBatch() throws UnsupportedEncodingException {
    Logger.debug("testBatch()");
    Ebean.createSqlUpdate("delete from receipt").execute();
    callApi(URL_BATCH);
    callApi(URL_BATCH);
    callApi(URL_BATCH);
}

@Test
public void testBasic() throws UnsupportedEncodingException {
    Logger.debug("testBasic()");
    Ebean.createSqlUpdate("delete from receipt").execute();
    callApi(URL_BASIC);
    callApi(URL_BASIC);
    callApi(URL_BASIC);
}

}


### API 定義
1. bean() 不使用 `@Transactional`
2. beanTrans() 使用 `@Transactional`
3. beanBatch() 使用 `@Transactional`, 並使用 BatchMode
4. 每個 API 都是 Insert 1000 筆資料
```java

    public Result bean() {
        for (int i = 0; i < 1000; i++) {
            new Receipt(new Auth(0)).save();
        }
        return ok();
    }

    `@Transactional`
    public Result beanTrans() {
        for (int i = 0; i < 1000; i++) {
            new Receipt(new Auth(0)).save();
        }
        return ok();
    }

    public Result beanBatch() {
        Transaction txn = Ebean.beginTransaction();
        try {
            txn.setBatchMode(true);
            txn.setBatchSize(100);
            // ** turn off getGeneratedKeys if you don't need to use the
            // mymodel bean instances after you have inserted them **
            txn.setBatchGetGeneratedKeys(false);

            for (int i = 0; i < 1000; i++) {
                new Receipt(new Auth(0)).save();
            }

            txn.commit();

        } catch (Exception e) {
            e.printStackTrace();
        } finally {
            txn.end();
        }
        return ok();
    }

實驗結果

Test 1 測試三種 API 的結果

使用 @Transactional 可以減少約 66% 時間

是否開啟 BatchMode 似乎沒有差別

是否 setBatchMode(), setBatchSize() 沒有效果? (請看 Test 2)


[debug] application - testBasic()
[debug] application - end - start = 4669
[debug] application - end - start = 3621
[debug] application - end - start = 3387
[debug] application - end - start = 3124
[debug] application - end - start = 3482

[debug] application - testBatch() [debug] application - end - start = 1211 [debug] application - end - start = 1079 [debug] application - end - start = 1237 [debug] application - end - start = 1131 [debug] application - end - start = 1163

[debug] application - testTran() [debug] application - end - start = 1564 [debug] application - end - start = 1207 [debug] application - end - start = 1017 [debug] application - end - start = 1083 [debug] application - end - start = 1140


### Test 2 測試 setBatchMode, setBatchSize() 是否有用
- 在 API 中加入 Logger

```java
Logger.debug("getBatchSize = " + Ebean.currentTransaction().getBatchSize());
Logger.debug("getBatch = " + Ebean.currentTransaction().getBatch());

可以確認兩隻 API 的 Transaction 設定符合預期
是否開啟 BatchMode 似乎不影響 Insert 速度

[debug] application - testBatch()
[debug] application - getBatchSize = 100
[debug] application - getBatch = ALL
[debug] application - end - start = 1620
[debug] application - getBatchSize = 100
[debug] application - getBatch = ALL
[debug] application - end - start = 1372
[debug] application - getBatchSize = 100
[debug] application - getBatch = ALL
[debug] application - end - start = 1198
[debug] application - getBatchSize = 100
[debug] application - getBatch = ALL
[debug] application - end - start = 1087
[debug] application - getBatchSize = 100
[debug] application - getBatch = ALL
[debug] application - end - start = 958

[debug] application - testTran()
[debug] application - getBatchSize = -1
[debug] application - getBatch = NONE
[debug] application - end - start = 1634
[debug] application - getBatchSize = -1
[debug] application - getBatch = NONE
[debug] application - end - start = 1230
[debug] application - getBatchSize = -1
[debug] application - getBatch = NONE
[debug] application - end - start = 1163
[debug] application - getBatchSize = -1
[debug] application - getBatch = NONE
[debug] application - end - start = 1065
[debug] application - getBatchSize = -1
[debug] application - getBatch = NONE
[debug] application - end - start = 982

~Test 3 測試 Batch Mode 的影響~

以 Insert 10000 筆為基準, 呼叫十一次 API, 忽略第一次結果
完成速度 Batch Mode > Non Batch Mode (越前面越快)
標準差 Non Batch Mode < Batch Mode (越前面越小)
測試多次的結果都不太一致

[debug] application - testBatch()
[debug] application - end - start = 13671
[debug] application - end - start = 10091
[debug] application - end - start = 8635
[debug] application - end - start = 8594
[debug] application - end - start = 9293
[debug] application - end - start = 12716
[debug] application - end - start = 10084
[debug] application - end - start = 8571
[debug] application - end - start = 10006
[debug] application - end - start = 10800
[debug] application - end - start = 10127
[debug] application - total = 98917

[debug] application - testTran()
[debug] application - end - start = 13457
[debug] application - end - start = 10823
[debug] application - end - start = 10583
[debug] application - end - start = 10794
[debug] application - end - start = 11090
[debug] application - end - start = 11087
[debug] application - end - start = 11027
[debug] application - end - start = 10616
[debug] application - end - start = 10412
[debug] application - end - start = 10621
[debug] application - end - start = 9022
[debug] application - total = 106075

Test 4 測試 Batch Size 的影響

以 Insert 10000 筆為基準, 呼叫十一次 API, 忽略第一次結果
完成速度 100 > 500 > 10 (越前面越快)
標準差 100 < 500 < 10 (越前面越小)

[debug] application - testBatch()
[debug] application - end - start = 11677
[debug] application - end - start = 9143
[debug] application - end - start = 9899
[debug] application - end - start = 8678
[debug] application - end - start = 8264
[debug] application - end - start = 8362
[debug] application - end - start = 9611
[debug] application - end - start = 9540
[debug] application - end - start = 8665
[debug] application - end - start = 8859
[debug] application - end - start = 8812
[debug] application - total = 89833

[debug] application - testBatch500()
[debug] application - end - start = 8929
[debug] application - end - start = 11508
[debug] application - end - start = 9512
[debug] application - end - start = 8602
[debug] application - end - start = 9509
[debug] application - end - start = 11985
[debug] application - end - start = 9493
[debug] application - end - start = 9791
[debug] application - end - start = 9604
[debug] application - end - start = 9201
[debug] application - end - start = 9055
[debug] application - total = 98260

[debug] application - testBatch10()
[debug] application - end - start = 13276
[debug] application - end - start = 11663
[debug] application - end - start = 9911
[debug] application - end - start = 10153
[debug] application - end - start = 9608
[debug] application - end - start = 10827
[debug] application - end - start = 10407
[debug] application - end - start = 9903
[debug] application - end - start = 13279
[debug] application - end - start = 9854
[debug] application - end - start = 12044
[debug] application - total = 107649

Test 5 觀察 Transaction Log

可以藉由 logback.xml 的設定看到 ebean 對 mysql 的操作及 transaction log
不使用 @Transactional 的 API 會有多個 txn[txnId]

使用 @Transactional 或是實作 Ebean.beginTransaction() 則會使用同一組 txn[txnId] basic transaction log

[debug] o.a.ebean.SQL - txn[3523] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(83218e21-07d1-448d-bfcc-914fd0f4cc93,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[3524] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(6a1fd2cb-60c1-4793-9a78-6f53896cbdf4,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[3525] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(1196dbd3-ef31-43b4-95bb-770076114559,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[3526] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(b62dd225-a151-4c88-b220-cbdb411fb498,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[3527] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(ea50fee4-ea73-4164-884b-1c2a03c162f4,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[3528] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(9fea1216-d57e-47a6-8ae3-8dfd014af3c2,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[3529] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(905217d6-6ed0-42f1-ae42-769a7acb1d4c,0,null,false,false,null,)

trans transaction log batch transaction log

[debug] o.a.ebean.SQL - txn[1004] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(6728e074-893c-4ec6-8204-f307f22bfaa7,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[1004] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(e69ecc8e-e18c-4d8d-8e70-3318e3766f1c,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[1004] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(e7a3208b-3140-4105-be9c-225690d1345c,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[1004] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(e346f8d9-2057-46de-b357-8937ad70b15b,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[1004] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(940760c9-3ef5-465f-aa62-6565664645aa,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[1004] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(147ffa27-4363-4749-b965-58fd7bc74f2c,0,null,false,false,null,)
[debug] o.a.ebean.SQL - txn[1004] insert into receipt (receipt_id, brand_id, name, is_master, is_enable, modify_log_uuid) values (?,?,?,?,?,?); --bind(d9f1c3da-5b8e-4b2b-886c-9002a77063ec,0,null,false,false,null,)

RammusXu / rammusxu.github.io