/Ring-Log

Ring-Log是一个高效简洁的C++异步日志, 其特点是效率高(每秒支持至少125万+日志写入)、易拓展,尤其适用于频繁写日志的场景

Primary LanguageC++

Ring Log

简介

Ring Log是一个适用于C++的异步日志, 其特点是效率高(每秒支持125+万日志写入)、易拓展,尤其适用于频繁写日志的场景

效率高:建立日志缓冲区、优化UTC日志时间生成策略

易拓展:基于双向循环链表构建日志缓冲区,其中每个节点是一个小的日志缓冲区

而: 传统日志:直接走磁盘 而“基于队列的异步日志”:每写一条日志就需要通知一次后台线程,在频繁写日志的场景下通知过多,且队列内存不易拓展

对应博文见我的CSDN: http://blog.csdn.net/linkedin_38454662/article/details/72921025

工作原理

数据结构

Ring Log的缓冲区是若干个cell_buffer以双向、循环的链表组成 cell_buffer是简单的一段缓冲区,日志追加于此,带状态:

  • FREE:表示还有空间可追加日志
  • FULL:表示暂时无法追加日志,正在、或即将被持久化到磁盘;

Ring Log有两个指针:

  • Producer Ptr:生产者产生的日志向这个指针指向的cell_buffer里追加,写满后指针向前移动,指向下一个cell_bufferProducer Ptr永远表示当前日志写入哪个cell_buffer被多个生产者线程共同持有
  • Consumer Ptr:消费者把这个指针指向的cell_buffer里的日志持久化到磁盘,完成后执行向前移动,指向下一个cell_bufferConsumer Ptr永远表示哪个cell_buffer正要被持久化,仅被一个后台消费者线程持有

Alt text

起始时刻,每个cell_buffer状态均为FREE Producer PtrConsumer Ptr指向同一个cell_buffer

整个Ring Log被一个互斥锁mutex保护

大致原理

消费者

后台线程(消费者)forever loop:

  1. 上锁,检查当前Consumer Ptr
  • 如果对应cell_buffer状态为FULL,释放锁,去STEP 4
  • 否则,以1秒超时时间等待条件变量cond
  1. 再次检查当前Consumer Ptr
  • cell_buffer状态为FULL,释放锁,去STEP 4
  • 否则,如果cell_buffer无内容,则释放锁,回到STEP 1
  • 如果cell_buffer有内容,将其标记为FULL,同时Producer Ptr前进一位;
  1. 释放锁
  2. 持久化cell_buffer
  3. 重新上锁,将cell_buffer状态标记为FREE,并清空其内容;Consumer Ptr前进一位;
  4. 释放锁

生产者

  1. 上锁,检查当前Producer Ptr对应cell_buffer状态: 如果cell_buffer状态为FREE,且生剩余空间足以写入本次日志,则追加日志到cell_buffer,去STEP X
  2. 如果cell_buffer状态为FREE但是剩余空间不足了,标记其状态为FULL,然后进一步探测下一位的next_cell_buffer
  • 如果next_cell_buffer状态为FREEProducer Ptr前进一位,去STEP X
  • 如果next_cell_buffer状态为FULL,说明Consumer Ptr = next_cell_buffer,Ring Log缓冲区使用完了;则我们继续申请一个new_cell_buffer,将其插入到cell_buffernext_cell_buffer之间,并使得Producer Ptr指向此new_cell_buffer,去STEP X
  1. 如果cell_buffer状态为FULL,说明此时Consumer Ptr = cell_buffer,丢弃日志;
  2. 释放锁,如果本线程将cell_buffer状态改为FULL则通知条件变量cond

在大量日志产生的场景下,Ring Log有一定的内存拓展能力;实际使用中,为防止Ring Log缓冲区无限拓展,会限制内存总大小,当超过此内存限制时不再申请新cell_buffer而是丢弃日志

图解各场景

初始时候,Consumer PtrProducer Ptr均指向同一个空闲cell_buffer1

Alt text

然后生产者在1s内写满了cell_buffer1Producer Ptr前进,通知后台消费者线程持久化

Alt text

消费者持久化完成,重置cell_buffer1Consumer Ptr前进一位,发现指向的cell_buffer2未满,等待

Alt text

超过一秒后cell_buffer2虽有日志,但依然未满:消费者将此cell_buffer2标记为FULL强行持久化,并将Producer Ptr前进一位到cell_buffer3

Alt text

消费者在cell_buffer2的持久化上延迟过大,结果生产者都写满cell_buffer3\4\5\6,已经正在写cell_buffer1

Alt text

生产者写满写cell_buffer1,发现下一位cell_buffer2FULL,则拓展换冲区,新增new_cell_buffer

Alt text

UTC时间优化

