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

[pymumu]

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
欢迎使用，提意见。

说明一下写这个日志模块的原因：
因生产环境 C 代码需要日志组件，分析过 log4c, boostlog 组件。这些组件功能虽齐全，但就是体积大，占用资源多，配置步骤多，其支持的动态格式配置，其实也不会天天改。

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

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

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

之前测试过基本性能。

树莓派这种 CPU，并发写的情况，20 万条 /秒的日志速度，单线程 2 万条 /秒的速度。
服务器 CPU，2.6G ，30 万条 /秒日志每问题。
耗时的其实是 sprintf 函数，localtime_r 函数，这个做了一点优化。
特别是 localtime_r 函数，有一把全局锁，这个后面会继续优化。

还有一个需求是多进程并发写同一个日志文件。
这个 log4c，boost 都是不支持的。

这个也是自己写日志模块的原因。

[laucenmi]

赞

[changnet]

我感觉主线程没法管理日志线程，有点失控。所以我都是自己写。

[pkookp8]

我用了很久的不加锁的类似代码，没有发现过两条日志互窜的现象

[neighbads]

@pkookp8 #3 确实，之前测过，一次打很长数据多个线程只打日志才少次出现胡窜状况。所以现在都是直接写。

[pymumu]

@changnet
主线程处理业务就好，日志的管理由日志线程处理，日志毕竟优先级比较低，不能影响业务。
日志一般要写磁盘的，并且还要压缩归档，如果磁盘繁忙，主线程不能因为磁盘忙阻塞的。所以需要异步日志。
当异步模式日志缓冲区满时，就丢弃日志，保证业务。（当然是可以配置的，可以选择阻塞，不丢日志）

正式上述原因，自己写了异步日志，上述代码已经在生产环境使用了，可以放心复用。

[pymumu]

@pkookp8
@neighbads
理论上，是存在日志互相串的。在 Linux 系统，fprintf 类是由缓冲的，一般这类函数在遇到\n 才刷盘的。
如果一次 fprintf 分了两次调用 write 写磁盘，那日志就会被拆分了。

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

另外，open 的时候，带 O_APPEND 标志，Linux 内核在 write 文件时，会保证原子性。
也是基于这个原理。我写的日志模块，可以支持多进程并发写同一个文件，并保证日志不会中间截断。

[fakevam]

1. fork 的场景下，锁怎么处理的问题
2. 多进程场景下，所有的锁都没办法互斥了，如果是 fork 场景参考 1
3. spinlock 的实现性能很差，如果出现大量冲突
4. _tlog_localtime 里面加锁是有问题，不过不影响程序的稳定性

其他还没看

[pymumu]

@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]

没考虑过 syslog 吗？
另外 linux 在 write 文件数据为 64kb 以下（具体大小可能记得不准确）是能保证原子性的。

[hilow]

更正一下
linux 中 append 文件时，4kb 一下的内容会保证原子性。
https://www.notthewizard.com/2014/06/17/are-files-appends-really-atomic/

[pymumu]

@hilow
syslog 是个很好的日志组件,个人感觉适合记录量不大的日志，没见过大型后台服务直接写 syslog 的，或者有使用经验的话，也可以分享
appen 原子性,我在看看内核代码

[hilow]

printf 会缓存到 4kb 才写文件，所以会快很多，但是在上层再加锁保证一致，感觉有些多此一举。
https://superuser.com/questions/305029/why-is-syslog-so-much-slower-than-file-io

[pymumu]

@hilow
fprintf 直接写文件的话，遇到\n,或满 4k 的话，都会写盘的，并且硬盘繁忙的话，就会阻塞了，另外还有日志归档能力，自己写日志组件也不是没有意义的

[pymumu]

@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]

@pymumu pthread_at_fork 看下,spinlock 在 busyloop 的时候需要适当插入 hlt/nop 指令, 可以提高性能,然后那个 lock 的问题,在于 2 个线程交互调度的时候,可能导致时间戳取到后者的,你还不如直接 atomic write 好了. 日志库这种轮子, 还是别自己造,如果真有需要, 直接 tls 掉,然后批量往日志里面刷减少频繁写入就好了

[pymumu]

@fakevam

[pymumu]

@fakevam
pthread_at_fork 这个只能进程本身去处理。组件的话，没法处理。多线程的进程，用 fork 后还调用原进程接口。这个本身就是危险的。对应的 malloc，也有问题，对吗。

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

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

后面会继续优化。

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

总之，你提的意见都比较好，应该是高手了。你的建议我会考虑如何优化的。

[zhiqiang]

我对这块也有需求，需求主要在于降低 log 对业务的延迟，提几个问题：

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

据我所知，有做高频的交易系统的 log，单条 log 的耗时大约是 1 微妙（单线程）。

[pymumu]

@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]

@pymumu 我在看源代码，似乎基本上能实现我说的。对我来说，设置日志长度限制比加锁要好。我看看怎么改一下。