磁盘满了对日志打印(Logback)的影响_linux空间满了导致日志不打印怎么办

CSDN博客 · · 634 次点击 · · 开始浏览    
这是一个创建于 的文章,其中的信息可能已经有所发展或是发生改变。

背景

我们生产环境有一个服务半夜报警:磁盘剩余空间不足10%,请及时处理。排查后发现是新上线的一个功能,日志打太多导致的,解决方法有很多,就不赘述了。领导担心报警不及时、或者报警遗漏,担心磁盘满了对线上业务有负面影响,甚至不可用,令我研究一下该情况下对服务的影响。

正文

注:我们线上的应用使用Logback日志框架进行打印,所以log4j、log4j2或其它日志框架不在本次研究的范围。

实验研究

实验步骤

  1. 启动服务,观察各项指标正常(模拟正常工作的服务以及环境状态)
  2. 将磁盘写满
  3. 观察应用服务、宿主机各项指标,查看服务响应是否正常(包括功能以及性能)
  4. 将大文件删除(恢复)
  5. 重复第3步

实验过程

第1、3、5步重在观测,不赘述。

第2步的模拟磁盘写满,使用linux的fallocate命令。

将磁盘写满的方式如下有几种:

  1. 自己写文件,写满为止,速度较慢,有开发(写脚本)成本
  2. 使用dd命令,但是比较慢,取决于磁盘的速度
  3. 使用truncate命令,但是该命令操作的结果并不占用实际的磁盘空间
  4. 使用fallocate命令,fallocate -l {size} {fileName},如fallocate -l 20G text1

我选择了方式4,很快就写满了磁盘

验证方式:vim {xxx},进入文件编辑,写入任意内容,保存失败并提示:Can’t open file for writing(No space left on device)

实验结果

  1. 磁盘写满前、后,应用服务各项指标均正常(功能、性能)
  2. 磁盘写满后,服务器磁盘空间报警(无可用空间),删除文件后报警恢复
  3. 磁盘写满后,应用日志停止打印,删除文件后应用日志恢复打印

即,磁盘满了对于使用logback日志框架的应用,并不会造成影响。

实验结果令人诧异,按正常理解,磁盘满了之后再写入,会报No space left on device异常,进而影响到应用程序的功能。

原理分析

logback配置文件里的文件appender如下(RollingFileAppender同理):

<appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>${LOG_HOME}/${APP_NAME}.log</file>
    <encoder>
        <pattern>%d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
</appender>

把关注点放到appender即可,因为最终的日志输出是由appender控制的:它控制写在哪个文件里,格式是怎样的,滚动策略又是怎样的。

通过IDEA查看RollingFileAppender的继承关系如下下示:

在这里插入图片描述

将视线聚焦到ch.qos.logback.core.OutputStreamAppender#writeBytes,代码如下:

private void writeBytes(byte[] byteArray) throws IOException {
    if(byteArray == null || byteArray.length == 0)
        return;
    
    lock.lock();
    try {
        this.outputStream.write(byteArray);
        if (immediateFlush) {
            this.outputStream.flush();
        }
    } finally {
        lock.unlock();
    }
}

由上可知,写日志时会加锁,避免资源竞争,然后通过outputStream写出,接着马上刷盘(默认情况)。

这里的outputStream可了不得,是个ResilientFileOutputStream实例,顾名思议,【弹性的】FileOutputStream。它是个子类,核心逻辑在父类ResilientOutputStreamBase上,看看write方法:

public void write(byte b[], int off, int len) {
    if (isPresumedInError()) {
        if (!recoveryCoordinator.isTooSoon()) {
            attemptRecovery();
        }
        return; // return regardless of the success of the recovery attempt
    }

    try {
        os.write(b, off, len);
        postSuccessfulWrite();
    } catch (IOException e) {
        postIOFailure(e);
    }
}

