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

在实际工作中发现很多人喜欢将日志输出到控制台，有的甚至直接只是输出到控制台，都不输出到日志文件中。
这种操作看似人畜无害，实际上直接影响着系统的性能，很多时候还难以排查，这里我从实际举例都背后原因来分析为什么这么做并不香。

通常的日志配置

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

1. <configuration scan="true" scanPeriod="1 hours" debug="false">
2.     <contextName>sample</contextName>
3.     <property name="log.path" value="../logs/sample" />
5.    
6.    
7.         <encoder>
8.             <pattern>%d %contextName [%t] %level %logger{36} - %msg%n</pattern>
9.             <charset>UTF-8</charset>
10.         </encoder>
11.     </appender>
13.    
14.         
15.         <file>${log.path}/sample.log</file>
16.         
17.         <encoder>
18.             <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level  %class{36} %L - %msg%n</pattern>
19.             <charset>UTF-8</charset>
20.         </encoder>
21.         
22.         <rollingPolicy >
23.             
24.             <fileNamePattern>${log.path}/%d{yyyy-MM-dd}/sample-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
25.             <maxFileSize>20MB</maxFileSize>
26.             <maxHistory>7</maxHistory>
27.             <totalSizeCap>10GB</totalSizeCap>
28.             <cleanHistoryOnStart>true</cleanHistoryOnStart>
29.         </rollingPolicy>
30.     </appender>
31.    
32.         <file>${log.path}/cool.log</file>
33.         <encoder>
34.             <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level  %class{36} %L - %msg%n</pattern>
35.             <charset>UTF-8</charset>
36.         </encoder>
37.         <rollingPolicy >
38.             <fileNamePattern>${log.path}/%d{yyyy-MM-dd}/cool-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
39.             <maxFileSize>20MB</maxFileSize>
40.             <maxHistory>7</maxHistory>
41.             <totalSizeCap>10GB</totalSizeCap>
42.             <cleanHistoryOnStart>true</cleanHistoryOnStart>
43.         </rollingPolicy>
44.     </appender>
46.     <logger name="o.s" level="WARN" additivity="false">
47.         
48.     </logger>
50.     <logger name="log.cool" level="info" additivity="false">
51.         
52.         
53.     </logger>
55.     <root level="info">
56.         
57.         
58.     </root>
59. </configuration>

复制代码

不良反应

按照上面的默认配置，然后倘若使用的window服务器，直接控制台模式运行Tomcat服务，那么日志肯定是会展示在控制台（好炫酷、好直观是不是，咱也不知道给谁看），因为在Linux服务器下，默认就是使用后台运行，不会给你一个黑框一直打印和展示日志（除非又有聪哥非得前台运行，还特意配置一下...）
那么假设此时有些代码疯狂的输出了很多日志，各种前端接受的参数输出，请求三方接口的参数输出、给前端响应之前的输出等等，总之日志量很大。那么就会发现系统偶发性的卡顿，没响应，吞吐量下降，但是服务器的CPU、内存、线程都很健康，好了，你无法给客户解释了。只能默默地说，肯定是网络抖动不骗你的~~~~
而实际上的罪魁祸首就是 日志输出到了控制台，尤其是大量日志输出到控制台。但是如果你不使用工具去从代码端检测，比如arthas之类的，你就不会知道尽然是输出日志导致整个服务卡。
用事实说话

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

