[分享] :自己写的一个 UNIX 系统下的高性能 C/C++日志库 - V2EX
V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
pymumu
V2EX    C

[分享] :自己写的一个 UNIX 系统下的高性能 C/C++日志库

  •  1
     
  •   pymumu 2018-04-20 21:19:42 +08:00 5269 次点击
    这是一个创建于 2731 天前的主题,其中的信息可能已经有所发展或是发生改变。
    UNIX 环境下轻量级的 C 语言日志组件,提供了常见的日志输出接口,并日志按一定格式输出到日志文件中。
    支持日志归档,支持多线程并发写日志,多进程并发写日志,支持非阻塞日志。

    代码仅一个 C,一个头文件,方便集成使用。

    日志输出例子
    [2018-04-03 21:52:13,485][INFO][ example.c:7 ] This is a log message.

    特性
    日志压缩归档。
    日志级别输出。
    日志格式定制。
    非阻塞日志。
    多线程并发写。
    多进程并发写。

    例子
    #include <stdio.h>
    #include "tlog.h"

    int main(int argc, char *argv[])
    {
    tlog_init("./", "example.log", 1024 * 1024, 8, 1, 0, 0);
    tlog(TLOG_INFO, "This is a log message.\n");
    tlog_exit();
    return 0;
    }

    项目地址: https://github.com/pymumu/tinylog
    欢迎使用,提意见。
    第 1 条附言    2018-04-20 23:38:15 +08:00
    说明一下写这个日志模块的原因:
    因生产环境 C 代码需要日志组件,分析过 log4c, boostlog 组件。这些组件功能虽齐全,但就是体积大,占用资源多,配置步骤多,其支持的动态格式配置,其实也不会天天改。

    我们的业务有一些特别的性能需求,在高负载的情况下,直接丢弃日志,保证业务性能。所以没有选用那些组件。性能要求上,CPU 资源不能占太多,不能阻塞业务。

    所以,本着实用的原则,写了此日志模块,就两个文件,目标就是:
    避免阻塞,高性能,易用,可定制,占用资源少。

    大致技术就是:
    1. 日志写缓冲区,异步日志线程写磁盘。
    2. 异步归档压缩,压缩归档与日志写同步进行。

    之前测试过基本性能。

    树莓派这种 CPU,并发写的情况,20 万条 /秒的日志速度,单线程 2 万条 /秒的速度。
    服务器 CPU,2.6G ,30 万条 /秒日志每问题。
    耗时的其实是 sprintf 函数,localtime_r 函数,这个做了一点优化。
    特别是 localtime_r 函数,有一把全局锁,这个后面会继续优化。
    第 2 条附言    2018-04-20 23:42:32 +08:00
    还有一个需求是多进程并发写同一个日志文件。
    这个 log4c,boost 都是不支持的。

    这个也是自己写日志模块的原因。
    20 条回复    2018-04-21 16:52:54 +08:00
    laucenmi
        1
    laucenmi  
       2018-04-20 21:39:01 +08:00
    changnet
        2
    changnet  
       2018-04-20 22:09:29 +08:00 via Android
    我感觉主线程没法管理日志线程,有点失控。所以我都是自己写。
    pkookp8
        3
    pkookp8  
       2018-04-20 22:15:41 +08:00 via Android
    我用了很久的不加锁的类似代码,没有发现过两条日志互窜的现象
    neighbads
        4
    neighbads  
       2018-04-20 22:20:36 +08:00
    @pkookp8 #3 确实,之前测过,一次打很长数据多个线程只打日志才少次出现胡窜状况。所以现在都是直接写。
    pymumu
        5
    pymumu  
    OP
       2018-04-20 22:24:15 +08:00
    @changnet
    主线程处理业务就好,日志的管理由日志线程处理,日志毕竟优先级比较低,不能影响业务。
    日志一般要写磁盘的,并且还要压缩归档,如果磁盘繁忙,主线程不能因为磁盘忙阻塞的。所以需要异步日志。
    当异步模式日志缓冲区满时,就丢弃日志,保证业务。(当然是可以配置的,可以选择阻塞,不丢日志)

    正式上述原因,自己写了异步日志,上述代码已经在生产环境使用了,可以放心复用。
    pymumu
        6
    pymumu  
    OP
       2018-04-20 22:29:36 +08:00
    @pkookp8
    @neighbads
    理论上,是存在日志互相串的。在 Linux 系统,fprintf 类是由缓冲的,一般这类函数在遇到\n 才刷盘的。
    如果一次 fprintf 分了两次调用 write 写磁盘,那日志就会被拆分了。

    可以加大日志量,就会高概率出现了。

    另外,open 的时候,带 O_APPEND 标志,Linux 内核在 write 文件时,会保证原子性。
    也是基于这个原理。我写的日志模块,可以支持多进程并发写同一个文件,并保证日志不会中间截断。
    fakevam
        7
    fakevam  
       2018-04-21 02:03:36 +08:00
    1. fork 的场景下,锁怎么处理的问题
    2. 多进程场景下,所有的锁都没办法互斥了,如果是 fork 场景参考 1
    3. spinlock 的实现性能很差,如果出现大量冲突
    4. _tlog_localtime 里面加锁是有问题,不过不影响程序的稳定性

    其他还没看
    pymumu
        8
    pymumu  
    OP
       2018-04-21 08:10:14 +08:00
    @fakevam
    厉害,提到的问题都很好。
    1. 对于 fork 场景,只要多线程的进程,fork 一般都有问题,因为 fork 的是当前线程,内存又一样,fork 后如果调用原带锁的接口,极大概率死锁,大部分函数,包括 malloc,都是 fork-unsafe 的。所以目前,日志模块也并不支持 fork 出两个一模一样的带日志功能的进程。后面看看有什么好的办法,或者有什么好的建议。
    2.这里多进程指的是通过 execve 启动的进程,进程间用文件锁互斥归档,open 的时候带 O_APPEND 并行写入。
    3.spinlock 是比较简单,实现不公平,可能会饿死某些线程。单其实,tlog 格式化函数是有 mutex 锁的,这个 spinlock 其实没有意义。只是从接口完整性来讲,用 spinlock 保护了一下。另外,macOS 没有 pthread_spin_lock 锁,要不然就直接用了,不会自己写。后面优化。
    4.自己没看到问题,spinlock 锁的时候,只有赋值的时候,其他调用 API 时是解锁的,还请指点一下。
    hilow
        9
    hilow  
       2018-04-21 08:24:37 +08:00 via Android
    没考虑过 syslog 吗?
    另外 linux 在 write 文件数据为 64kb 以下(具体大小可能记得不准确)是能保证原子性的。
    hilow
        10
    hilow  
       2018-04-21 08:32:26 +08:00 via Android
    更正一下
    linux 中 append 文件时,4kb 一下的内容会保证原子性。
    https://www.notthewizard.com/2014/06/17/are-files-appends-really-atomic/
    pymumu
        11
    pymumu  
    OP
       2018-04-21 08:44:26 +08:00 via Android
    @hilow
    syslog 是个很好的日志组件,个人感觉适合记录量不大的日志,没见过大型后台服务直接写 syslog 的,或者有使用经验的话,也可以分享
    appen 原子性,我在看看内核代码
    hilow
        12
    hilow  
       2018-04-21 08:56:36 +08:00 via Android
    printf 会缓存到 4kb 才写文件,所以会快很多,但是在上层再加锁保证一致,感觉有些多此一举。
    https://superuser.com/questions/305029/why-is-syslog-so-much-slower-than-file-io
    pymumu
        13
    pymumu  
    OP
       2018-04-21 09:19:53 +08:00 via Android
    @hilow
    fprintf 直接写文件的话,遇到\n,或满 4k 的话,都会写盘的,并且硬盘繁忙的话,就会阻塞了,另外还有日志归档能力,自己写日志组件也不是没有意义的
    pymumu
        14
    pymumu  
    OP
       2018-04-21 13:15:29 +08:00
    @hilow
    你说的这个 4K 是 libc 的机制,也就是依赖这个 4K 的话,只要单次写入大于 4K,日志就会拆分。这样是会混乱的。
    并且多个文件并发写同一个文件是有会打印混乱的。

    看了下 Linux 内核代码,sys_write 的调用,写时,对 inode 是加了锁的(调用__generic_file_aio_write 的时候)。所以用 append 模式写文件,能保证原子,tlog 日志模块每次写都是保证日志完整的。
    在加上内核的这个锁,所以,tlog 日志并发写是没有问题的。你用 printf 写的话,是会有日志混乱的情况的。

    ssize_t generic_file_aio_write(struct kiocb *iocb, const struct iovec *iov,
    unsigned long nr_segs, loff_t pos)
    {
    struct file *file = iocb->ki_filp;
    struct inode *inode = file->f_mapping->host;
    ssize_t ret;

    BUG_ON(iocb->ki_pos != pos);

    mutex_lock(&inode->i_mutex); 《==此处对 inode 加锁。
    ret = __generic_file_aio_write(iocb, iov, nr_segs, &iocb->ki_pos);
    mutex_unlock(&inode->i_mutex);

    if (ret > 0 || ret == -EIOCBQUEUED) {
    ssize_t err;

    err = generic_write_sync(file, pos, ret);
    if (err < 0 && ret > 0)
    ret = err;
    }
    return ret;
    }
    EXPORT_SYMBOL(generic_file_aio_write);
    fakevam
        15
    fakevam  
       2018-04-21 13:41:28 +08:00
    @pymumu pthread_at_fork 看下,spinlock 在 busyloop 的时候需要适当插入 hlt/nop 指令, 可以提高性能,然后那个 lock 的问题,在于 2 个线程交互调度的时候,可能导致时间戳取到后者的,你还不如直接 atomic write 好了. 日志库这种轮子, 还是别自己造,如果真有需要, 直接 tls 掉,然后批量往日志里面刷减少频繁写入就好了
    pymumu
        16
    pymumu  
    OP
       2018-04-21 14:02:48 +08:00
    pymumu
        17
    pymumu  
    OP
       2018-04-21 14:20:52 +08:00
    @fakevam
    pthread_at_fork 这个只能进程本身去处理。组件的话,没法处理。多线程的进程,用 fork 后还调用原进程接口。这个本身就是危险的。对应的 malloc,也有问题,对吗。

    spinlock 那个,这个组件里面,没有用汇编,用汇编的话,就依赖硬件了。用的只是 gcc 的原子变量接口。先比 linux 内核,确实少了 nop 指令。之前用 gcc 接口的时候,也考虑过,所以代码里面时调用了 sched_yied()接口的。当然,这种改法确实没有大规模验证过

    调用 localtime_r 这个修改是因为性能问题,这里现在实际上是没有问题的,因为这个函数外面是有一把 mutex 锁的。
    性能是有一些影响,但考虑实际日志 20 万条,足够了,当前也就没有深入优化。

    后面会继续优化。

    TLS 也是解决办法,但 TLS 方案不一定比这个方案好。
    因为,TLS 每个线程都要有缓冲区,日志线程写日志时,要遍历所有线程的 TLS 缓冲区。实现不会比这个高效。

    总之,你提的意见都比较好,应该是高手了。你的建议我会考虑如何优化的。
    zhiqiang
        18
    zhiqiang  
       2018-04-21 16:20:46 +08:00
    我对这块也有需求,需求主要在于降低 log 对业务的延迟,提几个问题:

    1. 有时候程序会调用多个动态链接库,每个里面都有 log 的需求,现在这么写会不会生成多个 log 实例在同时读写?
    2. 能否避免加锁?我知道的一种方法是,log 先写到内存,然后再用一个线程写入到文件。内存多读单写,控制好 memory barrier,可以避免加锁。缺陷是程序奔溃时,可能有部分 log 没来得及写入文件,不过大多数情况下也够用了。
    3. 直接支持 log_info, log_debug 之类的写法,格式类似于 printf。

    据我所知,有做高频的交易系统的 log,单条 log 的耗时大约是 1 微妙(单线程)。
    pymumu
        19
    pymumu  
    OP
       2018-04-21 16:40:08 +08:00
    @zhiqiang
    1. 动态库的话,直接调用日志接口,由主进程初始化日志模块。应该就没有问题了
    2.目前采用的是环形队列,加锁是因为 vsnprintf 在写的时候,在调用 vsnprintf 的时候,实际上是加锁的,因为不知道结束的位置,如果要降低影响,可以搞一个日志队列,比如每个条日志固定最大 1K,缓冲几千条日志记录,应该就可以搞定,缺点就是浪费点内存,锁的话,就只锁队列添加、删除的时候了,这样就能满足业务要求了。
    3.可以用宏封装,如下。
    #define log_info(format, ...) tlog_ext(TLOG_INFO, BASE_FILE_NAME, __LINE__, __func__, 0, format, ##__VA_ARGS__)
    zhiqiang
        20
    zhiqiang  
       2018-04-21 16:52:54 +08:00
    @pymumu 我在看源代码,似乎基本上能实现我说的。对我来说,设置日志长度限制比加锁要好。我看看怎么改一下。
    关于     帮助文档     自助推广系统     博客     API     FAQ     Solana     928 人在线   最高记录 6679       Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 27ms UTC 19:13 PVG 03:13 LAX 12:13 JFK 15:13
    Do have faith in what you're doing.
    ubao snddm index pchome yahoo rakuten mypaper meadowduck bidyahoo youbao zxmzxm asda bnvcg cvbfg dfscv mmhjk xxddc yybgb zznbn ccubao uaitu acv GXCV ET GDG YH FG BCVB FJFH CBRE CBC GDG ET54 WRWR RWER WREW WRWER RWER SDG EW SF DSFSF fbbs ubao fhd dfg ewr dg df ewwr ewwr et ruyut utut dfg fgd gdfgt etg dfgt dfgd ert4 gd fgg wr 235 wer3 we vsdf sdf gdf ert xcv sdf rwer hfd dfg cvb rwf afb dfh jgh bmn lgh rty gfds cxv xcv xcs vdas fdf fgd cv sdf tert sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf sdf shasha9178 shasha9178 shasha9178 shasha9178 shasha9178 liflif2 liflif2 liflif2 liflif2 liflif2 liblib3 liblib3 liblib3 liblib3 liblib3 zhazha444 zhazha444 zhazha444 zhazha444 zhazha444 dende5 dende denden denden2 denden21 fenfen9 fenf619 fen619 fenfe9 fe619 sdf sdf sdf sdf sdf zhazh90 zhazh0 zhaa50 zha90 zh590 zho zhoz zhozh zhozho zhozho2 lislis lls95 lili95 lils5 liss9 sdf0ty987 sdft876 sdft9876 sdf09876 sd0t9876 sdf0ty98 sdf0976 sdf0ty986 sdf0ty96 sdf0t76 sdf0876 df0ty98 sf0t876 sd0ty76 sdy76 sdf76 sdf0t76 sdf0ty9 sdf0ty98 sdf0ty987 sdf0ty98 sdf6676 sdf876 sd876 sd876 sdf6 sdf6 sdf9876 sdf0t sdf06 sdf0ty9776 sdf0ty9776 sdf0ty76 sdf8876 sdf0t sd6 sdf06 s688876 sd688 sdf86