投稿日：
2019年5月9日
最終更新日：
【SpringBoot2】リクエストの処理時間をログに出力する方法【AbstractRequestLoggingFilter】
YouTubeも見てね♪
ねこじゃすり
猫を魅了する魔法の装備品！
Anker PowerCor
旅行には必須の大容量モバイルバッテリー！
【最新機種】GoPro hero11 Black
created by Rinker
¥61,300
(2025/01/05 20:59:47時点 楽天市場調べ-詳細)
最新機種でVlogの思い出を撮影しよう！
ペヤング ソースやきそば 120g×18個
とりあえず保存食として買っておけば間違いなし！
レッドブル エナジードリンク 250ml×24本
翼を授けよう！
モンスターエナジー 355ml×24本 [エナジードリンク]
脳を活性化させるにはこれ！
Bauhutte ( バウヒュッテ ) 昇降式 L字デスク ブラック BHD-670H-BK
メインデスクの横に置くのにぴったりなおしゃれな可動式ラック！
リクエストの所要時間をログに出そう
前回、SpringBoot2のCommonsRequestLoggingFilterと言う既存Filterを用いたリクエスト情報のログ出力についてご紹介しました。
今回は、さらにもう一手間加え、リクエスト処理を完了するまでの時間をログに追加する方法をご紹介致します。
手順
AbstractRequestLoggingFilterの継承クラスを実装
まずは、AbstractRequestLoggingFilterを継承したクラスを用意しましょう。
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
|
package tech.blogenist.service.account.api.infrastructure.filter.millisec;
import javax.servlet.http.HttpServletRequest;
import org.springframework.web.filter.AbstractRequestLoggingFilter;
import lombok.extern.slf4j.Slf4j;
@Slf4j
public class RequestMilliSecFilter extends AbstractRequestLoggingFilter
{
private final String BEFORE_REQUEST_MILLI_SEC_KEY = this.getClass().getName();
@Override
protected boolean shouldLog( HttpServletRequest request )
{
return log.isDebugEnabled();
}
@Override
protected void beforeRequest( HttpServletRequest request, String message )
{
log.debug( message );
request.setAttribute( BEFORE_REQUEST_MILLI_SEC_KEY, System.currentTimeMillis() );
}
@Override
protected void afterRequest( HttpServletRequest request, String message )
{
Object beforeMilliTime = request.getAttribute( BEFORE_REQUEST_MILLI_SEC_KEY );
if( beforeMilliTime instanceof Long )
{
long startMilliTime = ( long ) beforeMilliTime;
long elapsedMilliTime = System.currentTimeMillis() - startMilliTime;
log.debug( "latency {} ms {}", elapsedMilliTime, message );
}else
{
log.debug( message );
}
}
}
|
Beanの追加
次に、前回利用した@Configurationがついたクラスを修正します。
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
|
package tech.blogenist.service.account.api.infrastructure.filter.config;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import tech.blogenist.service.account.api.infrastructure.filter.millisec.RequestMilliSecFilter;
import tech.blogenist.service.account.api.infrastructure.filter.x_request_id.MdcXRequestIdFilter;
import tech.blogenist.service.account.api.infrastructure.filter.x_request_id.ResponseHeaderAddXRequestIdFilter;
@Configuration
public class FilterConfig
{
@Bean
public MdcXRequestIdFilter mdcXRequestIdFilter()
{
MdcXRequestIdFilter filter = new MdcXRequestIdFilter();
return filter;
}
@Bean
public ResponseHeaderAddXRequestIdFilter responseHeaderAddXRequestIdFilter()
{
ResponseHeaderAddXRequestIdFilter filter = new ResponseHeaderAddXRequestIdFilter();
return filter;
}
@Bean
public RequestMilliSecFilter requestMilliSecFilter()
{
RequestMilliSecFilter filter = new RequestMilliSecFilter(); // CommonsRequestLoggingFilterから変更
filter.setIncludeClientInfo( true );
filter.setIncludeQueryString( true );
filter.setIncludeHeaders( true );
filter.setIncludePayload( true );
return filter;
}
}
|
これで準備は完了です。
確認
では、実際にリクエストを投げて確認してみましょう。
|
1
2
3
4
5
6
7
8
9
10
|
{
"timestamp":"2019-05-09T11:42:39.780+09:00",
"level":"DEBUG",
"thread":"http-nio-8080-exec-1",
"mdc":{
"x-request-id":"b9edaaf7-036e-4a59-84fb-f23d35ad98fc"
},
"logger":"tech.blogenist.service.account.api.infrastructure.filter.millisec.RequestMilliSecFilter",
"message":"latency 56 ms After request [uri=/v1/accounts/10001/;client=0:0:0:0:0:0:0:1;headers=[host:\"localhost:8080\", connection:\"keep-alive\", user-agent:\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.131 Safari/537.36\", header:\"fuga\", cache-control:\"no-cache\", postman-token:\"4b63ac31-571e-9fc4-c81b-eaaf2ce64ade\", accept:\"*/*\", accept-encoding:\"gzip, deflate, br\", accept-language:\"ja,en-US;q=0.9,en;q=0.8\", Content-Type:\"application/json;charset=UTF-8\"]]"
}
|
正常にlatencyにミリ秒が出力されるようになりましたね♪
終わりに
以上のように、用意されているクラスをカスタマイズするだけで、簡単に経過時間をログに出す事が出来ました。
パフォーマンス改善やチューニング作業などにはこの情報はとても重要になる為、出力するようにしておくと幸せになれると思いますので、是非やってみてください。♪