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

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

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

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

手順

AbstractRequestLoggingFilterの継承クラスを実装

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

RequestMilliSecFilter

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

FilterConfig

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

正常にlatencyにミリ秒が出力されるようになりましたね♪

終わりに

以上のように、用意されているクラスをカスタマイズするだけで、簡単に経過時間をログに出す事が出来ました。

パフォーマンス改善やチューニング作業などにはこの情報はとても重要になる為、出力するようにしておくと幸せになれると思いますので、是非やってみてください。♪