如何優雅打印接口調用時長

這篇文章主要介紹“如何優雅打印接口調用時長 ”，在日常操作中，相信很多人在如何優雅打印接口調用時長 問題上存在疑惑，小編查閱了各式資料，整理出簡單好用的操作方法，希望對大家解答”如何優雅打印接口調用時長 ”的疑惑有所幫助！接下來，請跟著小編一起來學習吧！

引言

優雅的API設計不僅僅是代碼層面的書寫規范.幾乎不可能API開發完畢就能正常投入使用,更多的是對細節的打磨.例如接口的每次執行時間,入參都會在API測試中反復的推敲

思考

如何設計一個方案使開發者能一目了然的可視化接口的處理時間以及入參是否正確呢?

思路

首先想到的是Spring的AOP切面,現在我們編寫API接口,一般都會把接口寫在controller控制層里,按照不同的業務,分為寫在不同業務包下的controller類中.大致的架構如下: 按照這種控制層的編寫規范,只需要用切面找到每個業務包下的controller類,監控類下面的每個方法的入參和執行時間,打印在log日志中便可以在控制臺中可視化每個接口的實時狀態了.

實踐

導包

<dependency>
    <!--spring啟動包-->
    <groupid>org.springframework.boot</groupid>
    <artifactid>spring-boot-starter-web</artifactid>
</dependency>
<dependency>
     <!--spring aop核心包-->
    <groupid>org.springframework.boot</groupid>
    <artifactid>spring-boot-starter-aop</artifactid>
</dependency>

AOP核心

aop的核心在于切點和通知類型.結合我們所需要實現的方案,我們所關注的切點就是每個業務下控制層包的每個類方法. 通知的主要類型分為:

• 前置通知[Before advice]：在連接點前面執行，前置通知不會影響連接點的執行，除非此處拋出異常。

• 正常返回通知[After returning advice]：在連接點正常執行完成后執行，如果連接點拋出異常，則不會執行。

• 異常返回通知[After throwing advice]：在連接點拋出異常后執行。

• 返回通知[After (finally) advice]：在連接點執行完成后執行，不管是正常執行完成，還是拋出異常，都會執行返回通知中的內容。

• 環繞通知[Around advice]：環繞通知圍繞在連接點前后，比如一個方法調用的前后。這是最強大的通知類型，能在方法調用前后自定義一些操作。環繞通知還需要負責決定是繼續處理join point(調用ProceedingJoinPoint的proceed方法)還是中斷執行。

這里因為我們需要記錄入參和接口處理時間,選用Before 前置通知和Around 環繞通知

定義切點

切面第一步,我們需要找準切點 新建RuntimeMethod類,用@Aspect @Component修飾定義這是由spring管理的切面入口類,@Log4j2 注釋方便后續打印日志

@Aspect
@Component
@Log4j2
public class RuntimeMethod {
    //定義aopPoint私有方法,用@Pointcut修飾并標識該切面的切點
    //以execution(* com.staging.business.*.controller.*.*(..))為例
    //execution()是切面的主體
    //第一個" * "符號,表示返回值的類型任意
    //com.staging.business表示AOP所切的服務的包名,即需要進行橫切的業務類
    //包名后面的" .. ",表示當前包及子包
    //之后的" * ",表示類名，*即所有類
    // .*(..) 表示任何方法名,括號內表示參數,兩個點表示匹配任何參數類型
    @Pointcut("execution(* com.staging.business.*.controller.*.*(..))")
    private void aopPoint() {
    } 
}

切面第二步,定義前置和環繞通知,并聲明通知的切點為aopPoint()

    /**
     * 功能描述: 前置通知
     */
    @Before("aopPoint()")
    public void before(JoinPoint joinPoint) throws Throwable {
        //在調用切面管理的接口前會進入這里
    }

    /**
     * 功能描述: 環繞通知
     */
    @Around("aopPoint()")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {  
        //在before通知后會走入這里,直到返回result對象后,客戶端才可以拿到回參
        Object result = joinPoint.proceed();
        return result;
    }

前面兩步實現了兩個需要用到的通知并簡要說明了他的作用.接下來還需要使用到spring包中的ServletRequestAttributes對象用于獲取HttpServletRequest對象,獲取到我們想要的一些打印參數.

    public void before(JoinPoint joinPoint) throws Throwable {
        //在調用切面管理的接口前會進入這里
        ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        HttpServletRequest request = requestAttributes.getRequest();
        Enumeration<string> e = request.getHeaderNames();
        JSONObject headers = new JSONObject();
        if (null != e) {
            while (e.hasMoreElements()) {
                String headerName = e.nextElement();
                Enumeration<string> headerValues = request.getHeaders(headerName);
                while (headerValues.hasMoreElements()) {
                    headers.put(headerName, headerValues.nextElement());
                }
            }
        }
        //參數依次代表請求方法,請求地址,參數,頭參數,調用時間
        log.info("-in- {} {} -{}{}",request.getMethod(),request.getRequestURI(),joinPoint.getArgs(),headers.toJSONString()}
    }

