logback高级特性二 异步记录日志
问题描述:
下图中JProfiler可看出logback的日志输出占了64%的cpu消耗
优化方案:
1. 这部分写日志的代码写了一些报文数据,确实是比较大的字符串。先禁掉控制台输出,生产环境也不需要控制台输出,写日志文件即可。
配置中去掉控制台输出
<rootlevel="INFO">
<!--<appender-ref ref="STDOUT"/>-->
<appender-refref="ASYNC_ROLLING_FILE"/>
</root>
优化后的结果,915ms直接变为76ms,优化效果相当显著
2. 可能这时有人会说了,“你控制台禁了,日志文件又禁不了,不还是慢啊!”这话很有道理,但是logback有个好东东,日志文件异步写入
配置如下:
<appendername="ASYNC_ROLLING_FILE"class="ch.qos.logback.classic.AsyncAppender"> <appender-refref="ROLLING_FILE"/> </appender> <rootlevel="INFO"> <appender-refref="ASYNC_ROLLING_FILE"/> </root>
所以在上面的性能监控里面就看不到文件写入的性能消耗了。
异步记录日志
AsyncAppender,异步记录日志。
工作原理:
工作原理:
当Logging Event进入AsyncAppender后,AsyncAppender会调用appender方法,append方法中在将event填入Buffer(这里选用的数据结构为BlockingQueue)中前,会先判断当前buffer的容量以及丢弃日志特性是否开启,当消费能力不如生产能力时,AsyncAppender会超出Buffer容量的Logging Event的级别,进行丢弃,作为消费速度一旦跟不上生产速度,中转buffer的溢出处理的一种方案。AsyncAppender有个线程类Worker,它是一个简单的线程类,是AsyncAppender的后台线程,所要做的工作是:从buffer中取出event交给对应的appender进行后面的日志推送。
从上面的描述中可以看出,AsyncAppender并不处理日志,只是将日志缓冲到一个BlockingQueue里面去,并在内部创建一个工作线程从队列头部获取日志,之后将获取的日志循环记录到附加的其他appender上去,从而达到不阻塞主线程的效果。因此AsynAppender仅仅充当事件转发器,必须引用另一个appender来做事。
在使用AsyncAppender的时候,有些选项还是要注意的。由于使用了BlockingQueue来缓存日志,因此就会出现队列满的情况。正如上面原理中所说的,在这种情况下,AsyncAppender会做出一些处理:默认情况下,如果队列80%已满,AsyncAppender将丢弃TRACE、DEBUG和INFO级别的event,从这点就可以看出,该策略有一个惊人的对event丢失的代价性能的影响。另外其他的一些选项信息,也会对性能产生影响,下面列出常用的几个属性配置信息:
属性名 | 类型 | 描述 |
queueSize | int | BlockingQueue的最大容量,默认情况下,大小为256。 |
discardingThreshold | int | 默认情况下,当BlockingQueue还有20%容量,他将丢弃TRACE、DEBUG和INFO级别的event,只保留WARN和ERROR级别的event。为了保持所有的events,设置该值为0。 |
includeCallerData | boolean | 提取调用者数据的代价是相当昂贵的。为了提升性能,默认情况下,当event被加入到queue时,event关联的调用者数据不会被提取。默认情况下,只有"cheap"的数据,如线程名。 |
默认情况下,event queue配置最大容量为256个events。如果队列被填满,应用程序线程被阻止记录新的events,直到工作线程有机会来转发一个或多个events。因此队列深度需要根据业务场景进行相应的测试,做出相应的更改,以达到较好的性能。
下面给出一个使用的配置示例:
下面给出一个使用的配置示例:
<appender name="FILE" class= "ch.qos.logback.core.rolling.RollingFileAppender"> <!-- 按天来回滚,如果需要按小时来回滚,则设置为{yyyy-MM-dd_HH} --> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <fileNamePattern>/opt/log/test.%d{yyyy-MM-dd}.log</fileNamePattern> <!-- 如果按天来回滚,则最大保存时间为1天,1天之前的都将被清理掉 --> <maxHistory>30</maxHistory> <!-- 日志输出格式 --> <layout class="ch.qos.logback.classic.PatternLayout"> <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} -%msg%n</Pattern> </layout> </appender> <!-- 异步输出 --> <appender name ="ASYNC" class= "ch.qos.logback.classic.AsyncAppender"> <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 --> <discardingThreshold >0</discardingThreshold> <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 --> <queueSize>512</queueSize> <!-- 添加附加的appender,最多只能添加一个 --> <appender-ref ref ="FILE"/> </appender> <root level ="trace"> <appender-ref ref ="ASYNC"/> </root>
同步/ 异步的性能对比测试
1. RollingFileAppender
配置:
<appender name="localFile" class="ch.qos.logback.core.rolling.RollingFileAppender"> <encoder> <ImmediateFlush>false</ImmediateFlush> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{32} %L - %msg %n</pattern> </encoder> <file>${LOG_HOME}/fileLog.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy"> <fileNamePattern>${LOG_HOME}/fileLog_%d{yyyyMMddHH}_%i.log.zip </fileNamePattern> <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP"> <maxFileSize>10MB</maxFileSize> </timeBasedFileNamingAndTriggeringPolicy> </rollingPolicy> </appender>
测试30s左右,去掉ImmediateFlush, 37s左右
2. 采用异步输出
配置:
<appender name ="asyncFile" class= "ch.qos.logback.classic.AsyncAppender"> <!-- 不丢失日志.默认的,如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 --> <discardingThreshold >0</discardingThreshold> <!-- 更改默认的队列的深度,该值会影响性能.默认值为256 --> <queueSize>2048</queueSize> <includeCallerData>true</includeCallerData> <!-- 添加附加的appender,最多只能添加一个 --> <appender-ref ref ="localFile"/> </appender>
includeCallerData = true: 27s左右
includeCallerData = false: 22s左右
3. 现网测试
不开启Logback, TPS: 3100左右;
未添加includeCallerData=true和ImmediateFlush=false时, TPS只能到500左右,添加这两个配置后,TPS能到2900左右
转自:
https://blog.csdn.net/Pasenger/article/details/38582949
https://blog.csdn.net/qq496013218/article/details/76603779
https://blog.csdn.net/ajax_yan/article/details/80519008