每条日志往往都需要UTC时间:yyyy-mm-dd hh:mm:ss(PS:Ring Log提供了毫秒级别的精度) Linux系统下本地UTC时间的获取需要调用localtime函数获取年月日时分秒 在localtime调用次数较少时不会出现什么性能问题,但是写日志是一个大批量的工作,如果每条日志都调用localtime获取UTC时间,性能无法接受

在实际测试中,对于1亿条100字节日志的写入,未优化locatime函数时 RingLog写内存耗时245.41s,仅比传统日志写磁盘耗时292.58s快将近一分钟; 而在优化locatime函数后,RingLog写内存耗时79.39s,速度好几倍提升

策略

为了减少对localtime的调用,使用以下策略

RingLog使用变量_sys_acc_sec记录写上一条日志时,系统经过的秒数(从1970年起算)、使用变量_sys_acc_min记录写上一条日志时,系统经过的分钟数,并缓存写上一条日志时的年月日时分秒year、mon、day、hour、min、sec,并缓存UTC日志格式字符串

每当准备写一条日志:

  1. 调用gettimeofday获取系统经过的秒tv.tv_sec,与_sys_acc_sec比较;
  2. 如果tv.tv_sec_sys_acc_sec相等,说明此日志与上一条日志在同一秒内产生,故年月日时分秒是一样的,直接使用缓存即可;
  3. 否则,说明此日志与上一条日志不在同一秒内产生,继续检查:tv.tv_sec/60即系统经过的分钟数与_sys_acc_min比较;
  4. 如果tv.tv_sec/60_sys_acc_min相等,说明此日志与上一条日志在同一分钟内产生,故年月日时分是一样的,年月日时分 使用缓存即可,而秒sec = tv.tv_sec%60,更新缓存的秒sec,重组UTC日志格式字符串的秒部分;
  5. 否则,说明此日志与上一条日志不在同一分钟内产生,调用localtime重新获取UTC时间,并更新缓存的年月日时分秒,重组UTC日志格式字符串

小结:如此一来,localtime一分钟才会调用一次,频繁写日志几乎不会有性能损耗

性能测试

对比传统同步日志、与RingLog日志的效率(为了方便,传统同步日志以sync log表示)

1. 单线程连续写1亿条日志的效率

分别使用Sync logRing log写1亿条日志(每条日志长度为100字节)测试调用总耗时,测5次,结果如下:

方式 第1次 第2次 第3次 第4次 第5次 平均 速度/s
Sync Log 290.134s 298.466s 287.727s 285.087s 301.499s 292.583s 34.18万/s
Ring Log 79.816s 78.694s 79.489s 79.731s 79.220s 79.39s 125.96万/s

单线程运行下,Ring Log写日志效率是传统同步日志的近3.7倍,可以达到每秒127万条长为100字节的日志的写入

2、多线程各写1千万条日志的效率

分别使用Sync logRing log开5个线程各写1千万条日志(每条日志长度为100字节)测试调用总耗时,测5次,结果如下:

方式 第1次 第2次 第3次 第4次 第5次 平均 速度/s
Sync Log 141.727s 144.720s 142.653s 138.304 143.818s 142.24s 35.15万/s
Ring Log 36.896s 37.011s 38.524s 37.197s 38.034s 37.532s 133.22万/s

多线程(5线程)运行下,Ring Log写日志效率是传统同步日志的近3.8倍,可以达到每秒135.5万条长为100字节的日志的写入

2. 对server QPS的影响

现有一个Reactor模式实现的echo Server,其纯净的QPS大致为19.32万/s 现在分别使用Sync LogRing Log来测试:echo Server在每收到一个数据就调用一次日志打印下的QPS表现

对于两种方式,分别采集12次实时QPS,统计后大致结果如下:

方式 最低QPS 最高QPS 平均QPS QPS损失比
Sync Log 96891次 130068次 114251次 40.89%
Ring Log 154979次 178697次 167198次 13.46%

传统同步日志sync log使得echo Server QPS从19.32w万/s降低至11.42万/s,损失了40.89% RingLog使得echo Server QPS从19.32w万/s降低至16.72万/s,损失了13.46%

USAGE

LOG_INIT("logdir", "myapp");

LOG_ERROR("my name is %s, my number is %d", "leechanx", 3);

最后会在目录logdir下生成myapp.yyyy-mm-dd.pid.log.[n]文件名的日志

日志格式为:

[ERROR][yyyy-mm-dd hh:mm:ss.ms][pid]code.cc:line_no(function_name): my name is leechanx, my number is 3

TODO

  • 程序正常退出、异常退出,此时在buffer中缓存的日志会丢失(通过把堆内存替换为共享内存来解决,见分支NoLoseData)
  • 第N天23:59:59秒产生的日志有时会被刷写到第N+1天的日志文件中