飞凌干货-printf数据打印的归宿

罗罗诺亚

& F7 N) x; f' p' R' ?关于printf

printf是一个接口，跟UNIX标准IO的write系统调用类似，但是更像[color=inherit !important]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>
2 g6 L; n) H' F! S) N#include <stdlib.h>
" k! J9 h% z& E! D7 m" qint main(int argc, char **argv)
, q2 |. @# _' W' D{       int i = 0;        
4 f% n8 l; d5 |& l. \int c = atoi(argv[1]);
% w7 j$ g6 ]; {) x+ W        for(; i < c; i++) {               
! p/ L8 g* [$ J- H$ U. h printf("############  %d\n", i);
. _6 h$ p+ W1 P! Q6 x' ^6 S! }# i}        return 0;
' q  K- k9 Q# C* X! R& I1 W}

我先给出结果：
1.在/dev/tty1上直接执行time ./test 1000
0 V6 ^+ _4 O7 t/ P, D$ o' v... #########  995
#########  996
' ]) L2 N, {3 J1 |; k#########  997
# H+ F/ B" k4 I$ G#########  998
#########  999
- u& a6 P( r8 Z. G1 n& oreal    0m0.414s
" c3 l' N. l9 f+ Tuser    0m0.003s
0 i1 b" T4 n2 `2 x9 b) nsys     0m0.411s

2.在/dev/tty1上执行time ./test 1000 >/dev/tty2
' _& C" G& _) K6 O% ?3 D& s" Wreal    0m0.007s
user    0m0.003s
sys     0m0.007s
' l# v1 v  l  ^6 R/ t3.在SecureC[color=inherit !important]RT上执行time ./test 1000
...
#########  997
' \. @. o- _+ c, i" e5 D* O! ~#########  998
4 H2 G; l9 }0 A2 |#########  999
. |. {* O3 O2 creal    0m0.010s
" `+ @& S! A$ T% D! ?) Guser    0m0.002s
sys     0m0.003s
3 B. R; T; h2 I: q) Q
9 J0 K. N( K9 F5 ~9 B% ]在SecureCRT上执行time ./test 100000 >/dev/tty1,此时不切换tty
. F7 L. t/ P2 ?" H; V...
1 w8 e  Y6 o' w3 r' W' k等了几秒，无结果，于是在键盘按下Alt-F2，切换到第二个tty，马上显示出了结果：
1 L& y& Z4 i' w& Preal    0m4.276s
; V& r4 M- Q% u# J+ Z1 S- y2 @3 e. huser    0m0.066s
sys     0m4.204s
/ e2 r2 X0 M$ Y! d! V* t5.在tty1上执行time ./test 100000 >/dev/tty2：
real    0m0.499s
user    0m0.081s
0 \8 C$ i! [3 r$ A) q) bsys     0m0.410s
/ M; U- l9 H: `' t+ j5 m* N  K6.在tty1上执行time ./test 100000 >/dev/null
' F& f) Y; f1 ^2 t& jreal    0m0.030s
user    0m0.028s
sys     0m0.001s

通过以上的结果数据，我们可以得到以下的结论：
0 T9 w" v* e  ga.对于tty终端而言，如果当前终端不是写入的终端，那么开销主要在内核态，且开销不是很大；
b.对于tty终端而言，如果当前终端是写入的终端，那么开销主要在内核态，且开销很大；
1 H0 f3 o9 g8 o8 c6 f6 t. m0 kc.对于不管是tty还是远程的pty终端，写入/dev/null的开销主要在用户态，开销不大；
d.对于pty远程终端(/dev/pts/X)，不管写入的是不是当前的pty终端，开销主要在内核态，且开销不是很大
9 ]9 C! G, t" R; W* Je.对应上面的结果和结论，下面给出一幅图解，详细解释一下printf冰山下面的秘密：
# O; S: k9 @  d0 G4 A- G

线路规程串口举例：

简易图如下：

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

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

关于日志记录

日志记录一直都是“薛定谔猫”式的东西，因为日志记录作为一段代码，它已经是程序的一部分，不可能独立地观察程序的行为，如果说用镜像系统的话，那么这种行为就是被动的，你不得不镜像每一条指令，以发现一些关键的信息，要想主动记录关键事件，必须用日志系统。打印日志可以方便信息获取和审计，但是代价有时也是高昂的：
1.你要设计一套日志回滚系统，防止存储空间被撑爆；
2.你要让日志记录尽快完成，不能降低关键路径的性能；
3.你要反复调试代码，确保日志记录的缓冲区不会溢出；
7 u: A7 h: ~+ _$ [& z+ k5 ^+ P4.为了让日志更短，语言能力不好的人组织的日志就像电报一样难以理解。
6 P4 z6 X0 o& J/ P  N' n" W* K. @" L...
我认为，日志记录应该遵循以下的原则：

1.除非必须要把事件发生的时间记录下来，否则就用计数器代替日志记录，一系列的事件映射成一系列的计数器，由用户决定什么时候查看事件发生了。事实上，[color=inherit !important]Linux的网络子系统就是用的这种方式，所有的/proc/net/netstat就是这个查看接口。

2.一定要有一个日志级别控制选项，用户可以决定是否记录日志，以及记录的日志详细到什么程度。

tty层接口

驱动代码摘自：

lichee/linux-3.10/drivers/tty/serial/sunxi-uart.c

接收数据

static unsigned int sw_uart_handle_rx(struct sw_uart_port *sw_uport, unsigned int lsr)

{

….

tty_flip_buffer_push(&sw_uport->port.state->port);

…

}

tty_termios_baud_rate(termios)

tty_termios_encode_baud_rate(termios, baud, baud);

发送数据

land

数据看结果         
2 }9 r! d  b" B4 {; r+ m6 D