投稿日： 2019年5月9日
最終更新日： 2023年3月28日

【SpringBoot2】リクエストの処理時間をログに出力する方法【AbstractRequestLoggingFilter】

YouTubeも見てね♪

ねこじゃすり

ワタオカねこじゃすりライトグレー

created by Rinker

PEPPY(ペピイ)

¥3,850 (2024/04/03 21:33:13時点 Amazon調べ-詳細)

猫を魅了する魔法の装備品！

【最新機種】GoPro hero11 Black

【日本国内正規品】 GoPro hero11 Black

created by Rinker

GoPro(ゴープロ)

¥62,000 (2024/04/03 21:42:08時点 Amazon調べ-詳細)

最新機種でVlogの思い出を撮影しよう！

[ノースフェイス] THE NORTH FACE メンズアウターマウンテンライトジャケット

created by Rinker

THE NORTH FACE(ザノースフェイス)

¥33,430 (2024/04/03 21:42:09時点 Amazon調べ-詳細)

防水暴風で耐久性抜群なので旅行で大活躍です！

ペヤングソースやきそば 120g×18個

created by Rinker

ペヤング

¥2,600 (2024/04/03 21:42:16時点 Amazon調べ-詳細)

とりあえず保存食として買っておけば間違いなし！

Bauhutte ( バウヒュッテ ) 昇降式 L字デスクブラック BHD-670H-BK

created by Rinker

Bauhutte(バウヒュッテ)

¥14,935 (2024/04/03 21:42:10時点 Amazon調べ-詳細)

メインデスクの横に置くのにぴったりなおしゃれな可動式ラック！

BANDAI SPIRITS ULTIMAGEAR 遊戯王千年パズル 1/1スケール

created by Rinker

BANDAI SPIRITS(バンダイスピリッツ)

¥7,500 (2024/04/03 21:42:14時点 Amazon調べ-詳細)

もう一人の僕を呼び覚ませ！！

サンディスク microSD 128GB

サンディスク microSD 128GB UHS-I Class10 Nintendo Switch SanDisk Ultra SDSQUA4-128G-EPK

created by Rinker

SanDisk

¥1,856 (2024/04/03 21:33:16時点 Amazon調べ-詳細)

スマホからSwitchまで使える大容量MicroSDカード！

1 リクエストの所要時間をログに出そう
2 手順
3 終わりに

リクエストの所要時間をログに出そう

前回、SpringBoot2のCommonsRequestLoggingFilterと言う既存Filterを用いたリクエスト情報のログ出力についてご紹介しました。

参考

【RequestBody/RequestHeader】SpringBoot2でリクエスト情報をログに出力する方法【CommonsRequestLoggingFilter】

今回は、さらにもう一手間加え、リクエスト処理を完了するまでの時間をログに追加する方法をご紹介致します。

手順

AbstractRequestLoggingFilterの継承クラスを実装

まずは、AbstractRequestLoggingFilterを継承したクラスを用意しましょう。

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 );
        }
    }
}

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がついたクラスを修正します。

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;
    }
}

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;

}

これで準備は完了です。

確認

では、実際にリクエストを投げて確認してみましょう。

{  
   "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\"]]"
}

{

"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にミリ秒が出力されるようになりましたね♪