码迷,mamicode.com
首页 > 其他好文 > 详细

Thrift 个人实战--Thrift RPC服务框架日志的优化

时间:2014-07-31 23:35:00      阅读:387      评论:0      收藏:0      [点我收藏+]

标签:blog   java   使用   os   strong   io   数据   for   

 

前言:
  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来构建一个简单的系统, 敬请期待.

Thrift 个人实战--Thrift RPC服务框架日志的优化,布布扣,bubuko.com

Thrift 个人实战--Thrift RPC服务框架日志的优化

标签:blog   java   使用   os   strong   io   数据   for   

原文地址:http://www.cnblogs.com/mumuxinfei/p/3876190.html

(0)
(0)
   
举报
评论 一句话评论(0
登录后才能评论!
© 2014 mamicode.com 版权所有  联系我们:gaon5@hotmail.com
迷上了代码!