说说日志
说说日志
一个应用被部署在服务器上,如果出了问题,又不能用手扒开去看,抛开额外开发的监控系统来说,如果要排错,日志是最终的依靠,甚至很多情况都是唯一的依靠.
而各位开发的大老爷,往往对应用程序中的日志输出,缺少足够的认识.在开发过程中,只重视功能的开发,而不注重日志输出.到最后生产出问题,日志输出有问题.
日志好的项目都是千篇一律,日志不好的项目,有以下问题
- 没有日志输出,发个请求,页面显示服务器异常,日志就2行.
- 瞎输出,一个请求输出500行或1M的日志,找个问题要翻半天
这篇文章来搞搞日志.
分类
在java开发中,有各种日志中间件,common-logging,slf4j,log4j,logback,还有jdk中自带的java.util.logging,我们首先要分清楚这些个日志中间件都是啥意思,为什么会有那么多的中间件.
我们可以简单的对上面列举的中间件中的jar包做一下分类
| 分类 | 说明 | 常见jar |
|---|---|---|
| 日志标准接口 | 在代码中使用或者import的java类 | common-logging,slf4j-api |
| 日志执行器 | 真正对磁盘进行写入的日志执行包 | log4j,logback,log4j2 |
| 日志桥接器 | 在不同的代码中对于不同的日志进行统一的输出 | slf4j-log4j,jcl-over-slf4j |
提示
java.util.logging比较特殊,既是标准接口,又是桥接器.
JDK就是那么强横.
slf4j的桥接器,又有以下几种类型
slf4j使用什么执行输出,代表的jar包为,slf4j-log4j简单理解就是代码中的slf4j的日志输出,使用log4j的执行器,写入日志
原本使用log4j的api的日志输出,使用slf4j进行桥接,然后使用logback输出,log4j-over-slf4j就是这类的包.
各种标准日志接口的双向桥接.
| 包名 | 说明 |
|---|---|
| jcl-over-slf4j | common-logging的api输出,桥接成slf4japi |
| slf4j-jcl | 把slf4j的api桥接成common-logging |
| jul-to-slf4j | java logging的api,桥接成slf4j |
警告
如果一个项目里面同时引入slf4j-log4j和log4j-over-slf4j,项目启动会出现SPI的死循环.这个死循环很奇怪,就是cpu完全被占据一个逻辑核,一般不是100%,请求还能访问,但是没有任何日志输出.
为什么会有那么多包
我们在写java代码的时候,会依赖不同的中间件,比如spring,mybatis,我们就拿这2个包来进行分析.
spring诞生的比较早,早到当时只有log4j,没有logback和java.util.logging.而spring框架在一开始的时候,没有依赖log4j,而是依赖了common-logging,原因就是spring无法决定自己被使用的环境是哪个日志环境.到目前为止,spring还是依赖了common-logging,而对于spring的日志输出,却可以随便变化,这就是日志标准接口的好处.
提示
到目前为止,要想输出spring的日志,要么使用common-logging(log4j里面默认带了common-logging的实现),要么使用jcl-over-slf4j,再桥接到执行器.
mybatis诞生的时候,已经出现slf4j,common-logging等标准接口,mybatis采用的策略是自己实现一套标准日志接口,自己对接其他的日志接口,感兴趣的朋友可以看看mybatis源码里面的org.apache.ibatis.logging的包.mybatis自己对接了各种常用的日志包.面对同样的问题,很明显2个框架采取了不一样的策略.
从上面我们常用的中间件可以看到,当我们研发一个中间件的时候,中间件内的日志输出一般会使用标准日志接口,因为中间件的研发者无法确定中间件的使用环境.如果中间件本身依赖了log4j,你让使用者怎么办???如果一个项目中,有多个中间件,其中一个用了log4j,另外一个用了jdk logging,这个项目最后应该用哪个中间件写磁盘??
其实除了jul和common-logging外,目前我们熟知的slf4j,log4j,log-back,log4j2,这些东西都是由同一个团队搞的,所以各种配置思想都差不多.本质上是一个人推动了整个技术的进步,有空各位可以去了解了解技术的八卦.
防止多余的日志
如果项目中缺少日志,肯定是日志埋点不够,这个没得说,只能加.
如果项目打印日志过多,除了在代码里面减少日志的输出外,我们还可以这么搞呢??除了提高日志输出级别和分文件外,其实仔细看过多的日志,就会发现,除了输出的内容多以外,还有部分是配置引发的重复输出.
在log4j和logback的配置中,对日志的配置有一个additivity属性,这个属性需要各位注意.
假设我们的配置是这样的
如果在其中配置的org.springframework.web.servlet.mvc.method.annotation程序包内,有一段应用输出了一个info日志,在没有配置additivity属性的前提下,这个info日志会被org.springframework.web.servlet.mvc.method.annotation的logger截获进行输出,也会被org.springframework截获,也进行输出,最终导致这段info会输出2遍.
提示
在logger的配置中,additivity属性默认是true,默认就是多次匹配输出.
所有的日志组件,都不能按照线程输出,这个问题请移步日志追踪查看,在启路框架中,通过对日志的MDC操作,让打印的日志使用同一个traceNo输出.
写在最后
最后在说一个事,在开发的程序中,再也不要写System.out.println();和e.printStackTrace()了,为什么??中间的问题是出在out和print的buffer上,System.out和System.err都是PrintStream,这个类是没有buffer的.
说人话就是,如果直接输出,会是一个字符一个字符的向磁盘文件写数据.我们采用日志中间件输出的日志,是先会写入buffer,然后一起刷到磁盘.
因为System.out和e.printStackTrace()引发的问题,都是生产问题,在开发阶段无法发现,在性能阶段可能不会安排专门的异常测试来刷数据,所以,这种问题往往会被简单的说一句,"不准使用System.out输出"来限制.
一个我排查过的真实案例,苏A某银行,有个应用程序在进行性能测试的时候,最开始的2分钟,TPS在30每秒,还可以接受,2分钟后会突然TPS降低到1每秒左右,客户直接甩脸子.找了2星期,各种工具无法发现问题.
最后分析线程栈,查明原因是因为e.printStackTrace中的PrintStream的write方法上,后面排查代码发现在for循环中printStackTrace.在前2分分钟的时候,性能高都是因为磁盘的缓存,后2分钟磁盘缓存写满以后,直接写磁盘的时候,性能直接下降.