Apache POI によるエクセルファイルの出力 その2 (Export to Excel file via Apache POI, Part 2)

前回のサンプルプログラムの性能を確認します。

CPU性能等の検証環境については「エクセルファイルのバッチ出力 その5」を参照してください。


【呼び出し側プログラムの修正】
テストプログラム側を以下の様に修正し、100ファイルを出力する際の処理時間を計測します。


List 3:

public class Test1 {

  public static void main(String[] args) throws Exception {
    long timeStarted = System.currentTimeMillis();

    Ora2Excel o2x = new Ora2Excel();
    
    o2x.openDb("scott", "tiger", "jdbc:oracle:thin:@windows2003srv:1521:orcl");
    
    for (int i = 0; i <100; i++) {
      long lapTime = System.currentTimeMillis();
      o2x.openBook("c:\\template.xlsx");
      System.out.println("[file open] " + (System.currentTimeMillis()- lapTime));
      
      lapTime = System.currentTimeMillis();
      o2x.extract("Sheet1", "select deptno, empno, ename, job, mgr, hiredate, sal, comm from emp order by deptno, empno");
      System.out.println("[extract] " + (System.currentTimeMillis()- lapTime));
      
      lapTime = System.currentTimeMillis();
      o2x.saveBook("c:\\temp\\result_" + i + ".xlsx");
      System.out.println("[save] " + (System.currentTimeMillis()- lapTime));
      
      lapTime = System.currentTimeMillis();
      o2x.closeBook();
      System.out.println("[close] " + (System.currentTimeMillis()- lapTime));
    }
    
    o2x.closeDb();
    System.out.println("[total] " + (System.currentTimeMillis()- timeStarted));
  }
}

上記の処理結果ログを集計し、1ファイルあたりの平均処理時間を算出した結果は以下の通りです。最も長い処理イベントはテンプレートファイルを開く部分(file open)であることがわかります。

Figure 4: Events

上記の結果は１００ファイルを出力した際の平均値ですが、実際には、１ファイル目と２ファイル目以降の処理時間は大きく異なります。以下のグラフは縦軸が各イベントが１ファイル毎に要する時間、横軸が処理ファイルの順番を表しています。２ファイル目以降の処理時間が大きく低減していることが分かります。

Figure 5: Elapsed time per file

１ファイル目ではテンプレートファイルを開くのに1.12秒、全体（1ファイルあたり）で約1.8秒要していましたが、2ファイル目以降、順次0.3秒程度まで低減し、1ファイルあたりの処理時間も平均で0.07秒まで低減しています。
単純に換算すると秒間の出力性能は約14ファイルとなりますので、1万ファイルを出力する場合はおよそ12分弱と推計されます。（2012-01-11 削除）

次回は並列実行した場合の検証を行います。

【2012-01-11追記】
今回の検証ではJVMの起動（および初回のロード）に伴うオーバーヘッドが経過時間に含まれてしまっています。このため、たとえば起動済みJVMで処理を行った場合や、出力するファイル数を増加させた上で平均をとった場合には、性能はより向上します。手元で改めて1000ファイルを出力した場合、1ファイルあたりの出力時間は約27.5ファイルとなりました。

---

[Summary]
The sample program shown in List 3 outputs 100 excel files (The original source is in the last post).


Figure 4 shows that the longest event is opening the template file - it takes about 35 millisecond per a file.
Figure 5, the left axis shows the elapsed time for each event per a file. The bottom axis shows the sequence number of the file produced. This graph shows that the first file takes much longer - around 1.8 second - than the following files.



[January, 11, 2012: append]
The elapsed time includes JVM start up overhead.  This overhead had reduced the performance.  The more files, the Additional test result: 36.27 sec. to produce 1000 files - 27.5 files per sec.