ラベル Performance/性能 の投稿を表示しています。 すべての投稿を表示
ラベル Performance/性能 の投稿を表示しています。 すべての投稿を表示

2012/01/24

ラウンドトリップタイム (Round-Trip Time; RTT)

海外拠点やクラウド事業者、災対サイトなど、ラウンドトリップタイム(RTT) が長い場所にあるDBから(やむを得ず)直接データを取得しなければならないケースが増えてきています。

ほとんどのDBクライアント用ドライバは、結果セットを分割して取得する仕様を採用しています。JDBCを例にとると、デフォルトでは10行ずつデータを取得(フェッチ)します。したがって、結果セットが25行ある場合、実際にはAPサーバとDBサーバの間ではデータが3回に分けて転送され、2回分のRTTが余分に経過します。

帳票は一般的に扱う行数が多い傾向があります。LPAR間などであれば問題が顕在化しないこともありますが、以下のいずれかに当てはまる場合、フェッチサイズの調整は検討に値します。
  • DBサーバとの間のRTTが長い
  • 取得する行数が極端に多い
また、プロジェクトで使用するフレームワークや共通部品は、場面に応じたフェッチサイズ変更を考慮した設計をお勧めします。

[Summary]
You can reduce the database round-trip by setting appropriate fetch size.

2012/01/17

Apache POI によるエクセル帳票出力の並列実行 その2 (Apache POI parallel processing, Part 2)


前回の並列実行の検証では、3スレッドまでは高い性能向上を示した後、伸び率が低下することが確認されました。
今回は、この時のOS統計を確認します。

【CPU】
CPU使用率の推移は以下の通りです。
※なお、検証環境の物理コア数は4です。
Figure 3: CPU usage

設定したスレッド数以上のコアが使用されていることが確認できます。これはJVM自身の挙動に関わるオーバーヘッドであり、これらを含めたスレッド数が物理コア数を超えたことで4スレッド時点で性能の伸び率が鈍化し始めたと想定されます。
※本記事ではこれ以上の調査は行いません。
過去にCOM経由でエクセルを操作した際の値と比較すると、CPU使用率が非常に低く抑えられています。性能の伸び率の高さは、このCPU使用率の余裕から生まれていると考えられます。

プロセッサ・キュー(Processor Queue Length)の値は6スレッドから目立ち始め、7スレッド以降は過負荷であることを示しています。
Figure 4: Processor Queue Length

参考まで、コンテキスト・スイッチ(Context Switches/sec)の発生も確認します。COM経由でExcelを操作した際の値と比較すると、10分の1以下で推移しています。
Figure 5: Context Switches / sec


【メモリ】
スレッド数の増加に伴って開きメモリが減少しますが、5GB以上の余裕があります。
グラフは割愛しますが、ページングも発生しておらず、問題は見られません。
Figure 6: Available Memory (MB)

【ディスク】
ディスクへの負荷はそれほど高くありません。グラフは割愛しますが、キューの待機も発生していません。
Figure 7: Disk usage

【GC】
今回はヒープを十分に確保(1GB)したため、Full GCは発生していません。参考まで、以下にJVMの推移を示します。
Figure 8: GC

※NEWについては改善の可能性もありますが、今回の検証ではこれ以上のチューニングは行わないこととします。

【結果】
以前の検証でエクセルによる帳票出力(COM経由での操作)を行ったときと同様、CPUの処理容量に依存しやすい傾向が確認されました。
※参照:「リンク」

COM経由でエクセルを操作する場合と比較すると、単位時間当たりの出力性能はApache POIが大幅に上回っています。
また、Apache POIを使用する場合はサーバ側のOSを選ばない点、およびサーバ側にエクセルのライセンスが不要である点も優位であるといえます。
しかしながら、Apache POI(またはその他のライブラリ)を使用する際には機能制限に留意する必要があります。現行バージョンの3.7ではXSLX形式の条件付書式に対応していない(次期3.8で対応予定)等、ユーザ要件を満たせない場合があります。エクセルのもつ機能・表現力を十分に発揮させたい場合には、これらの機能制限が不利となります。

帳票要件の複雑さと処理性能や実装環境を考慮し、Excelによる実装とApache POI等の外部ライブラリでの実装を使い分けることをお勧めします。
管理面からは「実装方式を一本化する」という方針が魅力的に見えることがありますが、実際には機能制限の回避や性能問題の解消などに不要な出費を強いる原因となりがちです。技術者の確保も容易な分野ですので、相当の理由がない限り、一本化は避けることをお勧めします。


