大規模な処理のパフォーマンス計測手段

2022/2/10

2022/8/15

製品

DT+Trace

カテゴリー

How-to

開発中に改善に時間のかかる不具合の一つに、大きな処理のパフォーマンスが思った以上にかかってしまう不具合があげられます。特に、Linux環境などでのマルチプロセス／スレッドを利用した処理や関係する関数が多い場合、ボトルネックになっている処理の特定は困難になります。

本資料では上記のような問題に対してのアプローチ手段について説明します。

Contents

1 見込める効果
2 作業手順
3 データの解析

見込める効果

不具合箇所の特定の効率化

DT+Traceでトレースデータを取得する事で「不定のタイミングで処理が重くなる」「広い範囲を解析するための準備、解析に時間がかかる」といった点を効率的に解析する事ができます。また、詳細な解析を行いたいテストレポート範囲トリミングして再解析する事で「関数レベルでの負荷の大きい処理を適切に発見」できます。また、見比べたい部分の関数遷移スコープを列挙して比較する事で通常処理とどのように処理の流れが違うのかなど、全体的な動作の違いをグラフィカルなイメージと合わせて確認する事で、現象の原因を俯瞰的に解析する事が可能になります。

作業手順

テストポイント挿入箇所の絞り込み及び挿入

自動挿入の範囲を設定する

不具合の解析では、闇雲にテストポイントを挿入してしまうとレポートデータ量が増加し解析に時間がかかってしまうケースがあります。
テストレポートの解析は不具合の状況によって適切なテストポイント挿入を行う事でより効率的に解析可能です。

不具合の検証範囲がある程度明確なケース

DTプロジェクトに登録／挿入するソースファイルは検証対象のみ限定したほうが効率的です。挿入設定は基本変更せず[ソースファイル／関数単位の挿入]や[手動での挿入]を活用し、不具合の原因を絞り込んでいく必要があります。

不具合の検証範囲が不明なケース

不具合原因予測ができず広い範囲で現象を確認する必要がある場合は広く浅く適用し、そこから対象を絞り込んでいく作業が必要になります。

登録するソースファイルは試験対象全てを範囲とし自動挿入設定の変更で挿入するテストポイントの種別を限定し、そこから適応範囲を絞り込んでいく必要があります。

テストポイントの種別を限定する方法はDT+Traceアプリケーションの「ファイル」メニュー＞「プロジェクトの設定」＞「自動挿入設定」＞「共通」＞「挿入アルゴリズム」＞「挿入するテストポイント種別」から指定します。

設定後、完了ボタンから「確定して新規挿入」を選択します。

データの取得

DTドライバのカスタマイズ

以下にドライバのカスタマイズの例を提示します。今回の環境はLinux環境のユーザーランド層ファイル書き出しドライバを適用するケースを元に解説しております。

複数のターゲットのデータを取得する場合の時間軸の調整

複数のターゲットからデータを取得する場合、アプリ間の時間軸を調整する必要があります。例えばファイル書き出しの標準のドライバではテスト開始時(一番最初のトレースデータの出力時)との差分時間を出力しています。

void _TP_BusOut(DT_UINT addr, DT_UINT dat)
{
...
	if (BusoutMode == 0) {
		/* Customize File Path */
		dat_file = fopen("ConvertData.DAT", "wb+");
		if (dat_file == NULL) {
			return;
		}
		/* start time data */
		//初期化処理内で時間値の起点を取得
		if (clock_gettime(CLOCK_MONOTONIC, &now) == -1) {
			printf("DT10 : timer error!\n");
		}
		start_time = (unsigned int)((now.tv_sec*1000*1000) + (now.tv_nsec/1000));
		BusOutModeSet(1);
	}

	SEM_WAIT;
	/* time data */
	//テストレポート取得時の時刻を取得
	if (clock_gettime(CLOCK_MONOTONIC, &now) == -1) {
		printf("DT : timer error!\n");
	}
	//開始時点からの差分時間のみ取得
	time = (unsigned int)((now.tv_sec*1000*1000) + (now.tv_nsec/1000));
	time -= start_time;	
...
	/* time data */
	//timeは4byte分取得
	buff[5] = (unsigned char)((time) & 0xFF);
	buff[6] = (unsigned char)((time >> 8) & 0xFF);
	buff[7] = (unsigned char)((time >> 16) & 0xFF);
	buff[8] = (unsigned char)((time >> 24) & 0xFF);
...
}

