首页 > 代码库 > Thrift 个人实战--Thrift RPC服务框架日志的优化
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来构建一个简单的系统, 敬请期待.