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

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

YouTubeも見てね♪

ねこじゃすり

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

created by Rinker

PEPPY(ペピイ)

¥3,850 (2025/01/05 12:56:12時点 Amazon調べ-詳細)

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

Anker PowerCor

Anker PowerCore モバイルバッテリー 20000mAh iPhone iPad Android

created by Rinker

Anker

¥3,990 (2025/01/05 12:09:11時点 Amazon調べ-詳細)

旅行には必須の大容量モバイルバッテリー！

【最新機種】GoPro hero11 Black

【最新機種】GoPro HERO13 Black【完全防水】

created by Rinker

¥61,300 (2025/01/05 20:59:47時点楽天市場調べ-詳細)

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

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

created by Rinker

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

¥33,000 (2025/01/05 13:22:08時点 Amazon調べ-詳細)

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

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

created by Rinker

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

¥10,429 (2025/01/05 12:09:13時点 Amazon調べ-詳細)

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

MOFT X 【新型ミニマム版】 iPhone対応スマホスタンド

created by Rinker

MOFT

Amazon一番人気のスマホスタンド！カード類も収納出来てかさ張らないのでオススメです！

サンディスク microSD 128GB

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

created by Rinker

SanDisk

¥3,279 (2025/01/05 12:33:41時点 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にミリ秒が出力されるようになりましたね♪