標準のドライバではif (BusoutMode == 0)のファイル生成時のタイミングを0起点として、以降の差分時間を記録します。一つのプログラムに適応する場合、レポートデータのインポート時に指定した日時から時刻変換を行うため、任意の時刻と合わせやすい形になります。ただ、この方法では複数のプログラムから同時にトレースログを取得する場合、時間値の0秒の基準が各アプリ単位で0秒の基準が異なってしまうため一つのテストレポートとしてまとめることができません。そのため、下記の変更をもって時間軸をターゲット上での一意の時間で取得するようカスタマイズします。

void _TP_BusOut(DT_UINT addr, DT_UINT dat)
{
...
	if (BusoutMode == 0) {
		/* Customize File Path */
		dat_file = fopen("/workspace/log/ConvertData.DAT", "wb+");
		if (dat_file == NULL) {
			return;
		}
		//初期化処理内では時間値の取得を行わず
		SEM_INIT;
		BusOutModeSet(1);
	}

　　 /* time data の取得 */
　　 //CLOCK_MONOTONIC(OS単位で一意の時刻)で現在時刻を取得
	if (clock_gettime(CLOCK_MONOTONIC, &now) == -1) {					
		printf("DT : timer error!\n");
	}
...	
　　 /* time data */
　　 //時間値を絶対時間方式(下位4バイトを秒、上位4バイトをナノ秒単位)に
	buff[4] = (unsigned char)((now.tv_nsec) & 0xFF);
	buff[5] = (unsigned char)((now.tv_nsec >> 8) & 0xFF);
	buff[6] = (unsigned char)((now.tv_nsec >> 16) & 0xFF);
	buff[7] = (unsigned char)((now.tv_nsec >> 24) & 0xFF);
	buff[8] = (unsigned char)((now.tv_sec) & 0xFF);
	buff[9] = (unsigned char)((now.tv_sec >> 8) & 0xFF);
	buff[10] = (unsigned char)((now.tv_sec >> 16) & 0xFF);
	buff[11] = (unsigned char)((now.tv_sec >> 24) & 0xFF);
}

これは他の接続方式でも時間軸をターゲットで取る場合には同じように時間軸の精度の調整が必要になります。汎用ポート接続などを利用する場合は、Multi Tracer Unitのご利用なども併せて検討ください。

イベント情報(プロセス／スレッド)の取得

マルチプロセス／スレッドの情報を取得する場合は、イベント情報の設定を行う必要があります。例えばドライバ対応方式でファイル書き出し接続のDTドライバではプロセス／スレッド情報を以下の処理で取得しています。

void _TP_BusOut(DT_UINT addr, DT_UINT dat)
{
	unsigned char buff[16] = {0};
	struct timespec now;
	unsigned int time;

#if DT_ADD_EVENT_INFO
	pid = getpid();
#endif
...
#if DT_ADD_EVENT_INFO
	/* pid */
	buff[9] = (unsigned char)((pid) & 0xFF);
	buff[10] = (unsigned char)((pid >> 8) & 0xFF);
	buff[11] = (unsigned char)((pid >> 16) & 0xFF);
	buff[12] = (unsigned char)((pid >> 24) & 0xFF);
#else
...
}

標準のドライバではgetpid()でプロセス情報を取得しています。適応する範囲がプロセス単位で異なる場合は上記の実装でどちらか判別できます。

マルチスレッドの処理の場合は、プロセスは同一の値となるため、以下のようにドライバの修正が必要です。

/*==============================================================================*/
/*  Desc:   Header for File IO                                                  */
/*==============================================================================*/
#include <stdio.h>
#include <sys/types.h>
#include <time.h>
#include <sys/time.h>
#include <unistd.h>

//systemcallを使用するため追加
#include <sys/syscall.h>

