【原創】日志輸出到序列槽裝置導緻的問題

問題場景： 

      測試人員報告，業務 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 的方式進行處理。 

      最後确定一下，輸出的日志資料是否過大，以及是否存在由于代碼編寫錯誤導緻的無用輸出。結果發現，消息内容是合法的，消息體确實比較大。