日志文件必须输出到控制台才香对吗

news/2025/3/19 15:35:33/文章来源:https://www.cnblogs.com/Nuwa/p/18781144

在实际工作中发现很多人喜欢将日志输出到控制台，有的甚至直接只是输出到控制台，都不输出到日志文件中。

这种操作看似人畜无害，实际上直接影响着系统的性能，很多时候还难以排查，这里我从实际举例都背后原因来分析为什么这么做并不香。

通常的日志配置

这里我们使用经常使用的logback来举例即可，很多项目的配置如下所示：这里定义了两个输出到指定文件的appender ，然后一个默认的输出到控制台的ConsoleAppender，默认的配置无论是root还是自定义的输出都会同时写入到控制台、日志文件。项目上线的时候，大概率也是这样就配置了，可能连级别都懒得改。

<configuration scan="true" scanPeriod="1 hours" debug="false"><contextName>sample</contextName><property name="log.path" value="../logs/sample" /><!--输出到控制台--><appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"><encoder><pattern>%d %contextName [%t] %level %logger{36} - %msg%n</pattern><charset>UTF-8</charset></encoder></appender><appender name="RollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender"><!-- 正在记录的日志文件的路径及文件名 --><file>${log.path}/sample.log</file><!--日志文件输出格式--><encoder><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level  %class{36} %L - %msg%n</pattern><charset>UTF-8</charset> <!-- 设置字符集 --></encoder><!-- 日志记录器的滚动策略，按日期，按大小记录 --><rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"><!-- 日志归档 --><fileNamePattern>${log.path}/%d{yyyy-MM-dd}/sample-%d{yyyy-MM-dd}.%i.log</fileNamePattern><maxFileSize>20MB</maxFileSize><maxHistory>7</maxHistory><totalSizeCap>10GB</totalSizeCap><cleanHistoryOnStart>true</cleanHistoryOnStart></rollingPolicy></appender><appender name="coolFile" class="ch.qos.logback.core.rolling.RollingFileAppender"><file>${log.path}/cool.log</file><encoder><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level  %class{36} %L - %msg%n</pattern><charset>UTF-8</charset></encoder><rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"><fileNamePattern>${log.path}/%d{yyyy-MM-dd}/cool-%d{yyyy-MM-dd}.%i.log</fileNamePattern><maxFileSize>20MB</maxFileSize><maxHistory>7</maxHistory><totalSizeCap>10GB</totalSizeCap><cleanHistoryOnStart>true</cleanHistoryOnStart></rollingPolicy></appender><logger name="o.s" level="WARN" additivity="false"><appender-ref ref="RollingFile"/></logger><logger name="log.cool" level="info" additivity="false"><appender-ref ref="STDOUT"/><appender-ref ref="coolFile"/></logger><root level="info"><appender-ref ref="STDOUT"/><appender-ref ref="RollingFile"/></root>
</configuration>

不良反应

按照上面的默认配置，然后倘若使用的window服务器，直接控制台模式运行Tomcat服务，那么日志肯定是会展示在控制台（好炫酷、好直观是不是，咱也不知道给谁看），因为在Linux服务器下，默认就是使用后台运行，不会给你一个黑框一直打印和展示日志（除非又有聪哥非得前台运行，还特意配置一下...）

那么假设此时有些代码疯狂的输出了很多日志，各种前端接受的参数输出，请求三方接口的参数输出、给前端响应之前的输出等等，总之日志量很大。那么就会发现系统偶发性的卡顿，没响应，吞吐量下降，但是服务器的CPU、内存、线程都很健康，好了，你无法给客户解释了。只能默默地说，肯定是网络抖动不骗你的~~~~

而实际上的罪魁祸首就是日志输出到了控制台，尤其是大量日志输出到控制台。但是如果你不使用工具去从代码端检测，比如arthas之类的，你就不会知道尽然是输出日志导致整个服务卡。

用事实说话

这里随便整了一个Demo，用的配置就是上面的logback的日志配置，然后简单压测，来看效果。

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;import javax.servlet.ServletException;
import javax.servlet.annotation.WebServlet;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.BufferedReader;
import java.io.FileReader;
import java.io.IOException;@WebServlet("/console/*")
public class ConsoleServlet extends HttpServlet {//模拟上面两个日志配置，输出到不同的文件而已private static final Logger log = LoggerFactory.getLogger(ConsoleServlet.class);private static final Logger log2 = LoggerFactory.getLogger("log.cool");@Overrideprotected void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {String uri = req.getRequestURI();if (uri.endsWith("root")) {logRoot();} else if (uri.endsWith("each")) {logEach();}}private void logRoot() {String content = getContent();log.info("root:{}",content);}private void logEach() {log.info("each");log2.info("each");}public String getContent() {//模拟输出大量日志，下手很重的，比如几百K到几M这种。try {try(BufferedReader br = new BufferedReader(new FileReader("C:\\m3.log"));) {StringBuilder sb = new StringBuilder();String line =null;while ((line = br.readLine())!=null) {sb.append(line);}return sb.toString();}} catch (IOException e) {throw new RuntimeException(e);}}
}

就这么简单个代码，我们配置内存-Xmx2G -Xms2G,然后启动Tomcat来进行压测，这里使用jmeter压测，