void _TP_BusOut(DT_UINT addr, DT_UINT dat)
{
	unsigned char buff[16] = {0};
	struct timespec now;
	unsigned int time;

#if DT_ADD_EVENT_INFO
　　 //syscall(SYS_gettid)はスレッドID値を取得するシステムコール
　　 //戻り値はpid_t(最終的な定義はint型)の為、int型にキャスト
	pid = (int)syscall(SYS_gettid); 				
#endif
...
	/* pid */
	buff[12] = (unsigned char)((pid) & 0xFF);
	buff[13] = (unsigned char)((pid >> 8) & 0xFF);
	buff[14] = (unsigned char)((pid >> 16) & 0xFF);
	buff[15] = (unsigned char)((pid >> 24) & 0xFF);
...
}

システムコールを使って、スレッドID値を取得します。プロセス、スレッド両方の値を取得する場合は、カーネル情報出力の手段をご参照ください。

インポート設定の変更

データフォーマットの変更

ドライバのフォーマットを変更した場合は、DTプロジェクト側のインポート設定も変更する必要があります。

DTアプリケーションからファイルメニュー＞インポート＞「ファイル書き出しで取得したレポートデータ…」を選択し、テストレポートのインポートダイアログの左下の「データフォーマット…」から設定します。

今回は16Byteフォーマットで、以下の設定を変更しています。

addr：3→2 Byte

　・DTプロジェクト上で取り扱えるソースファイルの数の上限。通常3byteとなっている。

　・制限事項として登録可能なソースファイル数が4095までになります。

Time：4→8Byte

　・8Byteサイズで該当範囲のデータを時間値として取得する

時間データを絶対時間として扱う→有効

　・前提として8byte確保する必要があります。

　・チェックを有効にした場合、下位4バイトを秒、上位4バイトをナノ秒単位で扱います。

上記の設定はドライバの下記の箇所と対応させます。

void _TP_BusOut(DT_UINT addr, DT_UINT dat)
{
...
	buff[0] = (unsigned char)((dat) & 0xFF);
	buff[1] = (unsigned char)((dat >> 8) & 0xFF);
	//addrは2byteに変更
	buff[2] = (unsigned char)((addr) & 0xFF);					
	buff[3] = (unsigned char)((addr >> 8) & 0xFF);
	/* time data */
	//timeは8byteに変更
	//時間値を絶対時間方式(下位4バイトを秒、上位4バイトをナノ秒単位)に
	buff[4] = (unsigned char)((now.tv_nsec) & 0xFF);		
	buff[5] = (unsigned char)((now.tv_nsec >> 8) & 0xFF);
	buff[6] = (unsigned char)((now.tv_nsec >> 16) & 0xFF);
	buff[7] = (unsigned char)((now.tv_nsec >> 24) & 0xFF);
	buff[8] = (unsigned char)((now.tv_sec) & 0xFF);
	buff[9] = (unsigned char)((now.tv_sec >> 8) & 0xFF);
	buff[10] = (unsigned char)((now.tv_sec >> 16) & 0xFF);
	buff[11] = (unsigned char)((now.tv_sec >> 24) & 0xFF);

	/* pid */
	//Eventは4Byteに変更
	buff[12] = (unsigned char)((pid) & 0xFF);
	buff[13] = (unsigned char)((pid >> 8) & 0xFF);
	buff[14] = (unsigned char)((pid >> 16) & 0xFF);
	buff[15] = (unsigned char)((pid >> 24) & 0xFF);
...
}

解析すべき箇所の絞り込み

取得したレポートデータから解析対象の処理の検証・比較をしやすくするために、レポートデータをトリミングします。トリミングの切り口として以下の手段があります。

レポートデータから見たい範囲を特定する

実行時間／周期時間レポートの結果から探す

もっとも簡単な方法は関数単位の実行時間／周期時間の結果をそのまま利用する方式です。

テストレポートが表示される状態でレポート解析メニュー＞レポートデータの解析を選択するとテストレポートの解析が行われ、実行時間レポートや周期時間レポートが表示されます。

