Logging | 边际效应 - 杨文博的个人博客

做后台系统比做客户端软件的辛苦的地方，就是不能让程序轻易地挂掉。因为在生产环境中无法容易地复现或调试 bug，很多时候需要程序日志提供足够的信息，所以一个后台系统的程序员必须要明白该如何打日志（logging）。

很多语言都有自己现成的 logging 库，比如 Python 标准库中的 logging 模块，Apache 的 log4cxx(C++), log4j(Java)。如果你愿意找，很容易能找到基本满足自己需求的日志程序库。当然，自己实现一个也不是很困难。难点不在于写这些库，而是如何去使用它们。

大部分情况下，我们关注的都是日志的级别和内容。即哪些情况下，该打哪个级别的日志，日志语句中，该怎么写。

在程序开发的过程中，我们需要很多的日志协助分析程序问题；但在生产环境中，我们没有那么多的空间存储丰富的日志，而且日志量太大对于问题排查反而是累赘。有些人使用预处理解决这个问题，在 debug 版本和 release 版本中编译进不同的日志语句。这样能够解决一些问题，但却使得在生产环境中无法轻易地打印更多的日志。大部分人更接受的做法是，使用配置（参数）控制日志的打印级别，在需要更多日志的时候，可以随时打开它们。为了实现日志“少但是足够”的目标，开发人员必须明白日志信息的价值，即哪些日志应该属于哪个级别。

日志的作用是提供信息，但不同的日志语句，提供的信息量却是不一样的。有的日志里会写“Failed to get sth..”，但却忘记加上失败调用的返回值。同程序一样，日志语句中有的是变量（某个变量内容），有的是常量（提示信息）。常量你总能从程序源代码中获得，但变量不行。所以在一条日志中，信息量最大的是变量，是函数返回值/字符串内容/错误码，因而变量应该尽量放在靠前的位置。常量也不是一点价值没有，写得好的提示语句，会使问题一目了然，可以免去你到代码中 grep，然后重读代码的麻烦。

上面这两点，几乎所有知道 logging 重要性的同学都会了解。但关于 logging 对性能的影响，很多人没有足够的警惕心。例如有人会在一个按行解析文件的函数中写下这样的日志：

int parseline(...)
{
log_trace("Enter parseline with ...");
DO_SOMETHING;
log_trace("Exit parseline with ...");
return 0;
}

乍一看，由于 log_trace 级别不高，在生产环境中肯定会关闭，那么这样做看起来对性能没太大影响。但实际上 log_trace 可能是这样实现的：

#define log_trace(fmt, arg...) \
    xx_log(LVL_TRACE, "[%s:%d][time:%uus]" fmt, __FILE__, __LINE__,\
           log_getussecond(), ## arg)
#endif

可以看到 log_trace 宏中自动添加了很多信息，值得注意的是时间参数 log_getussecond()。大家都知道统计时间需要系统调用，那么无论 log_getussecond() 函数是如何实现的，它的代价肯定是高于一般的简单函数。

我们本以为 log_trace 在 LVL_TRACE 级别被关闭的情况下，消耗的代价仅仅是一个函数调用和分支判断，却没有发现宏参数中还隐藏着一个需要调用系统调用的函数。当文件不大是还算能够忍受，但当这个文件是一个数据库，扫描每一行都要执行两次 log_trace() 时，它对系统性能的影响就绝不可忽视了。

所以，最佳的做法还是，在性能攸关的代码中，使用可被预处理掉的 logging 语句，仅仅在 debug 发布中才能见到这些日志，release 版本中不把它们编译进来。

此外，上面这个 log_trace，是一个糟糕的设计。logging 模块只应该干 logging 的事情，开发人员需要时间统计时会自己完成。

今天小弟在重构代码中的一个脚本模块，其中涉及到日志功能。上午花了点儿时间想出了个在 shell 打日志的技巧，觉得值得写一下。

希望要实现的效果是：实现一个 write_log 命令，给一条出错消息作为输入，write_log 记录日志时自动加上时间戳、脚本文件名和行号。形如：

2010-12-17 19:13:44 [work.sh:24] FATAL: mkdir -p /x.

时间戳、脚本文件名都好获得，但是行号就没那么容易实现了。shell 中的 $LINENO 变量只能展开成当前行的行号，如果把 write_log 实现成函数的话，势必在函数中无法使用 $LINENO。

开始我想了好大一会儿，觉得 eval 能干这个事情。但是如果用 eval 的话，还不如直接把 $LINENO 传给 write_log 函数呢，与我的初衷不是太相符。我拉来同事讨论了一把，也没解决问题。正当我准备放弃了，计划每次传 $LINENO 参数时，忽然想起来，怎么把 alias 给忘了呢？

于是，write_log 的实现就是这个样子了：

function _write_log()
{
if [ $# -eq 2 ]; then
    if [ -z $LOGFILE ]; then
      echo "$(date "+%Y-%m-%d %H:%M:%S") [$0:$1] $2"
    else
      echo "$(date "+%Y-%m-%d %H:%M:%S") [$0:$1] $2" >> $LOGFILE
    fi
elif [ $# -eq 1 ]; then
    if [ -z $LOGFILE ]; then
      echo "$(date "+%Y-%m-%d %H:%M:%S") [$0] $1"
    else
      echo "$(date "+%Y-%m-%d %H:%M:%S") [$0] $1" >> $LOGFILE
    fi
else
    return 1
fi
}
alias write_log='_write_log $LINENO' # 这里必须使用单引号

存在的问题是：上面这段代码在 bash 里是不工作的，但是用 sh 可以——即使 sh 也是链接到 bash 的。问题出在 alias 上，可以把问题简化成这样，有一个脚本 a.sh：

$ cat a.sh
alias lss='ls -l'
lss /tmp

这个脚本用 /bin/sh 执行是这样的：

$ sh a.sh 
total 8
drwx------ 2 gdm gdm 4096 2010-12-17 19:34 orbit-gdm
drwx------ 2 gdm gdm 4096 2010-12-17 11:04 pulse-PKdhtXMmr18n

用 /bin/bash 执行是这样的：

$ bash a.sh 
a.sh: line 2: lss: command not found

把 bash 随便 link 成一个叫 sh 的链接文件，再执行是类似这样的：

$ ln -s /bin/bash ~/sh
$ ~/sh a.sh 
total 8
drwx------ 2 gdm gdm 4096 2010-12-17 19:34 orbit-gdm
drwx------ 2 gdm gdm 4096 2010-12-17 11:04 pulse-PKdhtXMmr18n

这个问题肯定是有原因的，我不愿意去翻 bash 源代码，也不知道哪里去找答案，所以我放弃了，直接在文件头加上

#!/bin/sh

如果哪位兄台知道这种“奇怪”现象的原因所在，请不吝赐教 :)

标签： Logging

警惕程序日志对性能的影响

在 shell 脚本里打日志