logback框架之——日志分割所带来的潜在问题

• 源码：
  1. logback-test.xml文件如下，有2个需要我们重点关注的参数：
     1. fileNamePattern：这里的日志文件名变动的部分是年月日时，外加1个文件分割自增变量，警告，年月日时的数值依赖于系统时间，自增变量依赖logback框架里运行时的内存变量。
     2. maxFileSize：这里日志文件分割的条件为日志文件大小达到1M。

        <?xml version="1.0" encoding="UTF-8"?>
        <configuration>
            <appender name="testLog"
                      class="ch.qos.logback.core.rolling.RollingFileAppender">
                <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
                    <!-- 我们的日志文件名变动的部分是年月日时，外加1个分割自增变量 -->
                    <fileNamePattern>test-log.%d{yyyy-MM-dd-HH}.%i.log</fileNamePattern>
                    <!-- 保存历史文件的个数 每产生一个日志文件，该日志文件的保存期限为 7天 -->
                    <maxHistory>168</maxHistory>
                    <timeBasedFileNamingAndTriggeringPolicy
                            class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                        <maxFileSize>1MB</maxFileSize><!-- 日志文件分割的条件为日志文件大小达到1M -->
                    </timeBasedFileNamingAndTriggeringPolicy>
                </rollingPolicy>
                <encoder>
                    <!-- pattern节点，用来设置日志的输入格式 -->
                    <pattern>
                        %d{HH:mm:SSS} %p [%thread] (%file:%line\)- %m%n
                    </pattern>
                    <!-- 记录日志的编码 -->
                    <charset>UTF-8</charset>
                </encoder>
            </appender>
        
            <root level="debug">        
                <appender-ref ref="testLog" />
            </root>
        </configuration>

         

  2. 输出日志的源码如下，需要注意的是：
     1. 我们用while循环输出日志，比正常的日志输出强度高许多；
     2. 我们的日志内容是"Hello logback, line "+i。

        package demo.logback;
        
        import org.slf4j.Logger;
        import org.slf4j.LoggerFactory;
        
        public class LogFileCut {
        
          public static void main(String[] args) {
            Logger logger = LoggerFactory.getLogger("demo.logback.LogFileCut");
            int i = 0;
            while(i < 100000) {
                logger.debug("Hello logback, line ++++++ "+i);
                i++;
            }
          }
        }

         

• 根据源码：
  1. 第一步，我们现在要输出10万条日志到日志文件当中，每个文件大小为1MB，如图：
     可以看到，实际的文件大小是不确定的1142KB，1152KB，都大于1MB，最后一个日志文件因为还没有填满而小于1MB。这是我们要弄明白的第一个问题，为什么日志文件大小实际上大于我们设定的上限值？
  2. 第二步，因为我们是用main方法输出日志，我们再运行一遍就相当于服务器重启一遍，这个时候我们把日志输出内容换成，“Hello logback, line ++++++”+i。<br/运行结果如图：
     1. 先看文件数量，循环次数相同，新增的日志文件数量是6个，前面0~6个文件是第一步里运行得到的，后面的7~12是这次生成的。
     2. 对比两张图里前面7个文件0~6,6号分割文件大小发生变化我们容易理解，但是0~5这6个文件怎么都增加了，这是我们要回答的第二个问题？
• logback日志分割问题分析：
  • 第一个问题：为什么日志分割实际大小大于设定的上限值？
    • 证据：如上图。
    • 原因分析：
      • 一个日志文件分割时，有两个操作：
        1. 比较当前日志文件与设定值的大小，判断是否分割；
        2. 只要还未完成分割，持续向当前日志文件写入日志。
           当你还在比较的时候，我已经输出几百米了。。。行。。。。
      • 当判断出日志文件大小已经达到预定值的瞬间，日志文件还未进行分割，而此时日志文件仍然被写入日志。故正常情况下，日志文件的实际大小通常要大于设定值的大小。
      • 超出多少：日志文件实际超出预定值的大小size，基本上取决于判定出日志文件大小达到临界值的时间点zeroPoint以后，日志记录的写入相对于日志文件创建的速度。
      • 通常来说，日志在代码中的输出越频繁，超出临界值越多(我们这里的循环输出日志，强度是很大的)。
      • 诡谲：JIT在作祟？多次重复以上的单个步骤，观察日志分割文件大小，我们不难发现，日志文件列表的开头几个文件总是比后面的日志文件要小一些。换句话说，运行时的日志输出速度发生了变化，我猜想这里极有可能是因为while循环被JIT编译器检测到为热点代码，所以进行了再编译，从而使日志的输出速度变得更快，导致后面的日志文件更大些。
  • 第二个问题：为什么“重启”后，原本应该锁定的日志文件，再次被输入日志？
    • 证据：检查0~6号文件的末尾，我们都可以发现“Hello logback, line ++++++”+i，这段记录的存在。也就是说，“重启”之前的、按理说已经“满格”达到上限值日志文件，在“重启”后，发生了日志再次写入的问题。
    • 原因分析：
      • 日志名称：test-log.2018-08-14-13.0.log。文件名称精确到小时，我们“重启”前后，都是在同一天的13点！
        1. 日志名称的变化依赖于时间，以及分割序号，时间由操作系统决定，分割序号由logback框架决定。分割序号对应的变量值是没有持久化的！一旦重启，就只能重头开始，所以在同一个时间段(这里是同一天的同一个小时)里发生重启，不会新建日志文件，而是在原有的日志里追加记录；
        2. 第一个问题里已经说了，日所以志文件在比较的时候(还未比较完成时)，仍然在进行日志输出，所以日志文件会变大。