服务被干爆了！竟然是日志的锅！！

电玩女神 2022-12-28 00:54 144阅读 0赞

作者 l Hollis

来源 l Hollis（ID：hollischuang）

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

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

**问题过程**

某次大促期间，某一个线上应用突然发生大量报警，提示磁盘占用率过高，一度达到了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

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

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

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 之前，一定要考虑下执行的后果是什么**，背后原理可以参考：[我到服务器执行kill -9后，就被通知第二天别来了！][kill -9]

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

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

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

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

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

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

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

关于日志降级工具的开发思路和相关代码，下一篇文章中给大家分享。

**思考**

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

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

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

推荐阅读：

*  [推荐一款神仙颜值的 Redis 客户端工具][Redis]
 *  [腾讯 Code Review 规范出炉！你还敢乱写代码？？][Code Review]
 *  [Elasticsearch官方已支持SQL查询，用起来贼方便！][Elasticsearch_SQL]
 *  [写代码有这16个好习惯，可以减少80%非业务的bug][16_80_bug]

**![format_png][]喜欢我可以给我设为星标哦![format_png][]**

![format_png 1][]

![format_png 2][]

**好文章，我****“在看”**

![format_png 3][]

[kill -9]: http://mp.weixin.qq.com/s?__biz=MzI3NzE0NjcwMg%3D%3D&chksm=f36ba087c41c29916a572f24f2a9b21cdc7080a75261c7f662d86de558840d13cd0bc93ed1fc&idx=1&mid=2650127782&scene=21&sn=87cc02ab1484b14e0313998da527bedf#wechat_redirect
[Redis]: http://mp.weixin.qq.com/s?__biz=Mzg3MjA4MTExMw%3D%3D&chksm=cef60bbff98182a93228f6e01abd430019b48937585f922c80232d6bc6bf2161df20c07cfe6d&idx=1&mid=2247497737&scene=21&sn=0fcc5f02cf96290ccd469ebde557f16b#wechat_redirect
[Code Review]: http://mp.weixin.qq.com/s?__biz=Mzg3MjA4MTExMw%3D%3D&chksm=cef6044ff9818d59ef2db5670daa6873436205d96ebcd8ad9b94e724b3b8a13e26c5230030da&idx=2&mid=2247497721&scene=21&sn=779cab3c1ca27a4c4cb235edaca96f17#wechat_redirect
[Elasticsearch_SQL]: http://mp.weixin.qq.com/s?__biz=Mzg3MjA4MTExMw%3D%3D&chksm=cef6046cf9818d7aa9f4c60fd2a64aa7b31a5b5afb1b75299ff62d5676aebc82eba098842f3e&idx=1&mid=2247497690&scene=21&sn=03f9f27e4eccc45ef0bb1d9cb19f4df3#wechat_redirect
[16_80_bug]: http://mp.weixin.qq.com/s?__biz=Mzg3MjA4MTExMw%3D%3D&chksm=cef604ccf9818dda8885bb8889f3b84cc3363b97f69bcf065a8959f623f3ffc2f8d5fff0e16f&idx=2&mid=2247497594&scene=21&sn=f601bee0a2516b248c48e4e2513e93ce#wechat_redirect
[format_png]: /images/20221120/df51b746a8c64396bf54a5de170f04a7.png
[format_png 1]: /images/20221120/4bdceb06ebf446cd96118dae88e897da.png
[format_png 2]: /images/20221120/d2f0adf59ba24ca6839ade267d88dec6.png
[format_png 3]: /images/20221120/a72e11672ae5486fad6d15b10376df9c.png