パフォーマンスログの出力¶

パフォーマンスログの出力方針
使用方法

パフォーマンスログは、任意の処理範囲に対する実行時間とメモリ使用量を出力し、開発時のパフォーマンスチューニングに使用する。アプリケーションでは、ソースコード上でフレームワークが提供するAPIを呼び出し、計測対象の処理範囲を指定して出力する。

パフォーマンスログの出力方針 ¶

パフォーマンスログは、ヒープサイズの取得などでパフォーマンスに影響を与える可能性がある。そのため、開発時の使用を想定しているためDEBUGレベルで出力する。

パフォーマンスログの出力方針¶
ログレベル	ロガー名
DEBUG	PERFORMANCE

上記出力方針に対するログ出力の設定例を下記に示す。

log.propertiesの設定例

writerNames=appLog

# アプリケーションログの出力先
writer.appLog.className=nablarch.core.log.basic.FileLogWriter
writer.appLog.filePath=/var/log/app/app.log
writer.appLog.encoding=UTF-8
writer.appLog.maxFileSize=10000
writer.appLog.formatter.className=nablarch.core.log.basic.BasicLogFormatter
writer.appLog.formatter.format=$date$ -$logLevel$- $runtimeLoggerName$ [$executionId$] boot_proc = [$bootProcess$] proc_sys = [$processingSystem$] req_id = [$requestId$] usr_id = [$userId$] $message$$information$$stackTrace$

availableLoggersNamesOrder=PER,ROO

# アプリケーションログの設定
loggers.ROO.nameRegex=.*
loggers.ROO.level=INFO
loggers.ROO.writerNames=appLog

# パフォーマンスログの設定
loggers.PER.nameRegex=PERFORMANCE
loggers.PER.level=DEBUG
loggers.PER.writerNames=appLog

app-log.propertiesの設定例

# PerformanceLogFormatter
#performanceLogFormatter.className=
#performanceLogFormatter.targetPoints=
#performanceLogFormatter.datePattern=
performanceLogFormatter.format=\n\tpoint = [$point$] result = [$result$]\
                               \n\tstart_time = [$startTime$] end_time = [$endTime$]\
                               \n\texecution_time = [$executionTime$]\
                               \n\tmax_memory = [$maxMemory$]\
                               \n\tstart_free_memory = [$startFreeMemory$] start_used_memory = [$startUsedMemory$]\
                               \n\tend_free_memory = [$endFreeMemory$] end_used_memory = [$endUsedMemory$]

使用方法 ¶

パフォーマンスログを出力する ¶

パフォーマンスログは、 PerformanceLogUtil を使用して出力する。 PerformanceLogUtil は、処理の開始時に呼び出す PerformanceLogUtil#start と終了時に呼び出す PerformanceLogUtil#end を提供する。 PerformanceLogUtil は、 PerformanceLogUtil#end が呼ばれた時点で、 PerformanceLogUtil#start で取得した日時とメモリ使用量を合わせて出力する。

PerformanceLogUtil の使用例を下記に示す。

// startメソッドでは、測定対象を識別するポイントを指定する。
// 誤設定による無駄な出力を防ぐため、
// このポイント名が設定ファイルに定義されていないとログは出力されない。
String point = "UserSearchAction#doUSERS00101";
PerformanceLogUtil.start(point);

// 検索実行
UserSearchService searchService = new UserSearchService();
SqlResultSet searchResult = searchService.selectByCondition(condition);

// endメソッドでは、ポイント、処理結果を表す文字列、ログ出力のオプション情報を指定できる。
// 以下ではログ出力のオプション情報は指定していない。
PerformanceLogUtil.end(point, String.valueOf(searchResult.size()));

重要

PerformanceLogUtil は、測定対象を実行時ID ＋ポイント名で一意に識別している。このため、再帰呼び出しの中で PerformanceLogUtil を使用すると計測を実施出来ないため注意すること。

パフォーマンスログの設定 ¶

パフォーマンスログの設定は、各種ログの設定で説明したプロパティファイルに行う。

記述ルール

performanceLogFormatter.className

PerformanceLogFormatter を実装したクラス。差し替える場合に指定する。

performanceLogFormatter.format

パフォーマンスログの個別項目のフォーマット。

フォーマットに指定可能なプレースホルダ

処理の実行時間(終了日時 - 開始日時):
測定対象を識別するID:	$point$
処理結果を表す文字列:	$result$
処理の開始日時:	$startTime$
処理の終了日時:	$endTime$
	$executionTime$