这个write方法隐藏着【即使磁盘满了也不影响业务】的秘密!它的核心逻辑是:如果能正常写文件,就写;如果写入失败(出现了IO异常),就抓住异常并切换至失败状态,接下来的一段时间都不再继续写文件,直接返回。

而此处所有的IO异常,就包含了No space left on device,因此,此处便是磁盘满了之后继续日志写入,却不会抛出No space left on device异常进而影响业务的原因。

还有一个问题,待磁盘有剩余空间后,如何恢复日志写入?上面实验结果提到,磁盘写满后,应用日志停止打印,删除文件后应用日志恢复打印。因此必然会有一个策略,能够在磁盘空间恢复后,继续进行日志写入。

再仔细查看看write方法,方法首先判断当前状态是否为“失败”。若是,接着检查自上次失败至今的时间。如果已经经过了很长时间,就【尝试恢复】。

void attemptRecovery() {
    try {
        close();
    } catch (IOException e) {
    }

    addStatusIfCountNotOverLimit(new InfoStatus("Attempting to recover from IO failure on " + getDescription(), this));

    // subsequent writes must always be in append mode
    try {
        os = openNewOutputStream();
        presumedClean = true;
    } catch (IOException e) {
        addStatusIfCountNotOverLimit(new ErrorStatus("Failed to open " + getDescription(), this, e));
    }
}

尝试恢复的逻辑是:关闭旧文件流并重新打开文件流,将【失败】状态切换至【半恢复】状态,此处并未完全进入【正常】状态,而是立即返回,即是说当次的日志记录请求并不会写文件。

下次的日志写入,才会尝试将日志写入文件

  • 若日志成功写入文件,就将状态切换至【正常】状态。
  • 若日志写入文件失败,就将状态切换至【失败】状态。

此处的失败以及恢复逻辑非常像Hystrix断路器,即经历一个正常→失败→半通路状态,通过下次请求的结果来决定是恢复正常还是保持失败。

上面提到若经过很长时间,就尝试恢复,这里的【很长时间】其实是一个泛指,它有自己的时间计算逻辑,此处采用了类似于RocketMQ在消费失败时的重试策略,即采用指数退避逻辑来控制重试时间间隔。

每次【半恢复】状态下写文件失败时,会保持【失败】状态,且每一次的失败写入都会指数级延长【失败】状态保持的时间。

public boolean isTooSoon() {
    long now = getCurrentTime();
    if (now > next) {
        next = now + getBackoffCoefficient();
        return false;
    } else {
        return true;
    }
}
private long getBackoffCoefficient() {
    long currentCoeff = backOffCoefficient;
    if (backOffCoefficient < BACKOFF_COEFFICIENT_MAX) {
        backOffCoefficient *= BACKOFF_MULTIPLIER;
    }
    return currentCoeff;
}

backOffCoefficient初始值:20

BACKOFF_COEFFICIENT_MAX:327680

BACKOFF_MULTIPLIER:4

总结

使用Logback日志框架,当磁盘满了后不必惊慌,它不会对应用程序产生太负面影响。仔细考虑,做为一个日志框架本该如此,不能因为写不了日志就抛出异常进而影响应用本身,毕竟,日志终究是个辅助的旁路逻辑,没有它应用也应该work well。

底层知识的掌握有助于迅速理解上层应用。在阅读源码的过程中,我发现了非常熟悉的设计逻辑:即类似于Hystrix的断路器和RocketMQ消费失败重试的策略。由于之前有相关经验,因此我很快就能够理解作者的设计意图。

注:事后我测试了一下Log4j2日志框架,表现也差不多,磁盘满了也不会对应用程序本身产生影响。

634 次点击  
加入收藏 微博
暂无回复
添加一条新回复 (您需要 登录 后才能回复 没有账号 ?)
  • 请尽量让自己的回复能够对别人有帮助
  • 支持 Markdown 格式, **粗体**、~~删除线~~、`单行代码`
  • 支持 @ 本站用户;支持表情(输入 : 提示),见 Emoji cheat sheet
  • 图片支持拖拽、截图粘贴等方式上传