[Summary]
OS statistics shows that Apache POI file processing is CPU bound.Please see Figure 3 to 7.
For your reference, Figure 8 shows JVM GC statistics.


The advantages of Apache POI:  The performance Apache POI manipulation is much faster than the performance of COM-Excel manipulation.  In addition, you do not need the Excel licence on the server side.
The disadvantage  of Apache POI: Apache POI does not support all the functions that Excel provides.

2011/10/26

エクセル帳票出力の並列実行 その2 (Excel file parallel processing, Part 2)


前回の並列実行の検証では、物理コア数までは並列度にしたがって出力性能が向上するものの、伸び率については、並列度が4倍(1→4)に増えても処理性能は2.3倍(秒間4.5ファイル→10.3ファイル)程度の伸び率にとどまることが確認されました。
今回は、この事象をOS統計から確認します。

【CPU】
CPU使用率の推移は以下の通りです。
※なお、検証環境の物理コア数は4です。
Figure 3: CPU usage

1スレッドでの実行においても、コアをまたがって処理負荷が分散されています。常に5つのコアがそれぞれ60%程度の使用率で推移しており、全体での使用率は約40%(300% ÷ 800%)です。従って、CPU容量に対する伸びしろはこの時点で最大2.5倍しか残されていないと言えます。

2スレッドでは、すべてのコアに処理負荷がかかっています。各コアの使用率はそれぞれ約60%、全体としての使用率も同じく60%です。
4スレッドで各コアの使用率が90%を超えます。また、5スレッド以降のCPU使用率の動きは、他のボトルネックによってCPUの動きが妨げられている可能性を示しています。

実行モードの内訳を確認すると、Priviledged Time (sys)が2割近くを占めています。
Figure 4: CPU mode

コンテキスト・スイッチ(Context Switches)の状態は以下の通りです。以前の検証でも高い値を記録していましたが、今回も同様です。
Figure 5: Context Switches

プロセッサ・キュー(Processor Queue Length)の値は4スレッドから目立ち始め、5スレッド以降は過負荷であることを示しています。
Figure 6: Processor Queue Length

【メモリ】
スレッド数の増加に伴って開きメモリが減っていきますが、6GB以上の余裕があります。
グラフは割愛しますが、ページングも発生しておらず、問題は見られません。
Figure 7: Memory

【ディスク】
4スレッドまでは問題ありません。5スレッド以降はDisk Timeの値が増加し始めます。
Figure 8: Disk Time (1 - Idle Time)

同様に、5スレッド以降、キューの滞留が徐々に増えています。
Figure 9: Disk Queue Length

【結論】
エクセルによる帳票出力(COMによる操作)はCPUの処理容量に依存しやすいと言えます。
また、エクセルのアプリケーション自体が10以上のプロセスを保持し、マルチスレッド処理を行っているため、エクセルのアプリケーションそのものを複数、並列に処理する場合でも処理性能が並列度に対してリニアに向上しないという点に留意する必要があります。


[Summary]
In the last post, multi thread processing had got poor result.  The maximum performance is 10.3 files per sec (130% increase) with four threads.
OS statistics explains the detail of this problem.


[CPU]
Figure 3 shows the CPU usage, from 1 to 8 threads.  The single thread test case(left side) uses 5 cores.  Overall CPU usage is about 40%, so the remained CPU resource is 60%.  This means that maximum performance increase ratio is 150% more ( 60 / 40 = 1.5).


Same as the past test (the original sample program), Priviledged Time (sys) gets higher than the ordinary level (Figure 4).
Context Switches seems bad in Figure 5.  Its trend is mostly same as CPU usage.
Processor Queue Length gets high from 5 to 8 threads (Figure 6).  This means too much threads causes collision and it leads lower performance.


[Memory]
Figure 7.  There seems no problem.


[Disk]
Figure 8 and 9.  Through 1 to 4 threads, no problem.  From 5 threads, Disk Time and Disk Queue Length get higher.


[Conclusion]
Excel file processing (Excel COM operation) is CPU bound.
Excel application itself manages more than 10 processes within , and perform multi thread processing.  This architecture might increase the single running performance though, there's few room to increase with running Excel application in parallel.

2011/10/25

エクセル帳票出力の並列実行 その1 (Excel file parallel processing, Part 1)

これまでの検証で、1ファイルあたりの処理時間は0.22秒まで短縮されました。処理性能は1秒当たり4.5ファイルとなります。
今回は並列処理で単位時間当たりの処理能力の向上を図り、どの程度リニアに性能が向上するかを検証します。

