概述
日常工作中,程式員需要經常處理線上的各種大小故障,如果業務代碼沒列印日志或者日志列印的不好,會極大的加大了定位問題的難度,使得解決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滿天飛。