如何優(yōu)雅打印接口調(diào)用時(shí)長(zhǎng)

這篇文章主要介紹“如何優(yōu)雅打印接口調(diào)用時(shí)長(zhǎng) ”，在日常操作中，相信很多人在如何優(yōu)雅打印接口調(diào)用時(shí)長(zhǎng) 問(wèn)題上存在疑惑，小編查閱了各式資料，整理出簡(jiǎn)單好用的操作方法，希望對(duì)大家解答”如何優(yōu)雅打印接口調(diào)用時(shí)長(zhǎng) ”的疑惑有所幫助！接下來(lái)，請(qǐng)跟著小編一起來(lái)學(xué)習(xí)吧！

引言

優(yōu)雅的API設(shè)計(jì)不僅僅是代碼層面的書(shū)寫(xiě)規(guī)范.幾乎不可能API開(kāi)發(fā)完畢就能正常投入使用,更多的是對(duì)細(xì)節(jié)的打磨.例如接口的每次執(zhí)行時(shí)間,入?yún)⒍紩?huì)在API測(cè)試中反復(fù)的推敲

思考

如何設(shè)計(jì)一個(gè)方案使開(kāi)發(fā)者能一目了然的可視化接口的處理時(shí)間以及入?yún)⑹欠裾_呢?

思路

首先想到的是Spring的AOP切面,現(xiàn)在我們編寫(xiě)API接口,一般都會(huì)把接口寫(xiě)在controller控制層里,按照不同的業(yè)務(wù),分為寫(xiě)在不同業(yè)務(wù)包下的controller類中.大致的架構(gòu)如下: 按照這種控制層的編寫(xiě)規(guī)范,只需要用切面找到每個(gè)業(yè)務(wù)包下的controller類,監(jiān)控類下面的每個(gè)方法的入?yún)⒑蛨?zhí)行時(shí)間,打印在log日志中便可以在控制臺(tái)中可視化每個(gè)接口的實(shí)時(shí)狀態(tài)了.

實(shí)踐

導(dǎo)包

<dependency>
    <!--spring啟動(dòng)包-->
    <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的核心在于切點(diǎn)和通知類型.結(jié)合我們所需要實(shí)現(xiàn)的方案,我們所關(guān)注的切點(diǎn)就是每個(gè)業(yè)務(wù)下控制層包的每個(gè)類方法. 通知的主要類型分為:

• 前置通知[Before advice]：在連接點(diǎn)前面執(zhí)行，前置通知不會(huì)影響連接點(diǎn)的執(zhí)行，除非此處拋出異常。

• 正常返回通知[After returning advice]：在連接點(diǎn)正常執(zhí)行完成后執(zhí)行，如果連接點(diǎn)拋出異常，則不會(huì)執(zhí)行。

• 異常返回通知[After throwing advice]：在連接點(diǎn)拋出異常后執(zhí)行。

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

• 環(huán)繞通知[Around advice]：環(huán)繞通知圍繞在連接點(diǎn)前后，比如一個(gè)方法調(diào)用的前后。這是最強(qiáng)大的通知類型，能在方法調(diào)用前后自定義一些操作。環(huán)繞通知還需要負(fù)責(zé)決定是繼續(xù)處理join point(調(diào)用ProceedingJoinPoint的proceed方法)還是中斷執(zhí)行。

這里因?yàn)槲覀冃枰涗浫雲(yún)⒑徒涌谔幚頃r(shí)間,選用Before 前置通知和Around 環(huán)繞通知

定義切點(diǎn)

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

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

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

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

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

前面兩步實(shí)現(xiàn)了兩個(gè)需要用到的通知并簡(jiǎn)要說(shuō)明了他的作用.接下來(lái)還需要使用到spring包中的ServletRequestAttributes對(duì)象用于獲取HttpServletRequest對(duì)象,獲取到我們想要的一些打印參數(shù).

    public void before(JoinPoint joinPoint) throws Throwable {
        //在調(diào)用切面管理的接口前會(huì)進(jìn)入這里
        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());
                }
            }
        }
        //參數(shù)依次代表請(qǐng)求方法,請(qǐng)求地址,參數(shù),頭參數(shù),調(diào)用時(shí)間
        log.info("-in- {} {} -{}{}",request.getMethod(),request.getRequestURI(),joinPoint.getArgs(),headers.toJSONString()}
    }

接口調(diào)用時(shí)間也能很輕松的在環(huán)繞通知中打印

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

運(yùn)行起來(lái),調(diào)用API接口,我們都會(huì)輸出以下日志

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

測(cè)試完全沒(méi)有問(wèn)題,當(dāng)然這不是最終版本,嘗試放在測(cè)試環(huán)境,調(diào)用的人多起來(lái),就會(huì)非?；靵y,類似下面的畫(huà)風(fēng)

    -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
    ......

可以看到問(wèn)題出現(xiàn)在并發(fā)操作上,在同一時(shí)間調(diào)用多個(gè)接口時(shí),日志會(huì)亂掉,這可不是我想要的結(jié)果.必須想辦法解決這個(gè)問(wèn)題.翻閱資料,想到用ThreadLocal線程局部變量以及Tuple元組對(duì)象解決這個(gè)問(wèn)題.接下來(lái)改造代碼. 在RuntimeMethod類中定義一個(gè)私有變量ThreadLocal.

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

再改造通知部分

    @Before("aopPoint()")
    public void before(JoinPoint joinPoint) throws Throwable {
        //打印請(qǐng)求體
        ServletRequestAttributes requestAttributes = (ServletRequestAttributes) RequestContextHolder.getRequestAttributes();
        if (null != requestAttributes) {
            //在loadingThreadLocal用ThreadLocal和Tuple對(duì)象存儲(chǔ)參數(shù).這樣就可以方便的取出接口的必要參數(shù)
            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 {
         // 調(diào)用目標(biāo)方法
        Object result = joinPoint.proceed();
        String requestUrl = threadLocal.get().getT2();
        // 注意在out的時(shí)候,取出調(diào)用的接口名稱,這樣可以用接口名稱去方便過(guò)濾,就不用害怕日志錯(cuò)亂的問(wèn)題了.return回參在生產(chǎn)環(huán)境中盡量不要加進(jìn)去,因?yàn)槭菧y(cè)試階段排查問(wèn)題打的日志所以越詳細(xì)越好.
        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());
                }
            }
        }
        //此處追加了一個(gè)調(diào)用鏈的id,可返回客戶端,讓客戶端在下一次請(qǐng)求中帶入這個(gè)id,方法統(tǒng)計(jì)一個(gè)業(yè)務(wù)閉環(huán).
        String businessId = IdUtil.getSnowflake(1, 1).nextIdStr();
        //請(qǐng)求方法,請(qǐng)求地址,參數(shù),頭參數(shù),調(diào)用時(shí)間,調(diào)用鏈id
        threadLocal.set(Tuples.of(request.getMethod(), request.getRequestURI(), args, headers.toJSONString(), System.currentTimeMillis(), businessId));
    }

再看看使用此方案后的接口調(diào)用日志

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

到此，關(guān)于“如何優(yōu)雅打印接口調(diào)用時(shí)長(zhǎng) ”的學(xué)習(xí)就結(jié)束了，希望能夠解決大家的疑惑。理論與實(shí)踐的搭配能更好的幫助大家學(xué)習(xí)，快去試試吧！若想繼續(xù)學(xué)習(xí)更多相關(guān)知識(shí)，請(qǐng)繼續(xù)關(guān)注億速云網(wǎng)站，小編會(huì)繼續(xù)努力為大家?guī)?lái)更多實(shí)用的文章！