美文网首页Java 程序员微服务搭建Java
别再乱打日志了,这样才是定位 bug 打日志的方式

别再乱打日志了,这样才是定位 bug 打日志的方式

作者: 程序花生 | 来源:发表于2021-05-11 21:53 被阅读0次

概述

日常工作中,程序员需要经常处理线上的各种大小故障,如果业务代码没打印日志或者日志打印得不好,会极大的加大了定位问题的难度,使得解决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"
            }
         }
      }
   }
}

最新 Java 核心技术教程,都在这了。

为了能拼成一条,有两种方案,一种是比较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满天飞。

最后,另外,关注公众号Java技术栈,在后台回复:面试,可以获取我整理的 Java 系列面试题和答案,非常齐全。

原文:https://blog.csdn.net/linsongbin1/article/details/90349661
版权声明:本文为CSDN博主「Sam哥哥」的原创文章,遵循CC 4.0 BY-SA版权协议,转载请附上原文出处链接及本声明。

相关文章

  • 别再乱打日志了,这样才是定位 bug 打日志的方式

    概述 日常工作中,程序员需要经常处理线上的各种大小故障,如果业务代码没打印日志或者日志打印得不好,会极大的加大了定...

  • 5,打log心得

    不能乱打日志,也不能少打日志,打印日志心得: 只要遵从以上几点,日志很清晰,长远考虑这个日志可做大数据分析 就到这...

  • 2018-08-21第十二天

    网站请求+BUG定位 如何定位Bug界面:肉眼看前端代码:F12 console前端日志报错,定位HTML错误行网...

  • 第十四天_复习bug定位&linux命令加强

    第三周第四天复习bug定位linux命令加强 复习bug定位 发现bug后定位流程 看界面提示 看前端日志 抓包看...

  • Docker和ELK搭建日志平台

    Elasticsearch, Logstash 和 Kibana 简称ELK,是日志平台。用途:Bug定位,历史统...

  • ThinkPHP 接入 SeasLog 日志组件

    【背景】 为实现开发前期联调bug 定位、线上bug快速定位、快速响应,遂暂为斐讯路由后台 Api 模块添加日志记...

  • Java 如何正确地输出日志

    几个错误的打日志方式 不要使用 System.out.print..输出日志的时候只能通过日志框架来输出日志,而不...

  • C++ 之 日志可变参数输出

    在开发应用或者游戏的过程中,定位bug、查看获取数据、跟踪执行流程等都需要查看日志,可见日志的重要程度。当然如果我...

  • iOS 如何找到或生成 .dSYM 文件

    iOS 第三方dSYM定位BUG系统崩溃日志或者手机奔溃日志 0.生成 .dSYM 配置介绍 1.发布模式 Xco...

  • dYSM定位bug日志

    1、打开终端输入以下路径 cd /Applications/Xcode.app/Contents/SharedFr...

网友评论

    本文标题:别再乱打日志了,这样才是定位 bug 打日志的方式

    本文链接:https://www.haomeiwen.com/subject/sznndltx.html