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

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


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

  1. RocketMQ / MyCAT / Sharding-JDBC 所有源码分析文章列表
  2. RocketMQ / MyCAT / Sharding-JDBC 中文注释源码 GitHub 地址
  3. 您对于源码的疑问每条留言将得到认真回复。甚至不知道如何读源码也可以请教噢
  4. 新的源码解析文章实时收到通知。每周更新一篇左右
  5. 认真的源码交流微信群。

概述

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

文章目录
  1. 1. 概述
  2. 2. 请统一日志格式
  3. 3. 将request和response放置在一起
  4. 4. 日志里加入traceId