文章目录
- log.info日志的入参
- 双object和objects的区别
- 格式字符串(format)和直接字符串的区别
- 性能提升方法
- 通常哪些位置要加日志
- 加日志的注意点
- 很大的日志可以考虑不加,例如base64String
- 返回报文里面也序列化入参
- 为什么要日志优化
- service中的日志和返回体
- 微服务中日志的不足
- requestId实现分布式的日志追踪
- 日志中的行号找不到代码
- 日志和返回体中写法不同
- 日志中使用中括号
- 日志的规范性
- 规范性2
- traceId的作用
- 多线程日志如何打
- 批量数据要不要日志
- 日志中的低级错误
- 占位符和入参哪个少了会报错
- 日志和接口ResultJson的信息的区别:
- 日志会影响效率吗
- xshell日志工具
- 异常日志如何存库
- 动态调整日志级别
- traceId、spanId、parentSpanId的区别
为什么要打日志?
日志是非常重要的,好的日志可以快速定位问题。
试想如果你一行日志也不打,服务器出现问题,是不是很麻爪。
日志分为哪几种
(1) 调试开发日志
目的是开发期调试程序使用,这种日志量比较大,且没有什么实质性的意义,只应该出现在开发期,而不应该在项目上线之后输出。
(2) 用户行为日志
这种类型的日志,记录用户的操作行为,用于大数据分析,比如监控、风控、推荐等等。这种日志,一般是给其他团队分析使用,而且可能是多个团队,因此一般会有一定的格式要求,开发者应该按照这个格式来记录,便于其他团队的使用。当然,要记录哪些行为、操作,一般也是约定好的,因此,开发者主要是执行的角色。这种日志,又叫事件上报,或埋点。
(3)程序运行日志
记录程序的运行状况,特别是非预期的行为、异常情况,这种日志,主要是给开发、维护人员使用。什么时候记录,记录什么内容,完全取决于开发人员,开发者具有高度自主性。本文讨论的主要也是指这种类型的日志,因为作为一个服务端开发、运维人员,程序运行日志往往是解决线上问题的救命稻草。
(4)记录系统或者机器的状态
比如网络请求、系统CPU、内存、IO使用情况等等,这种日志主要是给运维人员使用,生成各种更直观的展现形式,在系统出问题的时候报警。
运行日志可以反馈哪些信息
(1) 通用信息
时间,日志类型,所在类等 。 (日志框架一般都带了)
(2) 进度信息
比如一个服务有5个步骤,是否开始这个服务。执行到了哪步等。
log.info("打开冰箱门");
log.info("把大象放进去");
log.info("关上冰箱门");
(3) 异常信息
log.error("什么操作发生了异常,异常信息为: "+e.toString())
这里要 特别注意一点,如果记录了异常日志,不要继续抛出异常了。 否则可能多次记录日志,因为其他位置可能还会捕获并记录。
注: 该写error的日志,千万别写为info,因为error有个最重的功能就是传入e,会自动打印异常栈,而info必须显式的打印。
(4) 接口间的日志(传递唯一标识)
我在这台机器上调用服务,服务是在另外一台机器。所以需要传递唯一标识。可以传递一个uuid,便于找到问题所在。如代码:
String uuid = UUID.randomUUID().toString();
logger.error("保存操作异常,id为:{},异常信息为:{}", uuid, e);
return new Result<>(ApiContants.ERROR,"id为: "+uuid);
这样我可能没有另一台服务的权限,但可以提供uuid给服务器的同事查问题。
每行日志都要带有uuid吗
每一行都带上更好,就是代码量稍多一些。
log.info 和String.format的对比
效果基本相同,log有些前缀信息。
log.info("param1: {} , param2: {}, param3: {}",111,222,333);
String format = String.format("param1: %s , param2: %s, param3: %s", 111, 222, 333);
引入日志
private Logger logger = LoggerFactory.getLogger(OaSpringBootApplication.class);
log.info日志的入参
可以使用格式字符串,用占用符替代参数。
Logger类定义的方法:
public void info(String msg);
public void info(String format, Object arg);
public void info(String format, Object arg1, Object arg2);
public void info(String format, Object... arguments);
public void info(String msg, Throwable t);
例子:
logger.info("请求异常,异常code: "+"404"); // 直接打印,不使用占位符
logger.info("请求异常,异常code: {}","404"); // 使用格式字符串,1个入参
logger.info("请求异常,异常code: {} 异常msg:{}"+"404","找不到页面"); // 使用格式字符串,2个入参
logger.info("请求异常,异常code: {} 异常msg:{} requestUrl: {}"+"404","找不到页面","/user/login"); // 使用格式字符串,参数列表
// 下面例子和上面一样,就是多了个exception
logger.info("请求异常,异常code: "+"404",e);
logger.info("请求异常,异常code: {}","404",e);
logger.info("请求异常,异常code: {} 异常msg:{}"+"404","找不到页面",e);
logger.info("请求异常,异常code: {} 异常msg:{} requestUrl: {}"+"404","找不到页面","/user/login",e);
// exception不会消耗占位符,他会单独打印
// 第3个{} 不会匹配到e, 所以还是打印{}
logger.info("请求异常,异常code: {} 异常msg:{} 异常信息:{}"+"404","找不到页面",e);
双object和objects的区别
开始我也纳闷,双object不就是objects的一个特殊形式么。
后来看了源码才发现,有点区别。 objects会创建一个objects数组。会增加消耗。
但是双object的2个对象是独立的,性能更高。 这也是把性能发挥到极致了。
public void info(String format, Object arg1, Object arg2);
public void info(String format, Object... arguments);
格式字符串(format)和直接字符串的区别
1、格式字符串可以使用占位符(这谁都知道)
2、看源码说,format还有个优点,就是如果日志级别不支持,不会创建对象。
这里说的不是传入的object对象,而是logger.trace()对象。
例如,默认的级别是info,trace对象是不会创建的。可以还没想到如何验证。
logger.trace("请求异常,异常code: "+"404"); // 无论如何会创建trace对象
logger.trace("请求异常,异常code: {}",new Object()); // trace级别低于info,所以不创建trace对象,但是 new Object()这个对象是会创建的
性能提升方法
1、尽量使用格式字符串。(可以减少低级别的日志对象创建,但是对入参object无效)
2、能使用双object就不要用objects数组。(省略数组开销)
3、使用logger.isErrorEnabled() 。 尤其在入参比较大的时候,这种方法性能很高。
if(logger.isErrorEnabled()){
logger.trace("请求异常,异常code: {}",new Object());
}
通常哪些位置要加日志
一般至少要说明以下信息:
发生了什么请求,入参是什么
成功了,返回值是
异常了,异常原因是
熟练使用日志还需要对业务非常熟悉才可以,否则都不知道该筛选什么日志。
controller入参日志
例如用户今天提交了个快递单,但是说他看不到。我在数据库查也没有。说明用户没有提交,或者是提交过程出错了。
如何排查呢:
1、那么先查info日志,看用户是否有提交的记录,如果没有日志,说明数据没有到后台。是不是前端出了问题。 经查,app端出了问题。
controller里面最好要2条日志,入参日志,结果日志。 调用的方法有日志,异常有日志,就实现了日志的全覆盖。
而且@RequestMapping 还可以设置name,很容易通过拦截器批量处理。
service层中的日志比较多样,这个可以手动掌握,更加的灵活。
异常日志
还是上述快递单的场景,info查到了入参日志,但是数据库没信息。
说明很有可能有异常了。 经常,后台空指针异常了。
方法完成返回结果日志
还是订单问题。 数据库没信息,info有出参日志,提示单据成功。 但是数据库查不到啊。继续翻日志,发现还有一条删除记录的日志。 说明用户提交了又删除了。所以查不到。
注: 如果是逻辑中远程调用的结果,最好也打上日志。这样好找问题。
加日志的注意点
加日志尽量全,又要尽可能少。
无用的日志
如下日志就是没用的。如:
log.info("转账: {} 元",amount);
看不懂了 ,转账1000元,谁转的啊。虽然有日志,但是和没有一样。
还是无用的日志
未获取对应的税号的期限!
谁呀,什么期限。谁也看不懂。
正确的方式:
1、 未获取对应的税号666999的期限 这样大家都能看懂。
如果有的税号没有期限记录,那么没法打印税号。 也要提供线索。
2、票据123456未获取对应的税号期限 这样也是可查的。
再来一个无用的日志
查询数据库数据,查询结果为空
这种日志在调试的时候,或许有点用。 但是到了生产上就屁用没有。
在海洋般的日志里,没有检索特征无异于大海捞针。
正确的例子:
查询用户信息,查询结果为空,查询条件为:
没必要的日志
基础方法里面没必要写日志。
例如生成随机码的工具类,没有必要在这里加。而是应该加在调用它的controller里面。
很大的日志可以考虑不加,例如base64String
例如上传的图片要处理,转化为base64,要不要加日志?
不加,万一出问题怎么办。加日志,一行日志就上千行,其实可读性也很差。
这样大的日志其实可以考虑去掉。
返回报文里面也序列化入参
为了方便查询,返回报文里面也打印入参。
缺点: 相当于入参打印了2遍,如果入参报文也比较多,那么很影响性能。
一个uuid贯穿比打2次入参方便很多。
为什么要日志优化
通常不会有这个问题,因为开发者只怕日志少,不怕日志多。
但是,如果经历过一天10G、甚至40G日志的场景,就能体会到了。
日志太大,即使一个简单的命令,捞数据效率也很慢,更别提复杂场景的数据捞取。
什么,拆分日志,40G的日志文件,即使1000M一个文件,也要拆分40个,要是100M一个,那要400个。 是不是很崩溃。所以日志肯定不是越多越好。
日志中不要有特殊字符
单双引号,星号,右斜杠等最好都不要加。
另外还有:
不要有多个中划线,一个中划线是没问题的,多个就很尴尬。
例如日志为 “--------请求已开始” 。
那你 grep --------请求已开始 a.txt 看下。
service中的日志和返回体
需要日志么:
这个要看具体情况,主要是service的复杂度。如果一个service里面就一个dao,dao里面就一个mapper,那么没必要加。
如果service集成了很多的逻辑,作为一个单独的功能,那么是可以加的。
需要返回体么:
service也可大可小。 如果一个service,包含了一个较大的功能,具备独立的code,message等,那么是可以配备返回体的。
微服务中日志的不足
日志虽然可以查看问题。但是如果在微服务中,查看日志还是有点捉襟见肘。
一种笨方法是:远程调用服务之前可以加是哪个远程服务的,这样跟踪的时候不蒙圈。
场景
应用由10个模块组成,每个模块双节点。 出了问题,先从主应用日志找,再找具体某个模块。 登录服务器需要堡垒机,最少要开4个shell窗口。 相当头疼。
解决方案
方案一:
仅依靠看日志效率还是有点低,一天出几个问题,就够受的了。 所以最好加入监控机制。
方案二:
其实springcloud中的slueth组件就是专门解决分布式日志的跟踪的。
能够记下主要接口在哪个应用中
应用有哪些主要接口是要了如指掌的。 至少看到service要知道属于哪个应用。
还有流程的过程也要清楚,走了几个应用,都是什么方法。
否则看日志都不知道去哪个应用下看。
requestId实现分布式的日志追踪
微服务中,经常用到不只一个rpc服务。通过requestId可以贯穿整个流程。
requestId可以放在入参父类中,自动生成。
继续调用其他rpc的时候requestId也传递出去。接收方先判断是否有requestId,如果存在,就直接使用,不存在则生成。
日志中的行号找不到代码
其实一般是能找到的,这里需要注意下,日志的行号是输出日志的那一行,异常在哪一行是在堆栈信息那一行。
如下:
demo2:58 是logger.error这一行
demo2(ModelController.java:56) 是报错的行
2020-05-18 07:12:42.430 ERROR[http-nio-8080-exec-1]com.example.Demo.demo2:58 -error
java.lang.ArithmeticException: / by zero
at com.example.ModelController.demo2(ModelController.java:56)
日志和返回体中写法不同
日志中推荐使用占位符的写法。 因为看起来更优雅,修改起来也方便。
返回体中推荐使用+号拼接字符串,因为JsonResult不具备解析占位符的功能。
正确的写法:
logger.info("修改信息成功 number: {}",request.getNumber());
return new JsonResult("0", "修改信息成功 number: "+request.getNumber()); // 注意这里是 + 号,不是逗号
错误的写法:
// 错误的写法 这里{}会原样输出。 number却会放到data中。
return new JsonResult("0", "修改信息成功 number: {}",request.getNumber());
// 因为一般JsonResult构造器为这样:
public JsonResult(String code, String message, T data) {
this.code = code;
this.message = message;
this.data = data;
}
日志中使用中括号
其实就是一种写法,为了便于删选:
# 这样就能删选出 中括号中的内容
grep "\[.*\]" info.log
日志的规范性
要做到绝对规范挺难的,因为不同场景,日志要打印的格式也不同。
要一致性,一种思路是定义常量。但是都用常量的话,看起来反而不如文字清爽。
不用常量的话,就会有一个问题,日志描述越写花样越多,例如:
method收到请求,入参:
method入参
method完成
method成功
method异常
这里追求日志完全一模一样挺难的,但至少要有保证一点,能把事情描述清楚。
规范性2
例如controller中用"请求":
请求开始,入参:
请求结束/完成/成功,返回报文:
请求失败,返回报文:
为了日志名称的一致性,@RequestMapping中可以设置下name属性,主要是为了复制起来方便。
@RequestMapping(value="getUser()",name="获取用户信息")
public User getUser(){
}
service中用"服务"
服务开始,入参:
服务结束/完成/成功,返回报文:
服务失败,返回报文:
主要就这2个了,dao里面一般不用日志的。
traceId的作用
1、多行不同的日志确定是同一个请求的。
2、跨服务之间日志的追踪。
多线程日志如何打
单线程根本不用指定uuid,因为日志工具一般都自带。
那么多线程为什么要打日志呢?
因为虽然有个主线程日志,可能会有及万行,根本不好筛选。
子线程难道没traceId吗?
有的。例如:
INFO thread-1 asldfjaldjfla-asdfajsldkfjalkjf-asdfasdsf
很明显,是有子线程记录的。但是如果是2个线程池,会反复thread-1和thread-2,如果数据量大,还是不好筛选。所以要子线程id。
那么如何传递呢?
常用的两种方案。
方案一:final String sonUuid=“asldfjalkdjf”; 直接带过去。同理,其他参数也可以设置为final带过去。(线程中只允许直接带入final变量)
方案二:通过构造器带过去。
批量数据要不要日志
有的时候考虑到日志量会非常大,便不打日志,这是不对的。因为万一某条数据有纠纷,什么都查不到,这官司怎么打? 所以宁可麻烦一点,批量数据也想办法加上日志。如果不是特别多,可以一起加,量很大的话,可以循环加。
日志是肯定要的。
日志中的低级错误
还有一种情况要坚决避免,就是日志写错的情况。
例如:
修改机构成功 错写为 修改用户成功
这种低级错误实际中确实有发生,要细心些,坚决避免。
占位符和入参哪个少了会报错
这个比较好测试,代码如下:
// 入参少于占位符
LOGGER.info("requestid:{},流水单导入收到请求:{}", 1 );
// 占位符少于入参
LOGGER.info("requestid:{},流水单导入收到请求:{}", 1 ,2,3);
实测都不会报错。如果少了,打印不出来而已。
日志和接口ResultJson的信息的区别:
当然是有区别的,
1、日志要带上请求的名称,ResultJson不用。
2、日志要加上,返回报文、返回信息 这样的字段,ResultJson不用。
至于占位符,都是可以使用的,因为有MessageFormat工具。
日志会影响效率吗
一般来说,单条日志的耗时是1ms级别甚至更少。
所以一个请求,有二三十条日志也不碍事。
只要日志打印的不是特别夸张的对象就行。例如一个超大的对象,几万行的json等。
xshell日志工具
简单说就是将日志结果保存到自己电脑上。
右键 | 日志 | 启动 ,然后弹出一个保存文件的对话框,选个文件就是日志输出的文件,所有的操作及返回都会打印到这个文件里。
如果不用了,右键 | 日志 | 停止 即可。
缺点: 因为要写日志到文件,所以稍微影响点效率。
异常日志如何存库
打印日志很简单,
logger.error(“error:”,e); // 注: error日志不用加{},否则反而抓不到。
但是如果记录下详细的堆栈信息呢? 用e.getStackTrace()就行吧?
实测原生的不行。那么怎么办呢?
不用担心,有现成的类库可以解决。
logger.info("testError请求异常,error:", e);
工具类的方法:
String stackTrace = ExceptionUtils.getStackTrace(e);
String message = ExceptionUtils.getMessage(e);
Throwable rootCause = ExceptionUtils.getRootCause(e);
logger.info("stackTrace:{}",stackTrace);
logger.info("message:{}",message);
logger.info("rootCause:{}",rootCause);
原生的方法:
logger.info("e.getCause():{}",JSON.toJSONString(e.getCause()));
logger.info("e.getMessage():{}",e.getMessage());
logger.info("e.getLocalizedMessage():{}",JSON.toJSONString(e.getLocalizedMessage()));
logger.info("e.getStackTrace():{}",JSON.toJSONString(e.getStackTrace()));
动态调整日志级别
其实actuator就行,详见笔者actuator使用笔记。
traceId、spanId、parentSpanId的区别
刚看到的时候有点蒙,为什么是三段式呢?一个uuid不就够了吗?
后来才明白这是分布式的日志概念。
例如:
结构:
traceId-spanId-parentSpanId
例子:
afa3a75ebd7d0439-7b57df10e16a0ec6-afa3a75ebd7d0439
参考下别人的说法:
traceId : 在一个 链路 中 traceId 唯一
spanId : 同一个线程中唯一, 从0始,按照调用链路从0递增
parentSpanId : 在同一个线程的链路中,用来连接 span
segmentId : 同一个 线程链路中,这个值都是相同的,不同线程链路中 这个值不同
traceId 倒好理解。
spanId为什么没有按照规则呢? 7b57df10e16a0ec6
这个是第几级的调用呢?
parentSpanId值为什么和traceId一致,什么时候不一致呢?