一个因为日志功能导致进程被挂起的悲伤故事。
一、背景
该问题出现在项目的中前期，但是之前的猜想是错误的，一直以为是cpu负载导致的。熟悉uds的人，都知道uds有一个2s的P6Client超时时间，在压测刷写的时候总是有概率出现36请求超时的情况，从日志上来分析是由于uds的进程被挂起了导致的，通过各种对cpu状态的监控，发现此时cpu的负载是很高的，从而怀疑是cpu负载高导致的，进而开始了轰轰烈烈的降CPU负载之旅，udsd的cpu负载也从4%将至0%了。
然而将cpu从实车的将近100%降到了60%，在SUD前夕，上述问题居然再次出现，由于现在复现概率极其低，从070版本以后只出现过一次，猜测概率小千分之一，这次决定不再等待复现，通过理论分析推测问题原因，进而去解决问题。
二、linux日志系统
由于问题发生时，很多进程的日志都被挂起了4s左右，所以首先怀疑是日志系统的问题。
1. fprintf vs. Boost::log
我们的日志库实际上目前针对C和C++语言实现了两个不同的版本，在C语言版本中最终会调用到fprintf()，在C++语言版本中最终会调用到Boost::log。
1.1 fprintf
实际上printf()就是fprintf()的一个特化，printf()是默认打印到stdout, 但是fprintf()的第一个参数是可以选择你打印的目的地的。我们这里Tiger Log用的目的地是stderr。
1.2 Boost::log
我们再来说下Boost::log, 对于Boost::log来说，他进行了前后端分离的架构，见下图所示：
前端Front-end会接收用户端的数据，然后通过Core传输给Back-end进行目的地的打印。这样架构分离的好处是可以灵活定制化，你可以定制不同的Front-End来支持你的Log打印特性，或者你可以定制不同的Back-end来控制你的目的地，比如可以打印到数据库，可以打印到文件，可以打印到网络等等。
废话先不扯，我们这里先关注下重点，用户真正需要打交道的大多数场景下，其实是Front-end部分，Front-end实际上他有三种不同的前端：
- Sync
- Async
- Unlocked-Backend
其中我们重点关注Sync和Async：
1.2.1 Sync同步模式
Boost::log会直接把内容从前端交给后端进行打印输出，这一点其实跟fprintf()类似，他会直接调用，可以理解为是block调用
1.2.2 Async异步模式
官网解释如下
Boost::log会启动一个额外线程和Queue把用户态的内容拷贝到自己的Queue里，然后用户就不需要管了，这个时候Back-end会通过Core去这个Queue去取，这样做的好处就是用户不会被阻塞，但是打印的时间点会延后，如果用Async的架构，大概如下图所示，会有Boost自己的线程去取数据到back-end,用户端只需要把数据投递到Boost::Log的队列里就行了。
综上可以看到，如果是Async的话，Boost::log会帮我们自己去维护队列，我们不需要去担心队列满的问题。如果用的同步模式，那么理论上，这个跟直接使用fprintf()是类似的，为了确定下我们目前针对Boost::log的用法，我们直接来看下调用Boost::Log的代码。
上面的红框表示，我们在创建Boost::Log的前端sink的时候，我们这里用的是Boost::Log的同步Sync前端，如果你想用异步的版本，你需要使用的应该是asynchronous_sink<>这个wrapper. 很显然，我们这里为了不defer对应的write,都是直接用的同步写，即他没有使用Boost::log的异步功能，因此没有开辟额外的线程来做这个异步操作。从这个层面上去理解，实际上这样的使用就和fprintf()是等价的了。
1.3 结论
在不聊缓冲区之前，我们先可以下一个结论，直接fprintf()和Boost::Log()的同步模式，其实从实现上是一致的并没有太多区别。
2. 缓冲区
2.1 stdout vs. stderr
在理解完上述的fprintf()和Boost::Log()在同步模式下没有本质区别之后，我们需要再理解一下缓冲区的概念，我们需要理清stdout和stderr的区别，这两者其实都可以打印到屏幕，但是stdout和stderr还是有不同的地方，即stderr是没有缓冲区的。怎么理解这句话？让我们来看下下面的例子：
在往下看之前，先简单的给自己一个测验，请问上面的代码会输出什么？
可以看到，我们先用fprintf()打印了"Hello"到了stdout, 然后用fprintf()打印"World"到了stderr. 其实从源代码上来看，似乎对输出结果可以有一个猜测，即结果应该是Hello World. 但是结果是啥，我们来看一下：
有趣的事情发生了，输出了World! Hello, 其实原理很简单，因为stdout有缓冲区，当他有数据之后，他不会立即打印到屏幕，而stderr是没有缓冲区的概念，所以对于stderr来说，不管你给他的是什么数据，他都会立即打印到屏幕。
我们再来看一下网上对printf()的解释
这其实也印证了我们上面的结论，对于stdout他是有缓冲区的，他会出现block的情况，但是对于stderr，是立即返回并且打印到屏幕的。
2.2 结合日志的实现去理解缓冲区的影响
借着对缓冲区的理解，让我们来看下Log库的实现，让我们再回到Log中对C语言和C++语言的封装上：
C版本：
可以看到这里的fprintf()，他所用的stream就是用的stderr。
C++版本：
同样，这里的Boost::log在构造front-end的时候，用的stream流就是std::clog, clog的定义也是stderr.
相信你也看出来了，无论是C还是C++版本，用的都是stderr, 这样的好处就在于，他们对log的输出会立即打印到屏幕，不会有缓冲区的概念，很显然这个对于Log模块来说是最合适的输出的地方。
2.3 结论
因此我们可以下一个定论：
- 用了stderr, 这种不带缓冲区的fd，他可以立即打印到屏幕，因此不会像stdout一样，如果对端消费的慢的情况下，会有block点
- 结合上面所述，目前的C语言版本的Log库和C++版本的Log库(Boost::Log开的还是同步模式)，无论是从同步异步，还是从缓冲区上来看，两者是没有本质区别的，而且因为用了stderr，因此两者的打印都不会被block住
3. stderr也会block
前面我们得出结论，stderr不会有block。但是这个结论是站在用户空间是没有问题的，但是站在内核空间就不是这样了。
3.1 环境搭建
首先通过如下代码启动了几十个appLogging-service（过程不表了，i++很重要！！），并且可以通过systemd-journald和syslog写到磁盘。
#include <stdio.h>
#include "tigerLogging.h"
#include <sys/ioctl.h>
int main()
{
long i = 0;
// int opt = 1;
// ioctl(2, FIONBIO, &opt);
// int fd = fileno(stderr);
// printf("fd = %d.\n", fd);
while (1)
{
LOG_TRACE("%d %s", i++, "this is a trace message");
LOG_DEBUG("%d %s", i++, "this is a debug message");
LOG_INFO("%d %s", i++, "this is an info message");
LOG_ERROR("%d %s", i++, "this is an error message");
LOG_FATAL("%d %s", i++, "this is a fatal message");
tigerLogging_setDefaultLevel(LOG_LABEL_TRACE);
LOG_TRACE("%d %s", i++, "this is a trace message");
LOG_DEBUG("%d %s", i++, "this is a debug message");
LOG_INFO("%d %s", i++, "this is an info message");
LOG_ERROR("%d %s", i++, "this is an error message");
LOG_FATAL("%s %d", "this is a fatal message", 999);
}
}
3.2 不同app的不同表现
在高负载情况下，手动重启udsd，我们从udsd.log，我们发现在一个for循环上的相邻两个loop被挂起足足8s，红框时间为事件产生时的时间戳。同时我们查看同样时间段的、以service起来的appLogging也会被挂起6s，但是以普通进程运行的appLogging，看起来并没有受到任何影响。同时查看了can-relay、m4-agent均没有挂起现象。
图1 udsd_hang.log be hanged 8s
图2 test.service(appLogging) hang log be hanged 6s
图3 非service启动appLogging, not be hanged anymore
通过上面的现象我们可以总结如下：
- 在日志写入有延时时（高负载时），日志频繁打印的app往往也会被挂起，而日志少量产生的则不会受影响
- 以service(systemd)启动的进程容易被挂起，而非systemd启动的进程则不会受此影响。
由此我们可以得出结论，在同样io负荷下，systemd启动和非systemd启动的进程是有区别。
3.3 systemd启动和非systemd启动的进程日志差异性
通过strace我们可以看到被挂起的进程是阻塞在write()函数里。
图4 write be blocked
前面提到，无论c++还是c版的日志库，最终都是使用stderr往外输出日志，并且不是block的。这个结果有没有问题？站在用户空间来看，当然是没问题的；但是在站在内核的角度这个结论就不对了。
如下图，我们可以看到，在用户空间，stdout是有缓冲区，而stderr是没有缓冲区的，也就是: stderr = stdout+fflush。这也就是Ricky的结论。但是我们看到最终都是调用write函数，而且write函数是缓存空间的，在缓存区空间满的时候，需要调用sync()函数才能写入到io设备(磁盘、屏幕等)，如果此时标志位是SYNC的，则在缓冲区满时，write函数会block住，就是如图4的现象。--->必须推荐一本好书《Linux/UNIX 系统编程手册》,下图来自上书。
图6 用户数据如何到io设备的
通过下图分析，我们可以看到，如果是systemd起来的应用write的目的是AF_Unix socket，而其中的buffer是依赖于systemd-journald取走的，而systemd-journald的buffer又依赖于syslog-ng取走，只要从udsd->systemd-journald buffer是满的，就会阻塞住udsd，其他app同理。
而通过图6，我们可以知道，一个普通进程，如果要写数据到io设备，有write函数放到kernel buffer后，则系统会在合适的时机放入到磁盘或者屏幕输出。
所以得出结论systemd启动的进程和非systemd启动的进程在日志路径上是有区别的，并且他们受到限制是不一样的，后者更多是只受io负荷、吞吐量以及cpu负载的影响，而前者不仅受以上的影响，还受systemd-journald和syslog-ng的效率影响。这也就是在我们环境中，我们起了很多由systemd启动的进程，并且在不同的输出日志，即：io负荷、吞吐量以及cpu负载一样时，为啥图3不会挂起(快速输出到屏幕，无阻塞)，而图1、图2会被挂起的原因；同时也解释了为啥其他进程不会被挂起的原因，因为他们输出的日志很少，可以放到内核buffer上去。
system service的标准输出与标准错误都会通过socket连到journald上面
The systemd service manager invokes all service processes with standard output and standard error connected to the journal by default.This behaviour may be altered via the StandardOutput=/StandardError= unit file settings, see systemd.exec(5) for details. The journal converts the log byte stream received this way into individual log records, splitting the stream at newline ("\n", ASCII 10) and NUL bytes.
systemd-journald是单线程
它有两个瓶颈：单线程的吞吐量，syslog-ng的吞吐量（由于journald需要通过sendmsg将消息阻塞的方式发送给syslog-ng).
单线程的吞吐量: 可以通过限制systemd-journald的cpu使用率来模拟.
限制systemd-journald cpu使用率为1%.
./cpulimit -p pidof systemd-journald -l 1
从上面的实验可以看到，udsd会被阻塞了137s.
4. 解决方案
通过以上分析，知道app被挂起的原因，即：write会block，进而导致对应的block会被block住。我们知道write写入的是文件(这不是废话，linux一切都是文件！)，我们知道文件描述符，有同步和异步之分，那我们把要写入的文件描述符设置为nonblock，是不是app就不会被挂起了？？
4.1 验证
我们将appLogging的stderr设置为nonblock，再次实验。
#include <stdio.h>
#include "tigerLogging.h"
#include <sys/ioctl.h>
int main()
{
long i = 0;
int opt = 1;
ioctl(2, FIONBIO, &opt);
int fd = fileno(stderr);
printf("fd = %d.\n", fd);
while (1)
{
LOG_TRACE("%d %s", i++, "this is a trace message");
LOG_DEBUG("%d %s", i++, "this is a debug message");
LOG_INFO("%d %s", i++, "this is an info message");
LOG_ERROR("%d %s", i++, "this is an error message");
LOG_FATAL("%d %s", i++, "this is a fatal message");
tigerLogging_setDefaultLevel(LOG_LABEL_TRACE);
LOG_TRACE("%d %s", i++, "this is a trace message");
LOG_DEBUG("%d %s", i++, "this is a debug message");
LOG_INFO("%d %s", i++, "this is an info message");
LOG_ERROR("%d %s", i++, "this is an error message");
LOG_FATAL("%s %d", "this is a fatal message", 999);
}
}
图7 stderr is nonblock, no hang anymore
通过上图我们可以看出，将stderr设置为nonblock后，进程的确无挂起，但是日志会丢。因为write()会很大概率返回EAGAIN.
图8 EAGAIN error
4.2 解决方案1
回到我们这个问题本身，udsd被挂起，导致刷失败，其中一个解决方案，我们可以将stderr设为nonblock，以避免app被挂起，但是这个有一个弊端就是日志容易丢失，而我开发的是整车网关，其日志可以很好的帮助解决问题，所以这不是一个很好的解决方案。
图9 8036目前解决方案
4.3 解决方案2
前面提到了，将stderr设为nonblock有一个无法容忍的弊端，还有一个解决方案就是，我们可以在用户空间通过空间换时间的方式来解决block问题。如下图：
我们可以在用户进程和kernel之间插入一个队列进行缓冲，这样对于app来说，它的日志输出只是一个内存拷贝的过程，而队列的pop线程则是真正将日志输出的。
为了降低cpu负载率，队列是通过CAS(cahnge and swap)实现的无锁队列，通过测试发现，使用此方案对性能影响特别小。该无锁队列是通过了16线程输入(push)，16线程输出(pop)，测试了100万次，没有发现问题。
三、写在最后
udsd被挂起问题，最早可以追述到050a的版本（重构后的第一个版本），在大规模压测过程中，发现刷写bgw时有概率刷写失败，当初得出的结论是cpu负载太高，导致udsd得不到运行，进而把爱国拉进来lead了轰轰烈烈的cpu降负载话题。但是没想到问题依然在cpu负载较低，在实车刷写中发现了问题，眼看SUD在即，终于不再拿cpu负载说事了，没想到始于CPU负载，居然可能需要终于日志系统。
解决这个问题的过程得到了很多同事的协助，甚至有一些材料是来自同事。但是在解决这个问题的过程真的是挺有意思的，特别是最后发现挂起问题，居然给cpu负载无关时。
A fascinating discussion is definitely worth comment. I do think that you ought to publish more about this topic, it may not be a taboo subject but typically people dont speak about such issues. To the next! Many thanks!!
I value the article post. Really thank you! Really Great. Laverne Lupkes
There is definately a great deal to know about this issue. I like all of the points you made. Lucine Bob Brose
Thanks so much for the article post. Really looking forward to read more. Fantastic. Mathew Mcteer
Itís difficult to find knowledgeable people about this subject, but you sound like you know what youíre talking about! Thanks
Excellent, what a website it is! This blog provides useful data to us, keep it up. Rudolph Nestor
Hello very nice site!! Man .. Excellent .. Wonderful .. Giuseppe Odum
I beloved up to you will receive performed proper here. Vito Copus
I have read so many articles or reviews about the blogger lovers except this paragraph is genuinely a pleasant post, keep it up. Duane Samide
Good article. I will be dealing with many of these issues as well.. Bert Ybos
You made certain nice points there. I did a search on the subject and found most folks will go along with with your blog. Manuel Grammes
Remarkable! Its in fact awesome post, I have got much clear idea regarding from this piece of writing. Julius Busenbark
I believe you have observed some very interesting points , thanks for the post. Jae Hickley
Hello. This article was really interesting, particularly because I was investigating for thoughts on this subject last Sunday. Colby Viray
Good post. I learn something totally new and challenging on sites I stumbleupon everyday. It will always be helpful to read content from other writers and practice a little something from other websites.
אני מאוד ממליץ על אתר הזה כנסו עכשיו ותהנו ממגוון רחב של בחורות ברמה מאוד גבוהה. רק באתר ישראל נייט לאדי <a href="https://romantik69.co.il/">https://romantik69.co.il/</a>
Very nice post. I just stumbled upon your weblog and wished to mention that I have truly enjoyed
surfing around your weblog posts. In any case
I will be subscribing to your feed and I hope you write once more soon!
my website :: <a href="http://tinyurl.com/2om4cd8j">tracfone special coupon 2022</a>
I just like the valuable information you supply for your articles.
I will bookmark your blog and test once more here frequently.
I'm moderately sure I will be informed many new stuff proper right here!
Best of luck for the following!
Check out my blog: <a href="http://tinyurl.com/2nrmvvez">tracfone special coupon 2022</a>
What a information of un-ambiguity and preserveness of valuable knowledge concerning unpredicted emotions. Alberto Gowan
Please visit the internet sites we stick to, which includes this a single, as it represents our picks through the web. Tommie Lewry
Some genuinely nice and useful information on this website, likewise I conceive the layout holds superb features. Lino Elm
I evedry time emailed thios web site pokst page too all mmy associates,
becawuse if like tto read iit afterward mmy contacts wikl too.
Hi, its nice paragraph about media print, we all know media is a enormous source of data. Shane Carril
Great delivery. Great arguments. Keep up the great effort. Jacques Bockemehl
什么，linux用户进程被挂起了？ - 金宝的博客
bgrgtxwo http://www.g57h9x708098r9in1h31uk0hfwnn14vvs.org/
[url=http://www.g57h9x708098r9in1h31uk0hfwnn14vvs.org/]ubgrgtxwo[/url]
<a href="http://www.g57h9x708098r9in1h31uk0hfwnn14vvs.org/">abgrgtxwo</a>
什么，linux用户进程被挂起了？ - 金宝的博客
hpmxgdgrgi http://www.gmlpf10w4xnq3oat1w7034508gr8816ys.org/
[url=http://www.gmlpf10w4xnq3oat1w7034508gr8816ys.org/]uhpmxgdgrgi[/url]
<a href="http://www.gmlpf10w4xnq3oat1w7034508gr8816ys.org/">ahpmxgdgrgi</a>
什么，linux用户进程被挂起了？ - 金宝的博客
ikmnllnqjb http://www.gbe9xbzx0r4w7vo9690k26u0s8y6y746s.org/
[url=http://www.gbe9xbzx0r4w7vo9690k26u0s8y6y746s.org/]uikmnllnqjb[/url]
<a href="http://www.gbe9xbzx0r4w7vo9690k26u0s8y6y746s.org/">aikmnllnqjb</a>
wonderful post, very informative. I ponhder why the other experts of thius sector ddo nott notice this.
You should proceed your writing. I aam confident, you have a huge
readers' base already!
Hey! I knmow this iis kind of off topic butt I was wondering wwhich blog platform aare
yyou using for this site? I'm geetting tireed off Wordplress because I've had problsms wkth
hacfkers and I'm lookin at alternatives for another platform.
I would be awesome if you coulld point mee in the direction of a
good platform.
Hi everyone, it's my firsst go to see at this website, andd paragraph is genjuinely frujtful in favor off me, keep uup posting these types of posts.
什么，linux用户进程被挂起了？ - 汽车与it技术学习与分享
[url=http://www.gs7dyni899z25778j95ugeb3w0m302jvs.org/]ufzhmievyyn[/url]
fzhmievyyn http://www.gs7dyni899z25778j95ugeb3w0m302jvs.org/
<a href="http://www.gs7dyni899z25778j95ugeb3w0m302jvs.org/">afzhmievyyn</a>