printf的归宿-数据打印到哪儿了

3reef

近日在一次测试Linux内核路由查找算法的过程中，发现一个printf语句竟然能将性能降低2/3。当然，使用“竟然”一词并不意味着这个问题是第一次发现，我的想法是，把它记录下来，让没有经验的同学对printf知其所以然，同时导出我对“性能攸关”的这类算法中记录日志的一个观点。
声明我不会把大段的源代码贴在文章中，而只是希望能通过阐述原理把我的意思表达清楚。诚然，作为程序员没有代码好像一切都会很虚，不过同样的，也是因为代码，总是会把人逼进死胡同，代码只是一种实现，理解了原理，作为一个懂编程的程序员，任何人都可以写出一个自己的实现。
       我会给出原理图，但是这图决不是我凭空想象的，来源在哪？当然是UNIX的相关标准以及Linux的具体实现代码。既然原理来自于Linux的代码，为何不贴出来分析一下呢？要知道，代码随着Linux的内核版本，C库的版本以及应用程序的版本变化而变化，不变的是思想！UNIX历经几十年，其思想不还在指导着千千万万的程序员吗？另外，有谁会去通读Linux内核代码呢？对于大多数的人而言，如果想知道printf或者任何其它的接口的原理，肯定不会去摆开架势做出一副要先了解Linux内核架构，C库架构作为前置知识，然后去跟踪调试其实现。在以上这个过程中，你会把大量的精力消耗在理解不相关的内容上，比如函数调用关系，层层嵌套的条件语句，或者调试器怎么使用，诸如此类。
关于printfprintf是一个接口，跟UNIX标准IO的write系统调用类似，但是更像C库的fwrite，因为同系列的函数中还有一个fprintf(至于同系列其它的函数，请自行man)。printf和fwrite的区别在于两点：
1.它可以格式化输出，如果用fwrite，它接受的是一个固定的buffer，你不得不在调fwrite之前先使用sprintf之类的函数格式化buffer；
2.它免除了你的fopen-fwrite-fclose这个序列的调用，因为它直接将格式化的内容写入UNIX进程自然打开的1号文件描述符，即标准输出。
既然printf写入了标准输出，那么接下来就要定义什么是标准输出。在早期UNIX年代，人们在终端或者伪终端操作机器，那时的输入基本都是键盘，磁带更古老的东西，而输出就是一个计算结果，需要展示出来给人看的那种，一般为终端屏幕，也可以是一条纸带，那么程序怎么知道输入和输出到底是什么呢？这就需要程序明确指定。UNIX的“一切皆文件”思想以及“分离抽象”思想彻底改变了这一切。
       UNIX定义了抽象文件描述符0，1，2分别为标准输入，标准输出，标准错误输出。至于它们到底对应什么设备，你可以在程序初始化的时候显式重定向到任意设备，也可以在外部shell做类似的重定向，这样就把指明设备这件事从程序分离了出来。
       我为什么不统一说一下fwrite调用对程序性能的影响呢？因为该调用之前你必须执行fopen，而fopen的一个参数明确表示了你希望写入的对象是什么，这就不会带来异议，毕竟如果你非要在性能测试的时候写CF卡，那也是你愿意。printf就不同了，它对效率的影响取决于标准输出是什么以及你是如何重定向标准输出的，所谓的标准输出并不是真实的设备，它只是一个抽象层，具体如何解释标准输出，还要依靠外部。
数据都去哪儿了我以下面这个超级小的程序来说明printf的时候，数据都去哪了：
#include <stdio.h>
#include <stdlib.h>


int main(int argc, char **argv)
{
        int i = 0;
        int c = atoi(argv[1]);
        for(; i < c; i++) {
                printf("############  %d\n", i);
        }
        return 0;
}
我先给出结果：
1.在/dev/tty1上直接执行time ./test 1000
...
#########  995
#########  996
#########  997
#########  998
#########  999

real    0m0.414s
user    0m0.003s
sys     0m0.411s
2.在/dev/tty1上执行time ./test 1000 >/dev/tty2
real    0m0.007s
user    0m0.003s
sys     0m0.007s
3.在SecureCRT上执行time ./test 1000
...
#########  997
#########  998
#########  999

real    0m0.010s
user    0m0.002s
sys     0m0.003s
4.在SecureCRT上执行time ./test 100000 >/dev/tty1,此时不切换tty
...
等了几秒，无结果，于是在键盘按下Alt-F2，切换到第二个tty，马上显示出了结果：
real    0m4.276s
user    0m0.066s
sys     0m4.204s
5.在tty1上执行time ./test 100000 >/dev/tty2：
real    0m0.499s
user    0m0.081s
sys     0m0.410s
6.在tty1上执行time ./test 100000 >/dev/null
real    0m0.030s
user    0m0.028s
sys     0m0.001s
通过以上的结果数据，我们可以得到以下的结论：
a.对于tty终端而言，如果当前终端不是写入的终端，那么开销主要在内核态，且开销不是很大；
b.对于tty终端而言，如果当前终端是写入的终端，那么开销主要在内核态，且开销很大；
c.对于不管是tty还是远程的pty终端，写入/dev/null的开销主要在用户态，开销不大；
d.对于pty远程终端(/dev/pts/X)，不管写入的是不是当前的pty终端，开销主要在内核态，且开销不是很大
e.

对应上面的结果和结论，下面给出一幅图解，详细解释一下printf冰山下面的秘密：

我想上图已经很清楚了，如果不懂什么叫行规程(也叫线路规程)的话，请阅读《UNIX环境高级编程》的终端和伪终端章节，简单来说，它就是一个中间层，用来适配VFS接口和底层的具体驱动，比如解释和处理控制字符等。从上面的图中，我们可以看出，主要的开销几乎都集中在底层，而底层却偏偏是我们不能控制或者很难控制的。之所以上面的测试例子中ssh登录的终端对test性能的测试效果良好，但是那是因为网络环境好，你在一个64kbps相隔5k公里的线路上试一下。

       小小的printf下面竟然藏着如此多的内容，并且很可能就是它成了你的程序的性能瓶颈，因为最底层的影响因素往往是不可控的。那么是不是就是意味着我要建议大家从来不用printf打印呢？或者说干脆就不要用标准输出呢？并不是这样。但是为何不把打印这种事交给本机的另一个进程呢？事实上，几乎所有的需要记录日志的系统都是这么做的，而syslog则迎合了这个思想。这种思想的背后就是“用可控制的一次IPC替换不可控制冰山之下的茫茫深海”

关于日志记录日志记录一直都是“薛定谔猫”式的东西，因为日志记录作为一段代码，它已经是程序的一部分，不可能独立地观察程序的行为，如果说用镜像系统的话，那么这种行为就是被动的，你不得不镜像每一条指令，以发现一些关键的信息，要想主动记录关键事件，必须用日志系统。打印日志可以方便信息获取和审计，但是代价有时也是高昂的：
1.你要设计一套日志回滚系统，防止存储空间被撑爆；
2.你要让日志记录尽快完成，不能降低关键路径的性能；
3.你要反复调试代码，确保日志记录的缓冲区不会溢出；
4.为了让日志更短，语言能力不好的人组织的日志就像电报一样难以理解。
...
我认为，日志记录应该遵循以下的原则：
1.除非必须要把事件发生的时间记录下来，否则就用计数器代替日志记录，一系列的事件映射成一系列的计数器，由用户决定什么时候查看事件发生了。事实上，Linux的网络子系统就是用的这种方式，所有的/proc/net/netstat就是这个查看接口。
2.一定要有一个日志级别控制选项，用户可以决定是否记录日志，以及记录的日志详细到什么程度。