⭐⭐⭐ Spring Boot 项目实战	⭐⭐⭐ Spring Cloud 项目实战
《Dubbo 实现原理与源码解析 —— 精品合集》	《Netty 实现原理与源码解析 —— 精品合集》
《Spring 实现原理与源码解析 —— 精品合集》	《MyBatis 实现原理与源码解析 —— 精品合集》
《Spring MVC 实现原理与源码解析 —— 精品合集》	《数据库实体设计合集》
《Spring Boot 实现原理与源码解析 —— 精品合集》	《Java 面试题 + Java 学习指南》

摘要: 原创出处 mp.weixin.qq.com/s/n26LqoC5DBJ5fi6CzeRcTw 「null」欢迎转载，保留摘要，谢谢！

🙂🙂🙂关注**微信公众号：【芋道源码】**有福利：

RocketMQ / MyCAT / Sharding-JDBC 所有源码分析文章列表

RocketMQ / MyCAT / Sharding-JDBC 中文注释源码 GitHub 地址

您对于源码的疑问每条留言都将得到认真回复。甚至不知道如何读源码也可以请教噢。

新的源码解析文章实时收到通知。每周更新一篇左右。

认真的源码交流微信群。

概述

日常工作中，程序员需要经常处理线上的各种大小故障，如果业务代码没打印日志或者日志打印的不好，会极大的加大了定位问题的难度，使得解决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
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，有一些性能损耗。像我之前在唯品会参与的商品聚合服务，用的就是第一种方案，毕竟每一秒要处理上百万的请求。

日志里加入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满天飞。

芋道源码 —— 纯源码解析博客

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

概述

请统一日志格式

将request和response放置在一起

日志里加入traceId