LOG_EVERY_N 如何实现

每个 LOG_EVERY_N() 都会生成一个 std::atomic 全局内部对象 counter,用 counter 来计数。

实际上为了避免直接取模,glog 实现用了另外一个变量利用减法来做 wrap

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
#define LOG_EVERY_N(severity, n)                                        \
SOME_KIND_OF_LOG_EVERY_N(severity, (n), google::LogMessage::SendToLog)

#define SOME_KIND_OF_LOG_EVERY_N(severity, n, what_to_do) \
static std::atomic<int> LOG_OCCURRENCES(0), LOG_OCCURRENCES_MOD_N(0); \
GLOG_IFDEF_THREAD_SANITIZER(AnnotateBenignRaceSized(__FILE__, __LINE__, &LOG_OCCURRENCES, sizeof(int), "")); \
GLOG_IFDEF_THREAD_SANITIZER(AnnotateBenignRaceSized(__FILE__, __LINE__, &LOG_OCCURRENCES_MOD_N, sizeof(int), "")); \
++LOG_OCCURRENCES; \
if (++LOG_OCCURRENCES_MOD_N > n) LOG_OCCURRENCES_MOD_N -= n; \
if (LOG_OCCURRENCES_MOD_N == 1) \
google::LogMessage( \
__FILE__, __LINE__, google::GLOG_ ## severity, LOG_OCCURRENCES, \
&what_to_do).stream()

// Use macro expansion to create, for each use of LOG_EVERY_N(), static
// variables with the __LINE__ expansion as part of the variable name.
#define LOG_EVERY_N_VARNAME(base, line) LOG_EVERY_N_VARNAME_CONCAT(base, line)
#define LOG_EVERY_N_VARNAME_CONCAT(base, line) base ## line

#define LOG_OCCURRENCES LOG_EVERY_N_VARNAME(occurrences_, __LINE__)
#define LOG_OCCURRENCES_MOD_N LOG_EVERY_N_VARNAME(occurrences_mod_n_, __LINE__)

LOG_OCCURRENCES(0) 宏展开之后就是

1
static std::atomic<int> occurrences_$LINE(0)

所以那个 0 其实是 counter 初始值。


再来看为啥要搞两个 counter 变量。

首先这种情况下会调用的 LogMessage 构造函数是

1
2
3
4
5
6
LogMessage::LogMessage(const char* file, int line, LogSeverity severity,
int64 ctr, void (LogMessage::*send_method)())
: allocated_(NULL) {
Init(file, line, severity, send_method);
data_->stream_.set_ctr(ctr);
}

额外的操作是为 LogStream 保存了当前的 counter。

而这个 counter 的作用就是当用户向知道这条日志消息目前的总 counter 数,即 google::COUNTER 时通过 steam 输出的

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
// LOG_EVERY_N(INFO, 10) << "Got the " << google::COUNTER << "th cookie";

// We want the special COUNTER value available for LOG_EVERY_X()'ed messages
enum PRIVATE_Counter {COUNTER};

// Output the COUNTER value. This is only valid if ostream is a
// LogStream.
ostream& operator<<(ostream &os, const PRIVATE_Counter&) {
#ifdef DISABLE_RTTI
LogMessage::LogStream *log = static_cast<LogMessage::LogStream*>(&os);
#else
LogMessage::LogStream *log = dynamic_cast<LogMessage::LogStream*>(&os);
#endif
CHECK(log && log == log->self())
<< "You must not use COUNTER with non-glog ostream";
os << log->ctr();
return os;
}

Raw Logging

针对那些底层模块无法使用普通 LOG 宏的场景,代码在 glog/raw_logging.h 中;区别在于

  • 不会在堆上分配内存
  • 只会往 stderr 写日志并且不带 buffering
  • 不用锁
  • 自动截断过长的消息
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
#define RAW_LOG(severity, ...) \
do { \
switch (google::GLOG_ ## severity) { \
case 0: \
RAW_LOG_INFO(__VA_ARGS__); \
break; \
case 1: \
RAW_LOG_WARNING(__VA_ARGS__); \
break; \
case 2: \
RAW_LOG_ERROR(__VA_ARGS__); \
break; \
case 3: \
RAW_LOG_FATAL(__VA_ARGS__); \
break; \
default: \
break; \
} \
} while (0)