確認するシーケンスが関数単位、あるいはある関数の周期などの場合実行時間レポートや周期時間レポ―トの結果からテストレポートの該当箇所の確認が可能です。実行時間レポート上の該当関数をクリックすると実行時間詳細リストが表示されます。

詳細リストのNo.を基にトリミングを行います。

二点間実行時間レポートを使って探す

Start関数とEnd関数のような、複数の関数をまたぐシーケンスを確認する場合は二点間実行時間レポートを利用します。二点間実行時間を設定する場合、ソースコードやフォルダビュー等から右クリックし、二点間実行時間を選択します。

選択すると区間設定ダイアログが表示されますので、以下の入力を行います。

区間名：

　任意の名前を設定

始点／終点ステップ：

　どちらか空欄になっている方の設定ボタンを操作すると下記ダイアログが開く為、そこから任意のテストポイント選択しOKボタンを操作します。

上記設定後に再度レポート解析を行うと、テストレポートのタブ一覧の中に「二点間実行時間レポート」が表示されます。実行時間レポートと同様にダブルクリックで詳細リストが表示されますので、レポ―トNoやマーク機能等を使って範囲を記録します。

マーク機能で目星を記録する

テストレポートの「マーク」欄に入力する事でレポート内にコメントを登録する事ができます。

登録すると以下のように「マークビュー」ウィンドウが表示されます。

マークを活用する事で、下記のようにテストレポートのどこでどのように動いたかを記録し、下記のように分かりやすくまとめる事ができます。

マークビューの記録確認する事で該当テストレポートの読み取り結果を記録できます。解析を複数日にわたって行う場合や他のメンバーと結果を共有する際などに活動いただけます。

データのトリミングして解析対象を絞る

テストレポート内の特定区間をトリミングする事で、任意の区間を別のテストレポートとして保存する事ができます。トリミングはテストレポート上で右クリックする事で選択が可能です。

No.またはマーク機能を使って取り出す箇所を指定します。

テストレポートのNo.またはマークの結果などでトリミングを行います。

トリミングしたテストレポートを基に、内容の確認を行います。

データの解析

トリミングし、見たい箇所をトリミングしたレポートデータを別途解析する事で様々な情報を確認する事ができます。

例えば、実行時間(占有時間)で解析する事で1回の処理に対しての処理の負荷が確認可能です。

上記のように分割して解析する事で、負荷の高い処理の内訳が、

　①1回の処理単位が大きい処理

　②1回は短いが複数回呼ばれることで負荷になっている処理

といった傾向の詳細分析が可能です。

ここからは処理の具体的な内容によって対応が異なる為、あくまで一例となりますが

①1回の処理単位が大きい処理の場合

　・ステップ単位でテストレポートを確認し、差分時間の大きいステップを特定。

　　・参照するタイミングや参照の仕方は適切か、別にずらせないか？

　　・大きいステップの処理内で使われているAPIやアルゴリズムの改善で負荷を抑えることはできないか？

　・別スレッド化や割り込み禁止などで処理の改善が可能か？

②1回は短いが複数回呼ばれることで負荷になっている処理

　・参照する回数は適切か、参照の仕方や参照する回数を減らすことはできないか？

　・参照先の関数自体の負荷の改善は可能か？

といった形で改善案を出し、再度DT+Traceで確認する事で改善案の結果を再度計測する事で有効かどうか検証ができます。

また、関数遷移スコープなどで比較する事でプロセス／スレッドなども含めた経路の違いを可視化できます。

上記の例では処理間で割り込むプロセスの違いによって処理時間が大きく変化していることがわかります。このように関数遷移スコープレベルで比較を行う事で、プロセス／スレッド単位の全体的な動作の違いを直感的に判断する事が可能になります。

上記の例でいえば大きな処理単位の間で割り込む別のプロセスによって処理時間が大幅に変化していますので、プロセスの優先度を変更する事で改善できないか、割り込み禁止を設定するなどして改善できないか、割り込んできているプロセス自体の処理時間の違いを調査して改善できないか？といった案が検討できます。

このページの情報はお役に立ちましたか？

はい (0)
いいえ (0)
探している内容ではない (0)

製品サポートサイト

製品

カテゴリー

タグ