切记，这样打日志定位 Bug 又快又准！

头像
民工哥
    阅读 7 分钟
    4
    头图

    概述

    日常工作中，程序员需要经常处理线上的各种大小故障，如果业务代码没打印日志或者日志打印的不好，会极大的加大了定位问题的难度，使得解决bug的时间变长了。对于那种影响比较大的bug，处理时间是分秒必争的，慢几秒处理完，可能GMV就哗啦啦的掉了很多。

    一个程序员是否优秀，其中一个判断维度就是：处理线上问题是否快狠准，而其中日志是帮我们快速定位问题的绝佳手段。

    下面分享一下笔者平时在业务系统里记日志的一些手法和习惯，希望对大家有一些帮助。

    请统一日志格式

    日志格式最好是统一的，即方便查看定位问题又方便统计收集。我一般喜欢定义一个LogObject对象，里面定义日志的各个字段。例如：

    import com.fasterxml.jackson.annotation.JsonInclude;
import com.fasterxml.jackson.annotation.JsonInclude.Include;
import com.fasterxml.jackson.annotation.JsonProperty;

public class LogObject {
    @JsonProperty(index = 1)
    private String eventName;

    @JsonProperty(index = 2)
    private String traceId;

    @JsonProperty(index = 3)
    private String msg;

    @JsonProperty(index = 4)
    private long costTime;

    @JsonProperty(index = 6)
    private Integer userId;

    @JsonProperty(index = 7)
    private Object others;

    @JsonProperty(index = 8)
    private Object request;

    @JsonProperty(index = 9)
    private Object response;


    public String getEventName() {
        return eventName;
    }

    public LogObject setEventName(String eventName) {
        this.eventName = eventName;
        return this;
    }

    public Object getRequest() {
        return request;
    }

    public LogObject setRequest(Object request) {
        this.request = request;
        return this;
    }

    public Object getResponse() {
        return response;
    }

    public LogObject setResponse(Object response) {
        this.response = response;
        return this;
    }

    public String getMsg() {
        return msg;
    }

    public LogObject setMsg(String msg) {
        this.msg = msg;
        return this;
    }



    public long getCostTime() {
        return costTime;
    }

    public LogObject setCostTime(long costTime) {
        this.costTime = costTime;
        return this;
    }


    public Integer getUserId() {
        return userId;
    }

    public LogObject setUserId(Integer userId) {
        this.userId = userId;
        return this;
    }

    public Object getOthers() {
        return others;
    }

    public LogObject setOthers(Object others) {
        this.others = others;
        return this;
    }

    public String getTraceId() {
        return traceId;
    }

    public LogObject setTraceId(String traceId) {
        this.traceId = traceId;
        return this;
    }

    traceId: 调用链id
    eventName: 事件名称,一般就是业务方法名称
    userId: C端用户id
    msg: 结果消息
    costTime: 接口响应时间
    request: 接口请求入参
    response: 接口返回值
    others: 其他业务参数

    使用链式的风格，方便设置字段的值：

    long endTime = System.currentTimeMillis();
LogObject logObject = new LogObject();
logObject.setEventName(methodName)
         .setMsg(msg)
         .setTraceId(traceId)
         .setUserId(backendId)
         .setRequest(liveRoomPushOrderReqDto)
         .setResponse(response)
         .setCostTime((endTime - beginTime));

LOGGER.info(JSON.toJSONString(logObject));

    当然最好还是封装出一个工具类出来,例如叫:LogTemplate，作为一个统一的入口。另外可以使用JsonProperty注解，指定字段的顺序，例如通过index=1，将eventName放置在最前面。

    @JsonProperty(index = 1)
private String eventName;

    将request和response放置在一起

    将请求和返回值，放置在同一条日志里，有个好处，就是非常方便查看上下文日志。如果打印成两条，返回值那条可能被冲到很后面，而且也得再做一次grep操作，影响效率。

    具体的日志如下：

    {
   "eventName":"createOrder",
   "traceId":"createOrder_1574923602015",
   "msg":"success",
   "costTime":317,
   "request":{
      "uId":111111111,
      "skuList":[
         {
            "skuId":22222222,
            "buyNum":1,
            "buyPrice":8800,
         }
      ]
   },
   "response":{
      "code":0,
      "message":"操作成功",
      "data":{
         "bigOrderId":"BIG2019",
         "m2LOrderIds":{
            "MID2019":{
               "22222222":"LIT2019"
            }
         }
      }
   }
}

    为了能拼成一条，有两种方案，一种是比较low的，直接在代码里使用try catch finally，例如：

     @PostMapping(value = "/createOrder")
    public JsonResult createOrder(@RequestBody Object request) throws Exception {
        String methodName = "/createOrder";
        Integer backendId = null;
        String msg = "success";
        long beginTime = System.currentTimeMillis();
        String traceId = "createOrder_"+beginTime;
        JsonResult response = null;
        try {
            OrderCreateRsp orderCreateRsp = orderOperateService.createOrder(request, traceId);
            response = JsonResult.success(orderCreateRsp);
        }
        catch (Exception e) {
            msg = e.getMessage();
            LOGGER.error(methodName+",userId:"+backendId+",request:"+ JsonHelper.toJson(request),e);
            throw new BizException(0,"下单失败");
        }
        finally {
            long endTime = System.currentTimeMillis();
            LogObject logObject = new LogObject();
            logObject.setEventName(methodName)
                     .setMsg(msg)
                     .setTraceId(traceId)
                     .setUserId(backendId)
                     .setRequest(request)
                     .setResponse(response)
                     .setCostTime((endTime - beginTime));

            LOGGER.info(JSON.toJSONString(logObject));
        }

        return response;
    }

