優雅列印介面呼叫時長

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

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

首先想到的是spring的aop切面,現在我們編寫api介面,一般都會把介面寫在controller控制層裡,按照不同的業務,分為寫在不同業務包下的controller類中.大致的架構如下:

按照這種控制層的編寫規範,只需要用切面找到每個業務包下的controller類,監控類下面的每個方法的入參和執行時間,列印在log日誌中便可以在控制台中視覺化每個介面的實時狀態了.

org.springframework.boot spring-boot-starter-web org.springframework.boot spring-boot-starter-aop

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

通知的主要型別分為:

這裡因為我們需要記錄入參和介面處理時間,選用before 前置通知和around 環繞通知

切面第一步,我們需要找準切點

新建runtimemethod類,用@aspect @component修飾定義這是由spring管理的切面入口類,@log4j2 注釋方便後續列印日誌

@aspect
@component
@log4j2
public class runtimemethod  
}

切面第二步,定義前置和環繞通知,並宣告通知的切點為aoppoint()

/**
* 功能描述: 前置通知
*/@before("aoppoint()")
public void before(joinpoint joinpoint) throws throwable 
/*** 功能描述: 環繞通知
*/@around("aoppoint()")
public object around(proceedingjoinpoint joinpoint) throws throwable

前面兩步實現了兩個需要用到的通知並簡要說明了他的作用.接下來還需要使用到spring包中的servletrequestattributes物件用於獲取httpservletrequest物件,獲取到我們想要的一些列印引數.

public void before(joinpoint joinpoint) throws throwable }}
//引數依次代表請求方法,請求位址,引數,頭引數,呼叫時間
log.info("-in- {} {} -{}{}",request.getmethod(),request.getrequesturi(),joinpoint.getargs(),headers.tojsonstring()}
}

介面呼叫時間也能很輕鬆的在環繞通知中列印

public object around(proceedingjoinpoint joinpoint) throws throwable ms", end - begin}
return result;
}

執行起來,呼叫api介面,我們都會輸出以下日誌

-in- get /user/info -id=123 header: -out- -time:91ms ......

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

-in- get /user/info -id=123 header: -in- get /teacher/info -id=123 header: -out- -time:91ms -in- get /user/info -id=321 header: -out- -time:191ms ......

可以看到問題出現在併發操作上,在同一時間呼叫多個介面時,日誌會亂掉,這可不是我想要的結果.必須想辦法解決這個問題.翻閱資料,想到用threadlocal執行緒區域性變數以及tuple元組物件解決這個問題.接下來改造**.

在runtimemethod類中定義乙個私有變數threadlocal.

private threadlocal> threadlocal = new threadlocal<>();

再改造通知部分

@before("aoppoint()")
public void before(joinpoint joinpoint) throws throwable  {} -{}",
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  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) }}
//此處追加了乙個呼叫鏈的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

至此一套簡化版的介面入參和介面時長統計方案齊活.大家需要注意的是,此方法會導致冗餘日誌過多盡量規避在生產環境中使用,可在類頭部加入@profile()指定環境.在生產環境中排查可使用阿里爸爸的arthas或者zipkin鏈路追蹤解決.切記,此方案只是方便排查測試時期錯誤入參和介面時間過長問題.github原始碼位址

優雅列印介面呼叫時長

列印函式呼叫時間

Tornado 介面呼叫時方法執行順序

OnNewIntent呼叫時機

優雅列印介面呼叫時長

列印函式呼叫時間

Tornado 介面呼叫時方法執行順序

OnNewIntent呼叫時機

相關推薦