Thrift 我的實戰--Thrift RPC服務框架日誌的優化

 

前言:
　　Thrift做爲Facebook開源的RPC框架, 經過IDL中間語言, 並藉助代碼生成引擎生成各類主流語言的rpc框架服務端/客戶端代碼. 不過Thrift的實現, 簡單使用離實際生產環境仍是有必定距離, 本系列將對Thrift做代碼解讀和框架擴充, 使得它更加貼近生產環境. 本文講述RPC服務框架中, 日誌的重要性, 以及logid的引入. 日誌不只包含豐富的數據(就看是否會挖掘), 並且仍是線上服務問題追蹤和排查錯誤最好的方式.

日誌級別
　　採用你們喜聞樂見的log4j做爲該RPC服務框架首選的日誌庫. 其對日誌的級別有以下幾種:
　　1). TRACE 最細粒度級別日誌級別
　　2). DEBUG 對調試應用程序有幫助的日誌級別
　　3). INFO 粗粒度級別突出強調應用程序的運行
　　4). WARN 代表潛在錯誤的情形
　　5). ERROR 明確發生錯誤, 但不影響系統繼續運行
　　6). FATAL 嚴重的錯誤, 會致使應用工做不正常
　　日誌級別等級順序以下: TRACE < DEBUG < INFO < WARN < ERROR < FATAL
　　而應用具體的輸出取決於日誌級別的設置(包含及以上纔會輸出), 每每項目該上線採用DEBUG級別(日誌量大, 容易寫滿磁盤), 等系統穩定後採用INFO級別

RPC服務日誌需求
　　上述的日誌需求雖然能定位問題, 但每每存在以下問題:
　　1). 不少日誌只是簡單了記錄該點(代碼行)運行過, 或是運行到該點的數據快照.
　　2). 服務由多種模塊(每一個模塊由有多個節點構成)組成, 之間的日誌串聯不起來.
　　而好的日誌設計, 必須能知足
　　1). 以完整的一次RPC調用做爲單位(不是某個執行點快照, 而是完整的RPC callback過程), 並輸出完整的一行日誌記錄, 包括(時間點, 來源, 輸入參數, 輸出參數, 中間經歷的子過程, 消耗時間).
　　2). 引入logid, 做爲多個模塊之間串聯的依據.

RPC級別的日誌解決方案
　　嘗試以下navie的方式去實現

public String echo(String msg) {

　　StringBuilder sb = new StringBuilder();
　　// *) 記錄輸入參數
　　sb.append("[request: {msg: msg}]");
　　// *) 訪問緩存服務
　　sb.append("[action: access redis, consume 100ms]");
　　// *). 訪問後端數據庫
　　sb.append("[action: dao, consume 100ms]");
　　// *). 記錄返回結果
　　sb.append("[response: {msg}]");	

　　logger.info(sb.toString());	
　　return msg;

}

　　評註: 這邊的echo函數表明了一個rpc服務調用接口, 且簡化了各個組件的交互. 同時引入StringBuilder, 記錄各個交互的過程和時間消耗, 最後統一由函數出口前使用logger進行日誌的統一輸入.
　　可是這種方式弊端很是的明顯:
　　1. 假設該rpc服務的函數, 存在多個出口
　　2. 函數存在嵌套調用, 須要嵌套子函數的過程信息
　　以下面的代碼片斷, 可參考:

public boolean verifySession() {
　　// ***********我要記錄日誌(*^__^*) *************** 
}

public String echo(String msg) {

　　StringBuilder sb = new StringBuilder();

　　// *) 調用子過程
　　verifySession();

　　// *) 記錄輸入參數
　　sb.append("[request: {msg: msg}]");
　　// *) 訪問緩存服務
　　if ( KeyValueEngine Access Fail ) {
　　　　// *********日誌記錄在那裏***********
　　　　throw new Exception();
　　}
　　sb.append("[action: access redis, consume 100ms]");

　　// *). 訪問後端數據庫
　　if ( Database Access Fail ) {
　　　　// *********日誌記錄在那裏***********
　　　　throw new Exception();
　　}
　　sb.append("[action: dao, consume 100ms]");
　　// *). 記錄返回結果
　　sb.append("[response: {msg}]");

　　logger.info(sb.toString());

　　return msg;

}

