【原创】日志输出到串口设备导致的问题

问题场景： 

      测试人员报告，业务 modb 作为 rabbitmq 的消费者，消费消息的速度非常慢，慢到大约每秒 2 条左右，从而导致 rabbitmq 的队列中积压了 4000+ 条消息。 

排查过程： 

      先通过 top 命令定位一下 

      看起来 cpu 和内存使用没有什么异常。通过 pstack 进行观察 

      发现 pid 为 8177 的 modb 调用栈确实会卡在 write() 系统调用上。对应到业务代码，则是 modb（内部链接的共享库 librabbitmq.so）中通过 fprintf 输出日志到 stderr 上的情况。 

      继续通过 strace 确认一下 

      通过 strace 发现，每次卡住的情况都发生在进行 write 系统调用时，且为向 fd 2 上输出日志信息。可以看到，输出的日志内容包括 modb 自身的日志和其所链接的 librabbitmq.so 中的日志。 

      怀疑是否因为硬盘被写满导致 ，查看系统硬盘和内存情况，发现均无异常。

      怀疑是否由于有其他业务程序写磁盘，导致 i/o 能力不够。查看发现只有 mysql 线程的磁盘写比较高，但也在合理范围内。 

      经过一番分析，发现之前的排查方向存在问题。日志输出到 stderr 上，但 stderr 却没有重定向到文件上。所以应该和磁盘 i/o 没直接关系。 

      查看下 stderr 的指向 

      结果发现，确实两个 modb 业务的 fd 0,1,2 均指向了 /dev/console 。并且系统中只有 modb 业务的 fd 0,1,2 是指向 /dev/console 的。 

那么 /dev/console 是什么呢？ 

=== 我是伪装者真好看的分隔线 ===

tty 是一类 char 设备的通称；

/dev/console 是一个虚拟的 tty ，它将映射到真正的 tty 上；

console 有多种含义，简单理解，可以认为特指 printk 输出的设备；

console 和 tty 有很大区别：console 是个只输出的设备，功能很简单，只能在内核中访问；tty 是 char 设备，可以被用户程序访问。 

实际的驱动，比如串口驱动会对物理设备（串口）注册两次，一个是 tty ，一个是 console ，并通过在 console 的结构中记录 tty 的主次设备号建立了联系。 

在内核中，tty 和 console 都可以注册多个。

当内核命令行上指定 console=ttys0 之类的参数时，首先确定了 printk 实际使用哪个 console 作为输出，其次由于 console 和 tty 之间的对应关系，打开 /dev/console 时，就会映射到相应的 tty 上。用一句话说：/dev/console 将映射到默认 console 对应的 tty 上。 

the /dev/console device is not necessarily available to you. the reason for that is because some system messages are written to the system console. for linux that device would only show any result if you happen to look at the current virtual terminal. 

from the documentation: 

/dev/tty        current tty device

/dev/console    system console

/dev/tty0       current virtual console

in the good old days /dev/console was system administrator console.  

and ttys were users' serial devices attached to a server.  

now /dev/console and /dev/tty0 represent current display and usually are the same.  

you can override it for example by adding console=ttys0 to grub.conf. after that your /dev/tty0 is a monitor and /dev/console is /dev/ttys0. 

/dev/console is a virtual set of devices which can be set as a parameter at boot time.  

it might be redirected to a serial device or a virtual console and by default points to /dev/tty0.  

/dev/tty0 is the current virtual console 

/dev/tty[1-x] is one of the virtual consoles you switch to with control-alt-f1 and so on. 

/dev/tty is the console used by the process querying it. unlike the other devices, you do not need root privileges to write to it. note also that processes like the ones launched by cron and similar batch processes have no usable /dev/tty, as they aren't associated with any. these processes have a ? in the tty column of ps -ef output.when multiple console= options are passed to the kernel, the console output will go to more than one device. 

=== 我是伪装者真好看的分隔线 === 

tty devices are among the most numerous and the most confusing of all the files in /dev. every time you log in or launch a new xterm, a tty device is assigned to the shell. this device is responsible for displaying the shell's output and providing its input. it is known as the controlling tty for that shell and its child processes. the device /dev/tty is a magic device that refers to whichever tty device is the controlling tty for that process. 

besides /dev/tty, there are three types of tty devices: consoles, serial ports and pseudo devices. 

console ttys are used when the keyboard and monitor are directly connected to the system without running the x window system. since you can have several virtual consoles, the devices are tty0 through tty63. in theory you can have 64 virtual consoles, but most people use only a few. the device /dev/console is identical to tty0 and is needed for historical reasons. if your system lets you log in on consoles 1 through 6, then when you run x windows system, x uses console 7, so you'll need /dev/tty1 through /dev/tty7 on your system. i recommend having files up through /dev/tty12. for more information on using virtual consoles, see the article keyboards, consoles and vt cruising by john fisk in the november 1996 issue of linux journal. 

      从上面的信息可以知道，/dev/console 的值和内核命令行参数设置有关。查看当前内核命令行设置，如下 

      可以看到 console=ttys0,9600n8 这个设置，意思是输出到 /dev/console 的内容，实际是发送给了串口，而串口波特率默认值为 9600 b/s 。虽然后续会调整到 115200 ，那也不过才 115 kb/s 的输出速度。 

      所以，在日志输出频繁的情况下，将导致串口输出速度达到饱和，进而卡住业务进程中的 write 系统调用，最终导致业务行为上“慢半拍”。 

虽然已经知道问题的原因了，但为什么 modb 这个业务的 fd 0,1,2 会指向 /dev/console 呢？ 

这和两方面有关： 

业务 modb 已经被添加为系统服务，所以在系统启动时会被 init 进程所启动；

系统工程师为了排查问题的方便，在 /proc/cmdline 中配置了 console=ttys0,9600n8

那么是否其他业务作为系统服务被 init 进程启动时也有这个问题呢？查看信息如下 

选择其中几个进行查看 

      可以看到，fd 0,1,2 要么被重定向到 /dev/null ，要么被重定向到文件中了。 

      好吧，这说明要想作为系统服务运行的话，还是应该“洁身自好”才行~~ 

解决办法： 

      不再将业务 modb 添加为系统服务，只通过自定义脚本控制其启动和停止。并且在启动脚本中做重定向。 

      因为自定义脚本对应的进程为 -bash 的子进程，而业务程序以常规命令行形式启动，所以 fd 0,1,2 的重定向取决于和当前业务相关的进程树中是否有重定向动作。而通常的实现方式为，在启动业务程序的时候直接通过 >/xxx/xxx.log 2>&1 的方式进行处理。 

      最后确定一下，输出的日志数据是否过大，以及是否存在由于代码编写错误导致的无用输出。结果发现，消息内容是合法的，消息体确实比较大。