【検証の方法について】
通常の運用であれば、スケジューラのジョブを並列実行させますが、今回のサンプルではプログラム内で複数スレッドを生成することで検証を行います。
検証環境は「エクセルファイルのバッチ出力 その5」と同様です。なお、今回はデバッグモードではなく、アプリケーション(.exe)を直接実行します。

【サンプルソース(GUI部)】
サンプルのソースの内、呼び出し側(GUI側)を以下の様に修正します。並列度はスライダーで指定し、並列度を1から8(論理コア数)まで変化させます。
並列実行はSystems.Threads.Tasksに含まれるParallel.Forを使用します。スレッド毎に個別のオブジェクト(エクセルおよびDBセッションを保持する)を起動し、スレッド間の競合回避を図ります。
Figure 1: Form

List 1:

using System;
using System.Collections.Generic;
using System.ComponentModel;
using System.Data;
using System.Drawing;
using System.Linq;
using System.Text;
using System.Windows.Forms;
using Util;
using System.Diagnostics;
using System.Threading;
using System.Threading.Tasks;

 

namespace WindowsFormsApplication1
{
    public partial class Form1 : Form
    {
        public Form1()
        {
            InitializeComponent();
        }

        private void button1_Click(object sender, EventArgs e)
        {
            int num_threads = trackBar1.Value;
            List<Util.Ora2Excel> lst = new List<Util.Ora2Excel>();

            // initialize
            for (int i = 0; i < num_threads; i++)
            {
                lst.Add(new Util.Ora2Excel());
                lst[i].OpenDb(txtUser.Text, txtPassword.Text, txtConnString.Text);
                lst[i].InitExcel();
            }

            DateTime startTime = DateTime.Now;

            Parallel.For(0, num_threads, threadID =>
            {
                for (int idx = 0; idx < 100; idx++)
                {
                    lst[threadID].OpenBook(@"c:\template_emp.xlsx", true);
                    lst[threadID].Extract(txtSql.Text, txtSheet.Text);
                    lst[threadID].SaveBook(@"c:\" + threadID.ToString() + @"\result_emp" + "_" + threadID.ToString() + "_" + idx.ToString() + ".xlsx");
                    lst[threadID].CloseBook();
                }
            });
            
            // write the result
            System.IO.StreamWriter sw = new System.IO.StreamWriter(@"c:\testResult.log", true);
            sw.WriteLine("threads: " + num_threads.ToString() + ", "  + (DateTime.Now - startTime).ToString());
            sw.Close();
            
            // close objects
            for (int j = 0; j < num_threads; j++)
            {
                lst[j].QuitExcel();
                lst[j].CloseDb();
            }

        }

        private void trackBar1_Scroll(object sender, EventArgs e)
        {
            lblThreads.Text = "threads: " + trackBar1.Value.ToString();
        }
    }
}

【サンプルソース(DLL部)】
DLL部のソースに変更はありません。ソースは「エクセルファイルのバッチ出力 その3」を参照してください。

結果は以下の通りです。4多重まで増加させた場合でも、シングルスレッド実行の場合の約2倍の性能向上にとどまりました。秒間10.3ファイルの出力性能です。性能の向上率は高いとは言えません。
また、4コア以降、多重度を上げるにつれて性能が劣化しています。
Figure 2: Performance result

次回はOS統計を確認します。


[Summary]
In this post, we'll see how much we can increase Excel file processing performance by parallel (multi thread) processing.


[Environment]
Please refer to Excel file processing, Part 5.


[Sample source (GUI)]
In the ordinary batch system,you may run programs by job scheduler parallel.  In this test, I implement multi thread processing within the sample program.  Please refer Figure 1 and List 1.  The slider at the bottom of the form specifies the number of threads.  Each thread owns individual database session and Excel object.


[Sample source (DLL)]
No changes have been made.  Please refer to Excel file processing, Part 3 for the source code.


[Result]
As shown in Figure 2, the result is not so good.  The output performance hit the peak with four threads.  The peak performance is 10.3 files per sec. (100% increase from single thread performance)


In the next post, we read the OS statistics.

2011/10/17

エクセルファイルのバッチ出力 その6 (Excel file processing, Part 6)

ここで一度、サンプルプログラム実行時のマシン負荷を確認します。
今回はプログラムを素で実行し(デバッグモードではなく、EXEを直接起動)、OS統計を収集しました。
統計の取得間隔は2秒です。

【CPU】
論理8コア(物理4コア)の内、コアを4つ使用しています。各コアの使用率は50%程度で推移しており、全体としてのCPU使用率は約25%です。
Figure 11: CPU usage during the Excel file processing

CPU使用率の内訳を確認します。全体でのPrivileged TimeとUser Time(sys、user)の使用率は以下の通りです。Privileged Timeが若干ですが目立ちます。
Figure 12: CPU mode

念のためコンテキストスイッチ(Context Switches)を確認します。高い値で推移しています。Excel 2010では過去のバージョンよりも多くのスレッドが使用されているため、今回のような使用パターンでは値が高止まりしやすいと推測されます。
Figure 13: Context switches


また、エクセルのプロセスを抽出したCPUの使用率の推移は以下の通りです。約200%で推移しており、前述のCPU使用率(全体で25%)と概ね一致しています。
Figure 14: CPU usage of Excel process


今回はDBサーバが同一機材上のVMに構築されているため、VMのCPU使用状況も確認します。最大でも(800%中)約6%と、ほぼ凪であり、影響は概ね無視できると考えられます。
Figure 15: CPU usage of the VM processes


【メモリ】
メモリは余裕のある状態です。グラフは割愛しますが、ページングも発生しておらず、問題は認められません。
Figure 16: Memory usage


【ディスク】
ディスクも余裕のある状態です。問題は認められません。
Figure 17: Disk usage

今回の検証では、エクセル操作はCPUへの負荷が非常に高いことが確認されました。これらの値を踏まえた上で、次回はサンプルアプリにて並列処理を検証します。



[Summary]
Figures above show the OS statistics during the sample program processing.

[CPU]
Figure 11 shows that the sample program (and Excel process) uses 4 cores (Intel Core i7: 4 cores w/ HT).  Each cores are used around 50%.

Figure 12 shows Privileged Time and User Time in total.  the Privileged Time is higher than ordinary level.

Figure 13 shows Context Switches get high level.  Since Excel 2010 handles more threads than the past version (Excel 2003 and older), the overhead of context switch becomes bigger issue.

Figure 14 and 15 show CPU usage of Excel process and DB server on the virtual machine.  The CPU usage of VM is low enough to be ignored.

[Memory]
no problem with the memory (Figure 16).

[Disk]
Disk is not busy at all (Figure 17).

The result shows that Excel operation costs CPU resource.  I will test parallel processing in the next post.

2011/09/27

エクセルファイルのバッチ出力 その5 (Excel file processing, Part 5)

検証環境の記載を忘れていました。

検証環境はVM上に構築したDBに対して、実機上のクライアントアプリから問い合わせを行う構成です。
Figure 10: Machine environment

【DBサーバ】
VM: Virtual Box 4.0.12
CPU: 2コア
メモリ: 3GB
OS: Windows 2003 Server
DB: Oracle 11g R2 (11.2.0.1)

【クライアント】
CPU: Intel Core i7 920 (2.6GHz)
メモリ: 12GB
HDD: SSDを使用
OS: Windows 7 Ult.

【サンプルアプリ】
.NET: .NET Framework 4
言語・ツール: Visual Studio 2010 / C#
DB接続: OleDbConnection

計測はVisual Studio 2010のデバッグモードで行いました。
※デバッグモードと、Visual Studioを介さない素のアプリ実行との実測差異が無かった為、簡易ログ出力も兼ねて、デバッグモードで実行しています。実際のプロジェクトでは素のアプリで都度、計測を行ってください。本ブログでの検証はあくまでもサンプルです。



[Summary]
I forgot to put the machine environment description.  Please see Figure 1.


[DB Server (Virtual Machine)]
VM: Virtual Box 4.0.12
CPU: 2 cores
Memory: 3GB
OS: Windows 2003 Server
DB: Oracle 11g R2 (11.2.0.1)


[Client Machine (Physical Machine)]
CPU: Intel Core i7 920 (2.6GHz)
Memory: 12GB
HDD: SSD
OS: Windows 7 Ult.


[Sample Application]
.NET: .NET Framework 4
Language / Tool: Visual Studio 2010 / C#
DB Connection: OleDbConnection


Performance test is held on debug mode of Visual Studio.
(*) There are few performance difference between debug mode and native application running




2011/09/26

エクセルファイルのバッチ出力 その4 (Excel file processing, Part 4)

エクセルへのデータ転送が高速化された結果、ファイルのオープンおよび保存にかかる時間が無視できなくなりました。
参考まで、前回までの検証で使用したテンプレート(Fat file)に設定されていたスパークラインやコメントを取り除き、軽量化したテンプレート(Simple file)での計測結果は以下の通りです。
Figure 9: Light template file is processed faster.

1ファイルあたりの所要時間は0.30秒から0.22秒に短縮されています。テンプレートの軽量化には一定の効果(今回は約30%)があることが確認できます。


[summary]
Now the major events are save and open file.  To reduce these events, I removed the Spark Line and cell comments on the template sheet.
The results are shown in Figure 9.  Fat file is the ordinary template file (sample template of previous post).  Simple file is the template file without Spark Line and cell comments.
Total time is reduced from 0.30 sec to 0.22 sec (per file).

Complicated templates are not better than simple ones always.

2011/09/20

エクセルファイルのバッチ出力 その3 (Excel file processing, Part 3)

エクセルへのデータ展開を高速化する方法についてはマイクロソフト社のナレッジに説明されています。
Visual C# 2005 または Visual C# .NET を使用してデータを Excel ブックに転送する方法:


具体的には、データを各セルに1つ1つ設定するのではなく、データを配列に格納した上で、配列をエクセルのレンジに渡す処理を実装します。この実装によりエクセルとの通信回数が減り、処理時間が短縮されます。
サンプルのソースは以下の通りです。

List 5:

public void Extract(string sql, string SheetName)
{
    const int XL_WHOLE = 1;
    const int XL_DOWN = -4121;
    const string START_TAG = "$start";

    int colCount;
    List<object[]> lst = new List<object[]>();
    DateTime lapTime;

    lapTime = DateTime.Now;
    OleDbDataReader rst = GetRecordset(sql);    // get recordset
    colCount = rst.FieldCount;
    Debug.WriteLine("[query] " + (DateTime.Now - lapTime).ToString());

    lapTime = DateTime.Now;
    while (rst.Read())                          // output loop
    {
        object[] ColValues = new Object[rst.FieldCount];
        for (int idxCol = 0; idxCol < rst.FieldCount; idxCol++)
            ColValues[idxCol] = rst.GetValue(idxCol);
        lst.Add(ColValues);
    }
    Debug.WriteLine("[set row val] " + (DateTime.Now - lapTime).ToString());
    rst.Close();

    // convert list => array
    lapTime = DateTime.Now;
    object[,] Values2Copy = new Object[lst.Count, colCount];
    for (int idxRow = 0; idxRow < lst.Count; idxRow++)
        for (int idxCol = 0; idxCol < colCount; idxCol++)
            Values2Copy[idxRow, idxCol] = lst[idxRow][idxCol];
    Debug.WriteLine("[list to array] " + (DateTime.Now - lapTime).ToString());

    // copy array into excel sheet.
    lapTime = DateTime.Now;
    xSheet = xBook.Worksheets[SheetName];       // activate start position
    Debug.WriteLine("[activate sheet] " + (DateTime.Now - lapTime).ToString());

    lapTime = DateTime.Now;
    xSheet.Cells.Find(What: START_TAG, LookAt: XL_WHOLE).Activate();
    Debug.WriteLine("[find $start] " + (DateTime.Now - lapTime).ToString());

    lapTime = DateTime.Now;
    int idxStart = xApplication.ActiveCell.Row;
    xSheet.Rows[xApplication.ActiveCell.Row].Copy();
    xSheet.Rows[(idxStart + 1).ToString() + ":" + (idxStart + lst.Count-1).ToString()].Insert(Shift: XL_DOWN);
    Debug.WriteLine("[insert row] " + (DateTime.Now - lapTime).ToString());

    lapTime = DateTime.Now;
    Range r = xApplication.ActiveCell;
    r = r.get_Resize(lst.Count, colCount);
    r.set_Value(Missing.Value, Values2Copy);
    Debug.WriteLine("[copy into range] " + (DateTime.Now - lapTime).ToString());
}


実行時にレコードセットの列数と行数を動的に判断させるため、上記のソースでは一度データをListに関連付けたObjectに格納し、データをすべて抽出した後、Listの内容を配列に代入します。

上記サンプルの実行結果(経過時間)は以下の通りです。

Figure 7: Events

データ設定部分のイベント(extract)が大幅に低減(1.24秒→0.04秒)していることが確認できます。全体(1ファイルあたり)の処理時間も1.5秒から0.3秒に短縮されました。帳票出力のバッチとしては遅いといえますが、Excelオートメーションを利用する場合、この程度を目安にする必要があるといえます。
※なお、大量データを1つのシートに保存するようなケースでは、ファイルのオープン/クローズに要する時間の割合が低下するため、処理効率は向上します。

DLL処理部の内訳は以下の通りです。※時間の縮尺が異なります。
Figure 8: Events in DLL

エクセルオブジェクトの操作の操作に関わる部分で処理時間を要していることが確認できます。


[Summary]
To speed up Excel operation, please refer to the following Microsoft Knowledge Base.


How to transfer data to an Excel workbook by using Visual C# 2005 or Visual C# .NET
http://support.microsoft.com/kb/306023/en-us


The program transfer two dimension array to a range of multiple cells at one time.  This technique runs faster than passing data cell by cell.
List 5 uses List to store the fetched rows.  This is because the sample program determines the number of rows and columns in runtime.


Figure 7 shows elapsed time per file.  The main part (extract) is reduced from 1.24 sec to 0.04 sec.  So, the total elapsed time is 1.5 sec to 0.3 sec per each.  (Still it is slow, though)


Inside "extract", please see Figure 8.  (*) Note that time scale is different.

2011/09/13

エクセルファイルのバッチ出力 その2 (Excel file processing, Part 2)

前回のサンプルプログラムの性能を確認します。テストプログラム側を修正し、100ファイルを出力する際の処理時間を計測します。

List 3: Test GUI
private void button1_Click(object sender, EventArgs e)
{

    DefaultTraceListener dtl = (DefaultTraceListener)Debug.Listeners["Default"];
    dtl.LogFileName = @"c:\Sample.log";


    Util.Ora2Excel x = new Util.Ora2Excel();

    x.OpenDb(txtUser.Text, txtPassword.Text, txtConnString.Text);
    x.InitExcel();

    DateTime lapTime;
    DateTime startTime = DateTime.Now;

    for (int i = 0; i < 100; i++)
    {
        lapTime = DateTime.Now;
        x.OpenBook(txtTemplate.Text);
        Debug.WriteLine("[file open] " + (DateTime.Now - lapTime).ToString());

        lapTime = DateTime.Now;
        x.Extract(txtSql.Text, txtSheet.Text);
        Debug.WriteLine("[extract] " + (DateTime.Now - lapTime).ToString());

        lapTime = DateTime.Now;
        x.SaveBook(@"d:\result_emp" + i.ToString() + ".xlsx");
        Debug.WriteLine("[save] " + (DateTime.Now - lapTime).ToString());

        lapTime = DateTime.Now;
        x.CloseBook();
        Debug.WriteLine("[close] " + (DateTime.Now - lapTime).ToString());
    }

    Debug.WriteLine("[total] " + (DateTime.Now - startTime).ToString());

    x.QuitExcel();
    x.CloseDb();
}
上記の処理結果ログを集計し、1ファイルあたりの平均処理時間を算出した結果は以下の通りです。最も長い処理イベントはデータをエクセルシートに展開する部分であることがわかります。
Figure 5: Events

エクセルシートに展開する部分についてより詳細を確認するため、DLL内の処理を以下のように修正し、再度計測を行います。

List 4:
public void Extract(string sql, string SheetName)
{
    const int XL_WHOLE = 1;
    const int XL_DOWN = -4121;
    const string START_TAG = "$start";

    int idxRow;
    DateTime lapTime;

    lapTime = DateTime.Now;
    OleDbDataReader rst = GetRecordset(sql);    // get recordset
    Debug.WriteLine("[query] " + (DateTime.Now - lapTime).ToString());

    lapTime = DateTime.Now;
    xSheet = xBook.Worksheets[SheetName];       // activate start position
    Debug.WriteLine("[activate sheet] " + (DateTime.Now - lapTime).ToString());

    lapTime = DateTime.Now;
    xSheet.Cells.Find(What: START_TAG, LookAt: XL_WHOLE).Activate();
    Debug.WriteLine("[find $start] " + (DateTime.Now - lapTime).ToString());

    idxRow = xApplication.ActiveCell.Row;
            
    while (rst.Read())                          // output loop
    {
        lapTime = DateTime.Now;
        xSheet.Rows[idxRow].Copy();
        xSheet.Rows[idxRow+1].Insert(Shift: XL_DOWN);
        Debug.WriteLine("[insert row] " + (DateTime.Now - lapTime).ToString());

        lapTime = DateTime.Now;
        for (int idxCol = 0; idxCol < rst.FieldCount; idxCol++)
            xSheet.Cells[idxRow,idxCol+1].value = rst.GetValue(idxCol);
        Debug.WriteLine("[set cell val] " + (DateTime.Now - lapTime).ToString());

        idxRow++;
    }
    rst.Close();
}

結果は以下の通りです。セルへのデータ設定と行のインサート処理の占める割合が大きいことがわかります。
Figure 6: Events in DLL

今回のケースでは、10行程度の出力で、1ファイルあたり約1.5秒を要することが確認できます。
次回はデータをエクセルに出力する部分のソースを変更し、性能の改善を図ります。


[Summary]

The sample program shown in List 3 outputs 100 excel files (The original source is in the last post). This source writes down the lap time to log file.

Figure 5 shows that the longest event is extracting the data onto Excel worksheet.  Extracting takes about 1.2 second per a file.
To see more detailed log, see List 4 and Figure 6. You see that the cell and row manipulations take long time.

In the next post, these manipulations will be improved.

2011/08/11

Windowsにおけるディスクの稼働率 (Monitor the disk usage on Windows)

「バースティング性能 その3」にて「別途説明」としたまま%Idle Timeの説明を忘れていました。

Windowsのパフォーマンスモニタでのディスクの稼働状況を見る場合、負荷のかかった状態においてPhysical Diskの%Disk Timeの値がしばしば 100% を超えます。このため、Microsoftは以下のKnowledge Baseにて、「%100 - %Idle Time」の値を使用するようにガイドしています。
パフォーマンス MMC で %Disk Time の値が 100% を超える
http://support.microsoft.com/kb/310067/ja

残念ながら、「%100 - %Idle Time」で使用率を求めた場合でも高負荷時に統計情報が乱れることはあります。このため、Knowledge Baseの原文では以下の3つの値でディスクの遅延を監視するよう、記載が変更されています。
  • Avg. Disk sec/Read
  • Avg. Disk sec/Write
  • Avg. Disk sec/Transfer
% Disk Time may exceed 100 percent in the Performance Monitor MMC
http://support.microsoft.com/kb/310067/en-us

原文と日本語訳にずれがある状態です。とは言え、%100 - %Idle Timeで得られる情報は凪から中程度の負荷までは問題なく使用できると考えられますので、目的に応じて監視項目を使い分けてください。



[Summary]
When you monitor the disk usage on Windows OS, the easy way is to monior "%100 - %Idle Time" (not %Disk Time).
More accurate way is, monitoring the disk latencies with the following values.
  • Avg. Disk sec/Read
  • Avg. Disk sec/Write
  • Avg. Disk sec/Transfer



For more details, please refer to the Microsoft Knowledge Base:
% Disk Time may exceed 100 percent in the Performance Monitor MMC
http://support.microsoft.com/kb/310067/en-us

2011/05/12

バースティング性能 その6(Performance of the bursting function part 6)

BI Publisher 11gでの性能検証は、結論から申しますと失敗しました。1万ファイルへのバースティングに30分近く要する状況です。
VMの構成、およびJRockitの設定の見直しを行っているものの、芳しくありません。

この問題については今後、成功・失敗を問わず、事象に動きがあった段階でこのブログ上で公開したいと思います。


[Summary]
Performance test of BI Publisher 11g had not got good result so far - it takes around 30 minutes to burst the data into 10,000 files.
I suspend further investigation on this issue for a while.

2011/05/10

バースティング性能 その5(Performance of the bursting function part 5)

1ファイル1ページの出力を検証します。
残念ながら、BI Publisher 11g での検証は、VM上での検証が不調に終わったため、都合により、BI Publisher 10gでの検証結果を記載します。

【検証環境】
検証環境のBIサーバ構成を以下の通り変更します。
ゲストマシン2(BIEE):
CPU: 4コア
Memory: 4GB
OS: Windows2003 Server, 32bit
BIEE: Oracle BIEE 10g

BI Publisher10gでは、マルチスレッド処理の設定を手動で行う必要があります。今回はコア数と同じ4スレッドでの実行を設定します。
Figure 1: Runtime property setting


【結果】
出力結果は以下の通りです。出力に3分以上かかる結果となってしまいました。


所要時間(秒)
秒間出力ページ数
1回目
199.7
50.0
2回目
180.5
55.4
3回目
201.9
49.5
平均
194.0
51.7

平均で秒間約51ページの出力性能となりました。


【OS統計】
OS統計からは、ディスクおよびメモリに問題は見られません。
CPU使用率を確認すると、個々のコアの使用率が低く、かつ、断続的に落ち込んでいる状況が確認できます。

CPU:
バッチ処理としては、CPUリソースの能力を引き出せていません。全体で6割程度の使用率です。
Figure 2: CPU usage

メモリ:
メモリには余裕がある状態です。
Figure 3: Memory

ディスク:
ディスクアクセスにも問題はありません。
Figure 4: Disk time

【JVMのチューニング】
OS統計からは明確なボトルネック情報は得られませんが、CPUの動きからはGCが疑われます。
同時間帯のGCの様子を確認します。
Figure 5: Garbage Collection status (default setting)

Full GC (黒線)が多発しています。物理メモリにはまだ余裕がありますので、GCの間隔を広げるため、ヒープの絶対量を増やします。

最大サイズ(Xmx)を1GBに指定し、また、バッチ単体用途処理ですので、初期サイズ(Xms)も1GBに合わせます。併せて、パラレルGC (XX:+UseParallelGC)を設定します。参考まで、以下に追加・変更する設定を示します。
-Xmx1024M -Xms1024M -XX:+UseParallelGC


【再実行結果】
出力結果は以下の通りです。平均で約1分20秒、秒間約120ページの出力性能となりました。

所要時間(秒)
秒間出力ページ数
1回目
82.3
121.5
2回目
82.3
121.5
3回目
84.0
118.9
平均
82.9
120.7

GCの頻度が低減し、スループット(下図のThroughput)も改善(79.32% → 95.93%)しています。これは、実行時間中にGCのためにJVMが停止した時間が大幅に減少したことを表しています。
今回はこれ以上のJVMの調査・チューニングは行いません。
Figure 6: Garbage Collection (Heap=1GB)


【OS統計】
CPU使用率が回復していることが確認できます。


CPU:
おおむね100%に近い使用率となっています。バッチ処理として、リソースの性能を引き出すことができています。

Figure 7: CPU usage

メモリ:
JVMにメモリを割り当てた分、空き容量は減少していますが問題はありません。
Figure 8: Memory

ディスク:
ディスクは余裕のある状態です。
Figure 9: Disk Time


1ファイルに1万ページをまとめて出力した場合のファイルサイズは19MBでしたが、1ページ1ファイル(本来のバースティング)の出力では、出力されるファイルの総サイズが458MB(1ファイルあたり46KB)に増加します。
PDFファイルを個別に出力する際のオーバーヘッドを勘案すると、ある程度妥当な性能と言えます。
これまで見てきたように、BI Publisher のバースティング機能はCPU性能に依存しますので、機器構成の検討の際にはインフラ担当者と密に連携し、性能検証を十分に実施することをお勧めします。


[Summary]
Now it's one page in each file.
Since BI Publisher 11g on my VM did not get good result, this time, I use BI Publisher 10g.  I may try 11g again in near future.


With BI Publisher 10g, you need to specify some parameters to implement multi thread bursting.  Figure 1 shows the setting.  Please refer the manual:
http://download.oracle.com/docs/cd/E10415_01/doc/bi.1013/e12187/T518230T522345.htm




[Result]
The result are as follows...  Not good.  It took three minutes over.


Elapsed Time(sec)
pages / sec
1st
199.7
50.0
2nd
180.5
55.4
3rd
201.9
49.5
Average
194.0
51.7

[OS statistics]
OS statistics shows no bottleneck on memory nor disk (Figure 3 and 4).  You may see the CPU usage stays low (Figure 2).




[JVM Tuning]
BI Publisher runs on JVM, you should check the Garbage Collection behavior.  Figure 5 tells there had been too many Full GC.
The memory can afford more JVM heap.  Below is new setting:

-Xmx1024M -Xms1024M -XX:+UseParallelGC





[Result (with JVM heap size 1GB)]
It gets better.  The average is 120 pages per second.

Elapsed Time(sec)
pages / sec
1st
82.3
121.5
2nd
82.3
121.5
3rd
84.0
118.9
Average
82.9
120.7



Figure 6 shows that the Full GC has been vanished.  You can see the Throughput in GC Viewer increased from 79.32% to 95.93%.  It means the pause time in JVM had been reduced a lot.



[OS statistics]
CPU usage gets higher.  It's around 98% (Figure 7).  This means BI Publisher uses the CPU resource effectively.
The memory and the disk stay calm (Figure 8 and 9).


The PDF file size is 46KB each, total 458MB (46KB * 10,000 files = 458MB).  In Part 1, the file size was 18.8MB.  The file size increased more than 20 times.
With consideration of the overheads (overhead when BI Publisher produces 10,000 individual PDF files), I accept this result.

The bursting function of BI Publisher is CPU-bound.  You should better to communicate with the infrastructure team to discuss the server spec.  The performance test should be done with them before they determine the spec, if possible.