线上服务被干爆了!竟然是日志的锅!!

本文要介绍的是一个发生在我们线上环境的真实案例,问题发生在某次大促期间,对我们的线上集群造成了比较大的影响,这篇文章简单复盘一下这个问题。

问了方便大家理解,实际排查和解决过程可能和本文描述的并不完全一致,但是思路是一样的。

问题过程

某次大促期间,某一个线上应用突然发生大量报警,提示磁盘占用率过高,一度达到了80%多。

这种情况我们第一时间登录线上机器,查看线上机器的磁盘使用情况。使用命令:df查看磁盘占用情况。

$df
Filesystem     1K-blocks    Used Available Use% Mounted on
/               62914560 58911440 4003120  93% /
/dev/sda2       62914560 58911440 4003120   93% /home/admin

发现机器磁盘确实耗费的比较严重,因为大促期间请求量比较多,于是我们最先开始怀疑是不是日志太多了,导致磁盘耗尽。

这里插播一个背景,我们的线上机器是配置了日志的自动压缩和清理的,单个文件达到一定的大小,或者机器内容达到一定的阈值之后,就会自动触发。

但是大促当天并没有触发日志的清理,导致机器磁盘一度被耗尽。

经过排查,我们发现是应用的某一些Log文件,占用了极大的磁盘空间,并且还在不断的增大。

du -sm * | sort -nr
512 service.log.20201105193331
256 service.log
428 service.log.20201106151311
286 service.log.20201107195011
356 service.log.20201108155838

du -sm * | sort -nr :统计当前目录下文件大小,并按照大小排序

于是经过和运维同学沟通,我们决定进行紧急处理。

首先采取的手段就是手动清理日志文件,运维同学登录到服务器上面之后,手动的清理了一些不太重要的日志文件。

rm service.log.20201105193331

但是执行了清理命令之后,发现机器上面的磁盘使用率并没有减少,而且还是在不断的增加。

$df
Filesystem     1K-blocks    Used Available Use% Mounted on
/               62914560 58911440 4003120  93% /
/dev/sda2       62914560 58911440 4003120  93% /home/admin

于是我们开始排查为什么日志被删除之后,磁盘空间没有被释放,通过命令,我们查到了是有一个进程还在对文件进行读取。

lsof |grep deleted
SLS   11526  root   3r   REG   253,0 2665433605  104181296 /home/admin/****/service.log.20201205193331 (deleted)

lsof |grep deleted 的作用是:查看所有已打开文件并筛选出其中已删除状态的文件

经过排查,这个进程是一个SLS进程,在不断的从机器上读取日志内容。

SLS是阿里的一个日志服务,提供一站式提供数据收集、清洗、分析、可视化和告警功能。简单点说就是会把服务器上面的日志采集到,持久化,然后供查询、分析等。

我们线上日志都会通过SLS进行采集,所以,通过分析,我们发现磁盘空间没释放,和SLS的日志读取有关。

到这里,问题基本已经定位到了,那么我们插播一下原理,介绍一下这背后的背景知识。

背景知识

Linux系统中是通过link的数量来控制文件删除的,只有当一个文件不存在任何link的时候,这个文件才会被删除。

一般来说,每个文件都有2个link计数器:i_count 和 i_nlink,也就是说:Linux系统中只有i_nlink及i_count都为0的时候,这个文件才会真正被删除。

  • i_count表示当前文件使用者(或被调用)的数量
  • i_nlink表示介质连接的数量(硬链接的数量);
  • 可以理解为i_count是内存引用计数器,i_nlink是磁盘的引用计数器。

当一个文件被某一个进程引用时,对应i_count数就会增加;当创建文件的硬链接的时候,对应i_nlink数就会增加。

在Linux或者Unix系统中,通过rm或者文件管理器删除文件,只是将它会从文件系统的目录结构上解除链接(unlink),实际上就是减少磁盘引用计数i_nlink,但是并不会减少i_count数。

如果一个文件正在被某个进程调用,用户使用rm命令把文件"删除"了,这时候通过ls等文件管理命令就无法找到这个文件了,但是并不意味着这个文件真正的从磁盘上删除了。

因为还有一个进程在正常的执行,在向文件中读取或写入,也就是说文件其实并没有被真正的"删除",所以磁盘空间也就会一直被占用。

而我们的线上问题就是这个原理,因为有一个进程正在对日志文件进行操作,所以其实rm操作并没有将文件真正的删除,所以磁盘空间并未释放。

问题解决

在了解了线上的问题现象以及以上的相关背景知识之后,我们就可以想到办法来解决这个问题了

那就是想办法把SLS进程对这个日志文件的引用干掉,文件就可以真正的被删除,磁盘空间就能真正的被释放掉了。

kill -9 11526
$df
Filesystem     1K-blocks    Used Available Use% Mounted on
/               62914560 50331648 12582912  80% /
/dev/sda2       62914560 50331648 12582912  80% /home/admin

特别提醒下,在执行kill -9 之前,一定要考虑下执行的后果是什么

事后,我们经过复盘,发现之所以出现这样的问题,主要有两个原因

1、线上日志打印太多,太频繁
2、SLS日志拉取速度太慢

深入分析后我们发现,这个应用打印了很多过程日志,最初日志打印是为了方便排查线上的问题,或者做数据分析用的,但是大促期间日志量激增,导致磁盘空间占用极速上升。

另外,因为该应用和几个其他的大应用共用了一份SLS的project,导致SLS拉取速度被拉低,进而导致进程一直无法结束。

事后,我们也总结了一些改进项,对于第二个问题,我们对于该应用的SLS配置做拆分,独立出来进行管理。

对于第一个问题,那就是大促期间引入日志降级的策略,一旦发生磁盘爆满,就是将日志降级掉。

关于日志降级,我开发了一个通用的工具,就是通过配置的方式,动态推送日志级别,动态修改线上的日志输出级别。并且把这份配置的修改配置到我们的预案平台上,大促期间进行定时或者紧急预案处理,即可避免这个问题。

思考

每次大促之后我们复盘,都会发现其实大多数问题都是由几个不起眼的小问题堆积到一起而引发的。

在问题分析过程中往往会需要运用到很多非开发技能相关的知识,如操作系统、计算机网络、数据库、甚至硬件相关的知识。

所以我一直认为,判断一个程序员是否牛X,就看他的解决问题的能力!

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

推荐阅读更多精彩内容