第5章 高效的多线程日志

日志有两个意思:

  • 诊断日志(diagnostic log)   即 log4j、 logback、 slf4j、 glog、 g2log、 log4cxx、 log4cpp、 log4cplus、 Pantheios、 ezlogger 等 常用 日志 库 提供 的 日志 功能。
  • 交易 日志( transaction log)   即 数据库 的 write- ahead log1、 文件 系统 的 journaling2 等, 用于 记录 状态 变更, 通过 回 放 日志 可以 逐步 恢复 每一 次 修改 之后 的 状态。
1. 功能需求

常规的通用日志库如log4j13/ logback14 通常会提供丰富的功能,但这些功能不一定全都是必需的。

  1. 日志 消息 有多 种 级别( level), 如 TRACE、 DEBUG、 INFO、 WARN、 ERROR、 FATAL 等。
  2. 日志 消息 可能有 多个 目的地( appender), 如 文件、 socket、 SMTP 等。
  3. 日志 消息 的 格式 可 配置( layout), 例如 org. apache. log4j. PatternLayout。 4. 可以 设置 运行时 过滤器( filter), 控制 不同 组件 的 日志 消息 的 级别 和 目的地。

在上面 这 几项 中, 我 认为 除了 第一 项 之外, 其余 三项 都是 非 必需 的 功能。

日志 的 输出 级别 在 运行时 可调, 这样 同一个 可执行 文件 可以分 别在 QA 测试 环境 的 时候 输出 DEBUG 级别 的 日志, 在 生产 环境 输出 INFO 级别 的 日志。 在必 要的 时候 也可以 临 时在 线 调整 日志 的 输出 级别。

例如 某台 机器 的 消息 量过 大、 日志 文件 太多、 磁盘 空间 紧张, 那么 可以 临时 调整 为 WARNING 级别 输出, 减少 日志 数目。 又比 如 某个 新 上 线 的 进程 的 行为 略显古怪,则可以来临时调整为DEBUG级别输出,打印更细节的日志消息一遍分析查错。调整日志的输出级别不需要重新翻译,也不需要重启进程,主要调用muduo::Logger::setLogLevel()就能即时生效。

有几个简单的技巧:

  • 对于分布式系统中的服务进程而言,日志的目的地只有一个:本地文件。
  • 以本地文件为日志的destination,那么日志文件的滚动是必须的,这样可以简化日志的归档的实现。
  • 日志文件压缩与归档不是日志库应有的功能,而应该交给专门的脚本去做,这样C++和Java的服务程序就可以共享这一基础设施。如果想更改日志压缩算法或归档策略也不必动业务程序。

往文件写日志的一个常见问题就是,万一程序崩溃,那么最后若干条日志往往就丢失了,因为日志库不能每条信息都flush硬盘,更不能每条日志都open/close文件,这样开销太大。muduo采用的做法是:

  • 定期(默认3s)将缓冲区内的日志消息flush到硬盘;
  • 每条内存中的消息都带有cookie,其值为某个函数的地址,这样通过在core dump文件中查找cookie就能找到尚未来得及写入磁盘的消息。

日志消息的格式主要有以下几个要素:

  • 尽量每条日志都占一行;
  • 时间戳精确到微秒
  • 始终使用GTM时区
  • 打印线程id
  • 打印日志级别
  • 打印源文件名和行号
2. 性能需求

高效性体现在几方面:

  • 每秒写几千上万条日志的时候没有明显的性能损失;
  • 能应对一个进程产生大量的日志数据的场景;
  • 不阻塞正常的执行流程;
  • 在多线程程序中,不造成争用;
  • 磁盘带宽约是110MB/s,日志库应该能瞬间写满这个带宽;
  • 假设每条日志消息的平均长度是110个字节,这个意味着1s要写100万条日志。
3. 多线程异步日志

多线程程序对日志库提出了新的需求:线程安全,即多个线程可以并发写日志,两个线程的日志消息不会出现交织。

线程安全不难办到,简单的办法就是用一个全局的mutex保护IO,活着每个线程单独写一个日志文件,这两种做法会损失高效性。前者会造成全部线程抢一个锁,后者有可能让业务线程阻塞在写磁盘操作上。

一个多线的程序的每个进程最好只写一个日志文件,这样分析日志更方便。再说多线程写多个文件也不一定能够提速。解决办法可以用一个背景线程负责收集日志消息,并写入日志文件,其他业务线程只管往这个“日志线程”发送日志消息,这称为“异步日志”。

在多线程服务程序中,异步日志是必须的,因为如果在网络IO线程或业务线程中直接往磁盘写数据的话,写操作偶尔可能阻塞长达数秒之久。这可能导致请求方超时,活着耽误发送心跳消息,在分布式系统中更可能造成多米诺骨牌效应,例如误报死锁引发自动failover等。因此,正常的实时业务处理中,应该彻底避免磁盘IO,这里使用one loop per thread模型的非阻塞服务程序中尤为重要。

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

推荐阅读更多精彩内容