#define RAW_LOG_INFO(...) google::RawLog__(google::GLOG_INFO, \
__FILE__, __LINE__, __VA_ARGS__)

类似的手法,不过这回是直接调用 RawLog__() 这个函数。

DoRawLog() 封装了 vsnprintf(),可以往一个给定的 buffer 写入格式化字符串;buffer 就是一个局部数组,大小是 3000。

写操作用系统调用直接往 stderr 的 fd 写,目的是避开 crt 这一层内部的 buffering。

Syslog

和前面的 LOG 的流程类似,只不过这回 send method 是 SendToSyslogAndLog()

这个 method 核心

  • 调用 openlog() 设置往 syslog 的连接
  • syslog() 写日志

Automatically Remove Old Logs

核心是利用 LogCleaner 全局对象

1
2
3
4
5
6
7
void EnableLogCleaner(unsigned int overdue_days) {
log_cleaner.Enable(overdue_days);
}

void DisableLogCleaner() {
log_cleaner.Disable();
}

LogFileObject::Write() 最后执行清理

1
2
3
4
5
6
// Remove old logs
if (log_cleaner.enabled()) {
log_cleaner.Run(base_filename_selected_,
base_filename_,
filename_extension_);
}

Run() 其实就是

  1. 遍历每个 log directory
  2. 在 directory 中找到找到属于当前进程的日志文件,并且这个文件已经 overdue 了,塞到 overdue file list 中
  3. 然后对每个文件逐一删除(调用 unlink()

Crash/Signal Handler

现代一些的 Linux 发行版都支持 sigaction,所以 glog 这里也就强制要求用这个来完成 signal handler 安装。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
void InstallFailureSignalHandler() {
#ifdef HAVE_SIGACTION
// Build the sigaction struct.
struct sigaction sig_action;
memset(&sig_action, 0, sizeof(sig_action));
sigemptyset(&sig_action.sa_mask);
sig_action.sa_flags |= SA_SIGINFO;
sig_action.sa_sigaction = &FailureSignalHandler;

for (size_t i = 0; i < ARRAYSIZE(kFailureSignals); ++i) {
CHECK_ERR(sigaction(kFailureSignals[i].number, &sig_action, NULL));
}
kFailureSignalHandlerInstalled = true;
#elif defined(GLOG_OS_WINDOWS)
for (size_t i = 0; i < ARRAYSIZE(kFailureSignals); ++i) {
CHECK_NE(signal(kFailureSignals[i].number, &FailureSignalHandler),
SIG_ERR);
}
kFailureSignalHandlerInstalled = true;
#endif // HAVE_SIGACTION
}

const struct {
int number;
const char *name;
} kFailureSignals[] = {
{ SIGSEGV, "SIGSEGV" },
{ SIGILL, "SIGILL" },
{ SIGFPE, "SIGFPE" },
{ SIGABRT, "SIGABRT" },
#if !defined(GLOG_OS_WINDOWS)
{ SIGBUS, "SIGBUS" },
#endif
{ SIGTERM, "SIGTERM" },
};

在多线程环境下,可能会有多个线程同时触发 signal handler,比如

  • 虽然某些 signal 只会发给 calling thread,但是架不住多个线程(多核下)并行同时触发
  • 触发了发给所有 thread 的 handler (不过我怀疑安装了 handler 的 signal 没有这样的…)

所以 glog 进入 signal handler 之后首先要检查自己是否是第一个,用的是 CAS 指令,并且

  • 如果自己不是第一个,则无限 sleep;也就是等待第一个处理的线程完成 dumping
  • 如果自己是第一个线程并且发生了重入,这种情况是严重错误,所以立即调用默认的 handler 挂掉
  • 如果真的是第一个,那就开始 dump。

dumping 过程包含

  1. dump RIP 所在的栈/符号信息,这里用的 ucontext 并且只针对 Linux
  2. dump signal 自身信息
  3. dump stacktrace

不同平台/环境下 stacktrace 获取方法还不一样,这里 Linux 上推荐的是安装 libunwind 之后走 libunwind 的实现,最靠谱。

glibc 的实现(也即 backtrace() )很容易死锁

还有 libgcc/llvm 提供的 _Unwind_Backtrace

Windows 上就省事多了,直接 CaptureStackBackTrace()