创建了两个ThreadGroup,分别请求地址http://192.168.1.10:8108/sample/console/each和http://192.168.3.36:8108/sample/console/root
每个ThreadGroup并发3、LoopCount为20，也就是每个60次。每个都创建一个Summary Report来观察结果，同时观察JVM情况，确保不是JVM资源吃紧导致卡顿
越热两次后，观察JVM的使用率各项指标平稳后，开始正式测试并观察统计结果。

两个都启动，都给控制台和文件同时输出日志时JVM就指标无异常（其他情况更无异常）：

都输出到控制台和日志文件的时的测试结果：
只输出到文件时的测试结果：

结果说明：

可以看到只要日志输出到控制台，无论是大日志本身的请求，还是其他的请求，只要使用到日志输出，都会导致耗时飙升、吞吐量下降，比只输出到日志文件满了100倍,耗时更是不忍直视，注意上面是20个/每分钟，下面是26个/每秒。

解决办法

线上尽可能使用日志级别为error，毕竟如果重要日志，肯定是要写库吧。
异步日志处理器，但会占用更多的线程、更多资源【尤其是多个异步处理器，不信你试试朋友，CPU使用率biu一下子就起来了】，同时配置队列满了照样丢失日志。即使这样输出到控制台，一样卡。
限制日志输出的字符串长度，大多日志框架都支持，比如上面的logback你可以配置%.-Nlogger。对应上面就是%.-500msg，意思是输出前500个字符，剩下都会消失哦
重要的事情一遍就要记住：不要打印大日志<<我见过直接打印word文档的，打印几十万条数据的、打印Excel所有内容的，各种奇怪的姿势>>

分享一个异步的配置，就是改造下上面，拿去测吧，效果不见得多好，吃资源哟：

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="1 hours" debug="false"><contextName>sample</contextName><property name="log.path" value="../logs/sample" /><!--输出到控制台--><appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender"><encoder><pattern>%d %contextName [%t] %level %logger{36} - %msg%n</pattern><charset>UTF-8</charset></encoder></appender><appender name="RollingFile" class="ch.qos.logback.core.rolling.RollingFileAppender"><!-- 正在记录的日志文件的路径及文件名 --><file>${log.path}/sample.log</file><!--日志文件输出格式--><encoder><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level  %class{36} %L - %msg%n</pattern><charset>UTF-8</charset> <!-- 设置字符集 --></encoder><!-- 日志记录器的滚动策略，按日期，按大小记录 --><rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"><!-- 日志归档 --><fileNamePattern>${log.path}/%d{yyyy-MM-dd}/sample-%d{yyyy-MM-dd}.%i.log</fileNamePattern><!-- each file should be at most 2MB, keep 7 days worth of history, but at most 10 GB --><maxFileSize>20MB</maxFileSize><maxHistory>7</maxHistory><totalSizeCap>10GB</totalSizeCap><cleanHistoryOnStart>true</cleanHistoryOnStart></rollingPolicy><!-- 此日志文件只记录debug级别的 --><!--<filter class="ch.qos.logback.classic.filter.LevelFilter"><level>debug</level><onMatch>ACCEPT</onMatch><onMismatch>DENY</onMismatch></filter>--></appender><appender name="coolFile" class="ch.qos.logback.core.rolling.RollingFileAppender"><file>${log.path}/cool.log</file><encoder><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level  %class{36} %L - %msg%n</pattern><charset>UTF-8</charset></encoder><rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"><fileNamePattern>${log.path}/%d{yyyy-MM-dd}/cool-%d{yyyy-MM-dd}.%i.log</fileNamePattern><maxFileSize>20MB</maxFileSize><maxHistory>7</maxHistory><totalSizeCap>10GB</totalSizeCap><cleanHistoryOnStart>true</cleanHistoryOnStart></rollingPolicy></appender><appender name="ASYNC_ROLLING" class="ch.qos.logback.classic.AsyncAppender"><queueSize>512</queueSize> <!-- 可选，队列大小 --><discardingThreshold>0</discardingThreshold> <!-- 可选，避免丢弃日志 --><includeCallerData>true</includeCallerData> <!-- 解决类名丢失 --><appender-ref ref="RollingFile"/></appender><appender name="ASYNC_COOL" class="ch.qos.logback.classic.AsyncAppender"><queueSize>512</queueSize><discardingThreshold>0</discardingThreshold><includeCallerData>true</includeCallerData><appender-ref ref="coolFile"/></appender><logger name="o.s" level="WARN" additivity="false"><appender-ref ref="RollingFile"/></logger><logger name="log.cool" level="info" additivity="false"><appender-ref ref="STDOUT"/><appender-ref ref="ASYNC_COOL"/></logger><root level="debug"><appender-ref ref="STDOUT"/><appender-ref ref="ASYNC_ROLLING"/></root>
</configuration>

原因分析

其实很简单，默认的配置都是输出到控制台ch.qos.logback.core.ConsoleAppender，这里虽然是logback，而实际上其他的日志框架也是一样的道理，默认输出到控制台，其实就等于是标准输出，也就是System.out。
这里也就是为什么很多编码规范中不允许使用System.out去输出日志是一个道理，输出控制台到线上有何作用，刷屏那么快给谁看，而且这个标准输出必然是单线程的。就和有时候发现卡机了，原因是有人上去操作服务器，把控制台用鼠标点了一下，卡在那里了（整个因为这个卡了，你就说这不是闹呢么）