処理の開始時点のヒープサイズ:	$maxMemory$
処理の開始時点の空きヒープサイズ:
	$startFreeMemory$
処理の開始時点の使用ヒープサイズ:
	$startUsedMemory$
処理の終了時点の空きヒープサイズ:
	$endFreeMemory$
処理の終了時点の使用ヒープサイズ:
	$endUsedMemory$

デフォルトのフォーマット

\n\tpoint = [$point$] result = [$result$]
\n\tstart_time = [$startTime$] end_time = [$endTime$]
\n\texecution_time = [$executionTime$]
\n\tmax_memory = [$maxMemory$]
\n\tstart_free_memory = [$startFreeMemory$] start_used_memory = [$startUsedMemory$]
\n\tend_free_memory = [$endFreeMemory$] end_used_memory = [$endUsedMemory$]

performanceLogFormatter.datePattern

開始日時と終了日時に使用する日時パターン。パターンには、 SimpleDateFormat が規程している構文を指定する。デフォルトは”yyyy-MM-dd HH:mm:ss.SSS”。

performanceLogFormatter.targetPoints

出力対象とするポイント名。複数指定する場合はカンマ区切り。パフォーマンスログは、誤設定による無駄な出力を防ぐため、この設定に基づき出力する。

記述例

performanceLogFormatter.className=nablarch.core.log.app.PerformanceLogFormatter
performanceLogFormatter.targetPoints=UserSearchAction#doUSERS00101
performanceLogFormatter.datePattern=yyyy-MM-dd HH:mm:ss.SSS
performanceLogFormatter.format=point:$point$ result:$result$ exe_time:$executionTime$ms

JSON形式の構造化ログとして出力する ¶

JSON形式の構造化ログとして出力する設定によりログをJSON形式で出力できるが、 PerformanceLogFormatter ではパフォーマンスログの各項目はmessageの値に文字列として出力される。パフォーマンスログの各項目もJSONの値として出力するには、 PerformanceJsonLogFormatter を使用する。設定は、各種ログの設定で説明したプロパティファイルに行う。

記述ルール

PerformanceJsonLogFormatter を用いる際に指定するプロパティは以下の通り。

performanceLogFormatter.className 必須

JSON形式でログを出力する場合、 PerformanceJsonLogFormatter を指定する。

performanceLogFormatter.targets

パフォーマンスログの出力項目。カンマ区切りで指定する。

指定可能な出力項目

処理の実行時間(終了日時 - 開始日時):
測定対象を識別するID:	point
処理結果を表す文字列:	result
処理の開始日時:	startTime
処理の終了日時:	endTime
	executionTime
処理の開始時点のヒープサイズ:	maxMemory
処理の開始時点の空きヒープサイズ:
	startFreeMemory
処理の開始時点の使用ヒープサイズ:
	startUsedMemory
処理の終了時点の空きヒープサイズ:
	endFreeMemory
処理の終了時点の使用ヒープサイズ:
	endUsedMemory

デフォルトは全ての出力項目が対象となる。

performanceLogFormatter.datePattern

開始日時と終了日時に使用する日時パターン。パターンには、 SimpleDateFormat が規程している構文を指定する。デフォルトは”yyyy-MM-dd HH:mm:ss.SSS”。

performanceLogFormatter.targetPoints

出力対象とするポイント名。複数指定する場合はカンマ区切り。パフォーマンスログは、誤設定による無駄な出力を防ぐため、この設定に基づき出力する。

performanceLogFormatter.structuredMessagePrefix

フォーマット後のメッセージ文字列が JSON 形式に整形されていることを識別できるようにするために、メッセージの先頭に付与するマーカー文字列。メッセージの先頭にあるマーカー文字列が JsonLogFormatter に設定しているマーカー文字列と一致する場合、 JsonLogFormatter はメッセージを JSON データとして処理する。デフォルトは "$JSON$" となる。変更する場合は、LogWriterの structuredMessagePrefix プロパティを使用して JsonLogFormatter にも同じ値を設定すること（LogWriterのプロパティについてはログ出力の設定を参照）。

記述例

performanceLogFormatter.className=nablarch.core.log.app.PerformanceJsonLogFormatter
performanceLogFormatter.structuredMessagePrefix=$JSON$
performanceLogFormatter.targetPoints=UserSearchAction#doUSERS00101
performanceLogFormatter.datePattern=yyyy-MM-dd'T'HH:mm:ss.SSS'Z'
performanceLogFormatter.targets=point,result,executionTime

パフォーマンスログの出力¶