接口調用時間也能很輕松的在環繞通知中打印

    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {  
        long begin=System.currentTimeMillis();
        //在before通知后會走入這里,直到返回result對象后,客戶端才可以拿到回參
        Object result = joinPoint.proceed();
        long end= System.currentTimeMillis();
        log.info("-out -time:{}ms", end - begin}
        return result;
    }

運行起來,調用API接口,我們都會輸出以下日志

    -in- GET /user/info -id=123  header:{"content-length":"0",......}
    -out- -time:91ms
    ......

測試完全沒有問題,當然這不是最終版本,嘗試放在測試環境,調用的人多起來,就會非常混亂,類似下面的畫風

    -in- GET /user/info -id=123  header:{"content-length":"0",......}
    -in- GET /teacher/info -id=123  header:{"content-length":"0",......}
    -out- -time:91ms
    -in- GET /user/info -id=321  header:{"content-length":"0",......}
    -out- -time:191ms
    ......

可以看到問題出現在并發操作上,在同一時間調用多個接口時,日志會亂掉,這可不是我想要的結果.必須想辦法解決這個問題.翻閱資料,想到用ThreadLocal線程局部變量以及Tuple元組對象解決這個問題.接下來改造代碼. 在RuntimeMethod類中定義一個私有變量ThreadLocal.

    private ThreadLocal<tuple6<string, string, object[], long, string>&gt; threadLocal = new ThreadLocal&lt;&gt;();

再改造通知部分

    @Before("aopPoint()")
    public void before(JoinPoint joinPoint) throws Throwable {
        //打印請求體
        ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        if (null != requestAttributes) {
            //在loadingThreadLocal用ThreadLocal和Tuple對象存儲參數.這樣就可以方便的取出接口的必要參數
            loadingThreadLocal(requestAttributes, joinPoint.getArgs());
                log.info("-in- {} {} -{}",
                        threadLocal.get().getT1(),
                        threadLocal.get().getT2(),
                        threadLocal.get().getT6());
                log.info("Method arguments:{} -{}",
                        threadLocal.get().getT3(),
                        threadLocal.get().getT6());
                log.info("Request header:{} -{}",
                        threadLocal.get().getT4(),
                        threadLocal.get().getT6());
        }
    }
    
    @Around("aopPoint()")
    public Object around(ProceedingJoinPoint joinPoint) throws Throwable {
         // 調用目標方法
        Object result = joinPoint.proceed();
        String requestUrl = threadLocal.get().getT2();
        // 注意在out的時候,取出調用的接口名稱,這樣可以用接口名稱去方便過濾,就不用害怕日志錯亂的問題了.return回參在生產環境中盡量不要加進去,因為是測試階段排查問題打的日志所以越詳細越好.
        log.info("-out- {} return:{} -time:{}ms -{}", requestUrl, JSONObject.toJSONString(result), System.currentTimeMillis() - threadLocal.get().getT5(), threadLocal.get().getT6());
        //接口出參處理
        return delReturnData(result);
    }
    
    private void loadingThreadLocal(ServletRequestAttributes requestAttributes, Object[] args) {
        HttpServletRequest request = requestAttributes.getRequest();
        Enumeration<string> e = request.getHeaderNames();
        JSONObject headers = new JSONObject();
        if (null != e) {
            while (e.hasMoreElements()) {
                String headerName = e.nextElement();
                Enumeration<string> headerValues = request.getHeaders(headerName);
                while (headerValues.hasMoreElements()) {
                    headers.put(headerName, headerValues.nextElement());
                }
            }
        }
        //此處追加了一個調用鏈的id,可返回客戶端,讓客戶端在下一次請求中帶入這個id,方法統計一個業務閉環.
        String businessId = IdUtil.getSnowflake(1, 1).nextIdStr();
        //請求方法,請求地址,參數,頭參數,調用時間,調用鏈id
        threadLocal.set(Tuples.of(request.getMethod(), request.getRequestURI(), args, headers.toJSONString(), System.currentTimeMillis(), businessId));
    }

再看看使用此方案后的接口調用日志

2021-01-11 20:16:39.565 [http-nio-8080-exec-7] INFO  cn.mc.apd[86] - -in- GET /activityArea/getUserPrize -1348604735921459200
2021-01-11 20:16:39.565 [http-nio-8080-exec-7] INFO  cn.mc.appod[90] - Method arguments:[1] -1348604735921459200
2021-01-11 20:16:39.566 [http-nio-8080-exec-7] INFO  cn.mc.app.tood[93] - Request header:{"content-length":"0","idfa":"00000",x-nondec-sign":"d93207ba","host":"80""} -1348604735921459200
2021-01-11 20:16:39.593 [http-nio-8080-exec-7] INFO  cn.mc.app.tools.interceptor.RuntimeMethod[126] - -out- /activityArea/getUserPrize return:{"code":0,"data":{"userActivePrizeRec":"0","message":"成功"} -time:28ms

到此，關于“如何優雅打印接口調用時長 ”的學習就結束了，希望能夠解決大家的疑惑。理論與實踐的搭配能更好的幫助大家學習，快去試試吧！若想繼續學習更多相關知識，請繼續關注億速云網站，小編會繼續努力為大家帶來更多實用的文章！