磁盘满了对日志打印(Logback)的影响

背景

我们生产环境有一个服务半夜报警:磁盘剩余空间不足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的继承关系如下下示:

image.png

将视线聚焦到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日志框架,表现也差不多,磁盘满了也不会对应用程序本身产生影响。

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 194,088评论 5 459
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 81,715评论 2 371
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 141,361评论 0 319
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 52,099评论 1 263
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 60,987评论 4 355
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 46,063评论 1 272
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 36,486评论 3 381
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 35,175评论 0 253
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 39,440评论 1 290
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 34,518评论 2 309
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 36,305评论 1 326
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 32,190评论 3 312
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 37,550评论 3 298
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 28,880评论 0 17
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 30,152评论 1 250
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 41,451评论 2 341
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 40,637评论 2 335

推荐阅读更多精彩内容