    这种方案呢，有个缺点，就是每个业务方法都得处理日志，更好的方案是使用aop加thread local的方式，将请求统一拦截且将返回值和请求参数串起来，这个网络上的方案很多，这里就不阐述了。

    对于对性能要求比较高的应用，反而推荐第一种方案，因为使用aop，有一些性能损耗。像我之前在唯品会参与的商品聚合服务，用的就是第一种方案，毕竟每一秒要处理上百万的请求。另外，附送学习资源：Java进阶视频资源

    日志里加入traceId

    如果应用中已经使用了统一调用链监控方案，且能根据调用链id查询接口情况的，可以不用在代码里手动加入traceId。如果应用还没接入调用链系统，建议加一下traceId，尤其是针对聚合服务，需要调用中台各种微服务接口的。像聚合层下单业务，需要调用的微服务就有如下这么些：

    • 营销系统
    • 订单系统
    • 支付系统

    下单业务调用这些接口的时候，如果没有使用traceId进行跟踪的话，当下单失败的时候，到底是哪个微服务接口失败了，就比较难找。下面以小程序端，调用聚合层下单接口的例子作为展示：

    //营销系统
{
   "eventName":"pms/getInfo",
   "traceId":"createOrder_1575270928956",
   "msg":"success",
   "costTime":2,
   "userId":1111111111,
   "request":{
      "userId":1111111111,
      "skuList":[
         {
            "skuId":2222,
            "skuPrice":65900,
            "buyNum":1,
            "activityType":0,
            "activityId":0,
         }
      ],
   },
   "response":{
      "result":1,
      "msg":"success",
      "data":{
         "realPayFee":100,
      }
   }
}
    //订单系统
{
   "eventName":"orderservice/createOrder",
   "traceId":"createOrder_1575270928956",
   "msg":"success",
   "costTime":29,
   "userId":null,
   "request":{
      "skuList":[
         {
            "skuId":2222,
            "buyNum":1,
            "buyPrice":65900,
         }
      ],
   },
   "response":{
      "result":"200",
      "msg":"调用成功",
      "data":{
         "bigOrderId":"BIG2019",
         "m2LOrderIds":{
            "MID2019":{
               "88258135":"LIT2019"
            }
         }
      }
   }
}
    //支付系统

{
   "eventName":"payservice/pay",
   "traceId":"createOrder_1575270928956",
   "msg":"success",
   "costTime":301,
   "request":{
      "orderId":"BIG2019",
      "paySubject":"测试",
      "totalFee":65900,
   },
   "response":{
      "requestId":"test",
      "code":0,
      "message":"操作成功",
      "data":{
         "payId":123,
         "orderId":"BIG2019",
         "tradeType":"JSAPI",
         "perpayId":"test",
         "nonceStr":"test",
         "appId":"test",
         "signType":"MD5",
         "sign":"test",
         "timeStamp":"1575270929"
      }
   }
}

    可以看到聚合层需要调用营销、订单和支付三个应用的接口，调用的过程中，使用traceId为createOrder_1575270928956的串了起来，这样我们只需要grep这个traceId就可以把所有相关的调用和上下文找出来。

    traceId如何生成呢，一种简单的做法是，使用System.currentTimeMillis() 加上业务接口名字，如：

     long beginTime = System.currentTimeMillis();
 String traceId = "createOrder_"+beginTime;
加traceId会侵入到业务方法里，比如说：

public void createOrder(Object obj) {
  long beginTime = System.currentTimeMillis();
   String traceId = "createOrder_"+beginTime;
   pmsService.getInfo(obj,traceId);
   orderService.createOrder(obj,traceId);
   payService.getPrepayId(obj,traceId);
}

    像pmsService这些内部的service方法，都需要加一个traceId字段，目前我觉得还好，要是觉得入侵了，也可以考虑thread local的方式，处理请求的时候，为当前线程存储一下traceId，然后在业务方法里，再从当前线程里拿出来，避免接口方法里的traceId满天飞。

    来源：blog.csdn.net/linsongbin1/article/
    details/90349661

    java后端运维日志管理程序员
    民工哥
    26.4k 声望56.7k 粉丝

    10多年IT职场老司机的经验分享，坚持自学一路从技术小白成长为互联网企业信息技术部门的负责人。2019/2020/2021年度 思否Top Writer

    « 上一篇
    Prometheus+InfluxDB+Grafana 打造高逼格监控平台！
    下一篇 »
    深度解析！Linux 命令 su 和 sudo 的区别

    引用和评论

    推荐阅读
    头像
    早知道有这么个吊炸天的 CI&CD 工具，我就不用 Jenkins 了！

    民工哥赞 1阅读 2k

    头像
    在Java程序中监听mysql的binlog

    huan1993赞 13阅读 5.6k

    头像
    喜大普奔，适用于 VS Code 的 GitHub Copilot 全新免费版本正式推出，GitHub 全球开发者突破1.5亿

    鸣飞赞 8阅读 13.4k评论 1

    头像
    Bitmap 和 布隆过滤器傻傻分不清？你这不应该啊

    程序员小富赞 10阅读 4.8k评论 1

    头像
    Jerry和您聊聊Chrome开发者工具

    注销赞 9阅读 4.9k评论 3

    头像
    Spring 实现 3 种异步流式接口，干掉接口超时烦恼

    程序员小富赞 6阅读 2.5k

    头像
    💢线上高延迟请求排查

    crossoverJie赞 6阅读 4k评论 5

    0 条评论
    得票最新