　　評註: 子函數verifySession的調用, 須要把StringBuilder對象往裏傳, 才能記錄相關的信息, 而多個異常出口, 須要把日誌輸入往裏添加(這個繁瑣且容易忘記). 這種方案只能說容易想到, 但不是最佳的方案.
　　有一點不能否認, rpc調用始終在同一個線程中. 聰明的讀者是否猜到了最佳的解決方案.
　　對, 就是大殺器ThreadLocal,其能解決子函數調用的問題, 那多出口問題呢? 讓rpc服務框架去處理, 其做爲具體rpc調用的最外層.

　　採用動態代理類, 去攔截rpc的handler接口調用.

public class LogProxyHandler<T> implements InvocationHandler {

　　private T instance;

　　public LogProxyHandler(T instance) {
　　　　this.instance = instance;
　　}

　　public Object createProxy() {
　　　　return Proxy.newProxyInstance(instance.getClass().getClassLoader(), 
　　　　　　　　　　instance.getClass().getInterfaces(), this);
　　}

　　@Override
　　public Object invoke(Object proxy, Method method, Object[] args)
　　　　　　　　throws Throwable {
　　　　// *) 函數調用前, 攔截處理, 做ThreadLocal的初始化工做
　　　　LoggerUtility.beforeInvoke();	 // -----(1)
　　　　try {
　　　　　　Object res = method.invoke(instance, args);
　　　　　　// *) 函數成功返回後, 攔截處理, 進行日誌的集中輸出 
　　　　　　LoggerUtility.returnInvoke();	 // -----(2)
　　　　　　return res;
　　　　} catch (Throwable e) {
　　　　　　// *) 出現異常後, 攔截處理, 進行日誌集中輸入 // -----(3)
　　　　　　LoggerUtility.throwableInvode("[result = exception: {%s}]", e.getMessage());
　　　　　　throw e;
　　　　}

　　}

}

　　代碼評註:
　　　　(1). 攔截點beforeInvoke用於ThreadLocal的初始話工做, 日誌緩存的清空
　　　　(2). 攔截點returnInvoke用於函數成功返回後, 進行日誌集中輸出
　　　　(3). 攔截點throwableInvoke用於出現異常後, 進行日誌的集中輸出
　　同時在rpc服務調用中, 才用LoggerUtility的noticeLog靜態函數(簡單緩存中間日誌過程)代替以前的StringBuilder.append來記錄中間子過程
　　LoggerUtility的代碼以下所示:

public class LoggerUtility {

　　private static final Logger rpcLogger = LoggerFactory.getLogger("rpc");

　　public static final ThreadLocal<StringBuilder> threadLocals = new ThreadLocal<StringBuilder>();

　　public static void beforeInvoke() {
　　　　StringBuilder sb = threadLocals.get();
　　　　if ( sb == null ) {
　　　　　　sb = new StringBuilder();
　　　　　　threadLocals.set(sb);
　　　　}
　　　　sb.delete(0, sb.length());
　　}

　　public static void returnInvoke() {
　　　　StringBuilder sb = threadLocals.get();
　　　　if ( sb != null ) {
　　　　　　rpcLogger.info(sb.toString());
　　　　}
　　}

　　public static void throwableInvode(String fmt, Object... args) {
　　　　StringBuilder sb = threadLocals.get();
　　　　if ( sb != null ) {
　　　　　　rpcLogger.info(sb.toString() + " " + String.format(fmt, args));
　　　　}
　　}

　　public static void noticeLog(String fmt, Object... args) {
　　　　StringBuilder sb = threadLocals.get();
　　　　if ( sb != null ) {
　　　　　　sb.append(String.format(fmt, args));
　　　　}
　　}

}

　　二者的結合完美的解決了上述RPC的日誌問題, 是否是很贊.

Logid的日誌解決方案
　　Thrift框架自己是沒有logid的概念的, 咱們很難去改動thrift的rpc協議, 去添加它(好比大百度的作法是把logid做爲rpc協議自己一部分). 這邊的解決方案是基於約定. 咱們採用以下約定, 全部的rpc請求參數都封裝爲一個具體Request對象, 全部的返回結構都封裝爲一個具體的Response對象, 而每一個Request對象首個屬性是logid.
　　好比以下的結構定義:

struct EchoRequest {
　　1: required i64 logid = 1001,
　　2: required string msg	
}
struct EchoResponse {
　　1: required i32 status,
　　2: optional string msg
}

service EchoService {
　　EchoResponse echo(1: EchoRequest req);
}

　　評註: Request結構中logid, 就是約定的須要加到rpc的請求結構裏去的.
　　我一直以爲: 約定優於配置, 約定優於框架.

後續
　　中間插入日誌處理這塊, 後續講述以前計劃的服務發佈/訂閱化, 藉助zookeeper來構建一個簡單的系統, 敬請期待.