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

源码:

    logback-test.xml文件如下,有2个需要我们重点关注的参数:
      fileNamePattern:这里的日志文件名变动的部分是年月日时,外加1个文件分割自增变量,警告,年月日时的数值依赖于系统时间,自增变量依赖logback框架里运行时的内存变量。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>View Code

       

    输出日志的源码如下,需要注意的是:
      我们用while循环输出日志,比正常的日志输出强度高许多;我们的日志内容是"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++; } }}View Code

       

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