排查一例多线程服务的 crash

最近我们线上一个收集日志的服务运行不是很稳定,由于和我负责的服务有关,于是排查的任务就交给了我。

服务架构

首先介绍一下这个服务的前后接口。这个服务,我们内部叫做 LogWatcher,用来处理线上的一些日志。开发人员在调试线上服务的时候,经常需要打印调试日志,由于线上机器很多,开发不可能到真实机器上去看日志,因此我们的系统会把开发的调试日志从各个线上服务器实时的发送到一台日志存储机器上,LogWatcher 就工作在这台日志存储机器上,它本身会通过 Linux 系统的 inotify 监控调试日志文件,当有新的调试日志写入到日志文件后,会把这些日志解析,然后写入到 Mysql 中,此后我们会通过 sphinx 生成日志索引,给开发提供一个实时查看调试日志的系统。

LogWatcher 架构

LogWatcher 的架构如上图:main 线程负责进行 inotify 监控,监控到日志文件变动后,会把文件信息当做一个任务发送到 processor 线程。实际工作中,日志文件有多个,processor 线程也会有多个,main 线程会建立一个文件名和 processor 线程的 hash 映射,把任务发送给对应的处理线程。

故障现象

LogWatcher 出现的问题,主要有三点:

  1. 调试日志的系统有延迟,开发人员没办法实时的查看自己的调试日志。
  2. 有时候调试日志会丢失,开发人员找不到自己对应的调试日志。
  3. 运维也发现 LogWatcher 进程有时会 crash(1天左右)。

第一次排查

我简单看了下 LogWatcher 自身的日志,发现 main 线程向 processor 线程传入 task 的队列有积压,因此怀疑线上日志变多,导致 processor 线程处理不过来。那么应该可以通过增加 processor 线程数解决问题,于是,我把 processor 的线程数调大了1倍(50 -> 100)。

调大进程数并没有解决延迟的问题,队列依然积压,而且 crash 的频率还变高了,很奇怪。由于日志缺少我关心的信息,所以我开始边分析代码,边增加日志信息。

由于多线程架构,打印日志是个麻烦的任务,因此 LogWatcher 采用了一种简单的办法:每个线程单独打开一个独立的日志文件,分别记录日志,这样每个线程互不影响,不容易出问题。但这里的实现出现了 bug。

LogWatcher 把 processor 线程实现为一个类,这个类包括一个任务队列,一个处理日志、写数据库的函数,既然这个类是一个单独线程,那么这个类的对象,理所当然都会有一个自己的日志文件了,但是这里有个问题,main 线程会往 processor 的任务队列中发送任务,发送任务实际是调用 procesor 的 pushTask 函数,这个函数运行在 main 线程中,按照设计思路,如果 pushTask 函数要打印日志,需要打印到 main 线程的日志文件中,可实际上却没有,pushTask 直接使用了 processor 类的日志输出方法,把日志打印到了 processor 线程的日志中,此时两个线程同时写一个文件,导致了 crash。

一般日志文件都需要有切割的功能,比如一个小时切割成一个文件,这个过程可以简化为如下代码:

void WriteLog(log) {
if (HourChange(now)) {
     close(fd);
}
if (IsNotOpen(fd)) {
     open(fd);
}
print(fd, log);
}

假如 A、B 线程同时执行到了 close 这一行,就出现 fd 被 close 了两回的现象,这个问题叫做资源双重释放,是个未定义的操作,一般情况就是 crash。通过 core 文件的堆栈,可以验证我们的猜测,堆栈信息显示 crash 发生在 close 这一行。

分析出问题的原因,我选择把 LogWatcher 的日志全部替换成 glog,尝试修复 crash。glog这是一个 google 开源的日志库,能够处理多线程的日志输出问题。

第二次排查

使用 glog 上线以后,crash 没有了,但是调试日志缺失的问题还存在。这次我通过 gdb attach 到 LogWatcher 的进程上,看了现场,发现有多个 processor 线程死锁了,由于 main 线程是分别和每个 processor 线程建立队列,传输任务,那么一个 processor 线程死锁,这部分的日志就无法写到数据库,也就出现了部分日志丢失的问题。那么问题的原因呢?

排查发现,processor 使用了 pthread_mutex_t 处理队列的竞争,因为 main 线程和 processor 线程都会操作队列,一个 pushTask,一个 popTask,因此需要一个锁,来解决竞争,但是代码中使用 pthread_mutex_t 时,却忘了初始化,这导致可能 processor 类初始化的时候,锁就已经处于锁住的状态,自然也就死锁了。这个问题也是很好修复的。

第三次排查

初始化的问题上线后,部分日志缺失的问题解决了,那么还有没有日志延迟的问题呢?我们写了一个监控,分析日志生成时间和写入 Mysql 的时间延迟,分析发现还是有很大的延迟,此时我们怀疑 processor 写数据库是会一个瓶颈,因为日志量很大,一次写操作通常会写几十上百条日志,这可能是系统的瓶颈,那么,需要验证一下,我在 processor 的 doTask 函数中,增加了一些打印时间的信息,同时,在发现队列积压的时候,也通过 gdb attach去看线程在做什么,这次发现很多线程都卡在了一个系统调用mktime上,反而,记录的写 Mysql 耗时也并不是很长。

一般日志文件中都会有个肉眼可读的时间字符串,用于记录日志时间,但是写入到数据库中,我们可能需要统计一段时间的日志数量,此时这个字符串就不好处理了,那么就需要转成 unix timestamp,这个过程会用到 mktime,从现象来看,这个函数的内部实现一定是使用了锁,才导致各个线程频发调用这个函数时出现了竞争,解决这个问题可以自己实现一个字符串转 timestamp 的无锁方法,网上有现成的算法。我采取了一个取巧的办法,就是加缓存。日志的输出往往都是一秒中之内有大量日志写入,因此我在 processor 中增加一个成员变量,记录上一次日志中的时间串,和对应的 timestamp 值,如果当前日志的时间串和上次一样,就直接使用保存的值,不需要调用 mktime 函数了,修改上线好,延迟问题就解决了。

尾声

这次上线以后,LogWatcher 的问题基本解决完了,正好组里希望大家做一些 case study,我觉得这次 LogWatcher 的问题,虽然现象很严重,但最后发现都是一些小问题,问题的原因容易理解,很适合用来学习排查问题的思路和方法,因此做下记录,希望大家能从中学到一些分析问题的方法,自己有所提高。

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

推荐阅读更多精彩内容