1. import org.slf4j.Logger;
2. import org.slf4j.LoggerFactory;
4. import javax.servlet.ServletException;
5. import javax.servlet.annotation.WebServlet;
6. import javax.servlet.http.HttpServlet;
7. import javax.servlet.http.HttpServletRequest;
8. import javax.servlet.http.HttpServletResponse;
9. import java.io.BufferedReader;
10. import java.io.FileReader;
11. import java.io.IOException;
14. @WebServlet("/console/*")
15. public class ConsoleServlet extends HttpServlet {
16.         //模拟上面两个日志配置，输出到不同的文件而已
17.     private static final Logger log = LoggerFactory.getLogger(ConsoleServlet.class);
18.     private static final Logger log2 = LoggerFactory.getLogger("log.cool");
21.     @Override
22.     protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException {
23.         String uri = req.getRequestURI();
24.         if (uri.endsWith("root")) {
25.             logRoot();
26.         } else if (uri.endsWith("each")) {
27.             logEach();
28.         }
29.     }
30.     private void logRoot() {
31.         String content = getContent();
32.         log.info("root:{}",content);
33.     }
34.     private void logEach() {
35.         log.info("each");
36.         log2.info("each");
37.     }
39.     public String getContent() {
40.         //模拟输出大量日志，下手很重的，比如几百K到几M这种。
41.         try {
42.             try(BufferedReader br = new BufferedReader(new FileReader("C:\\m3.log"));) {
43.                 StringBuilder sb = new StringBuilder();
44.                 String line =null;
45.                 while ((line = br.readLine())!=null) {
46.                     sb.append(line);
47.                 }
48.                 return sb.toString();
49.             }
50.         } catch (IOException e) {
51.             throw new RuntimeException(e);
52.         }
53.     }
54. }

复制代码

就这么简单个代码，我们配置内存-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个字符，剩下都会消失哦
  
• 重要的事情一遍就要记住：不要打印大日志
  

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

1. <?xml version="1.0" encoding="UTF-8"?>
2. <configuration scan="true" scanPeriod="1 hours" debug="false">
3.     <contextName>sample</contextName>
4.     <property name="log.path" value="../logs/sample" />
6.    
7.    
8.         <encoder>
9.             <pattern>%d %contextName [%t] %level %logger{36} - %msg%n</pattern>
10.             <charset>UTF-8</charset>
11.         </encoder>
12.     </appender>
15.    
16.         
17.         <file>${log.path}/sample.log</file>
18.         
19.         <encoder>
20.             <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level  %class{36} %L - %msg%n</pattern>
21.             <charset>UTF-8</charset>
22.         </encoder>
23.         
24.         <rollingPolicy >
25.             
26.             <fileNamePattern>${log.path}/%d{yyyy-MM-dd}/sample-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
27.             
28.             <maxFileSize>20MB</maxFileSize>
29.             <maxHistory>7</maxHistory>
30.             <totalSizeCap>10GB</totalSizeCap>
31.             <cleanHistoryOnStart>true</cleanHistoryOnStart>
32.         </rollingPolicy>
33.         
34.         
35.     </appender>
36.    
37.         <file>${log.path}/cool.log</file>
38.         <encoder>
39.             <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level  %class{36} %L - %msg%n</pattern>
40.             <charset>UTF-8</charset>
41.         </encoder>
42.         <rollingPolicy >
43.             <fileNamePattern>${log.path}/%d{yyyy-MM-dd}/cool-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
44.             <maxFileSize>20MB</maxFileSize>
45.             <maxHistory>7</maxHistory>
46.             <totalSizeCap>10GB</totalSizeCap>
47.             <cleanHistoryOnStart>true</cleanHistoryOnStart>
48.         </rollingPolicy>
49.     </appender>
51.    
52.         <queueSize>512</queueSize>
53.         <discardingThreshold>0</discardingThreshold>
54.         <includeCallerData>true</includeCallerData>
55.         
56.     </appender>
58.    
59.         <queueSize>512</queueSize>
60.         <discardingThreshold>0</discardingThreshold>
61.         <includeCallerData>true</includeCallerData>
62.         
63.     </appender>
65.     <logger name="o.s" level="WARN" additivity="false">
66.         
67.     </logger>
69.     <logger name="log.cool" level="info" additivity="false">
70.         
71.         
72.     </logger>
74.     <root level="debug">
75.         
76.         
77.     </root>
78. </configuration>

复制代码

原因分析

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

—某领导霸气的说。

来源：程序园用户自行投稿发布，如果侵权，请联系站长删除
免责声明：如果侵犯了您的权益，请联系站长，我们会及时删除侵权内容，谢谢合作！