Setup a AQI(Air Quality Index) Monitoring System with Dylos and Raspberry Pi 2

I have been using air purifier for years in Beijing, China. So far so good except the only problem troubles me, is that effective? is my PM2.5 or PM10 reduced? the answer is probably obvious, but how effectively is it? Nobody knows.

At the morment, Dylos is the only manufacturer that provides consumer level product with accurate air quality index, so, not many choice. I got a Dylos air quality counter from Amazon, there are many products, if you want to export the index data from the black box into your desktop for later process , you'll need at least a DC 1100 pro with PC interface or higher version. Strongly not recommend buying from Taobao or the similar online stores, as far as I saw, None of them can provide the correct version, most of them exaggerate for a higher sale.

Now, half done. You need to Raspberry Pi, at the time of writing, Raspberry Pi 2 is coming to the market. I got a complete starter kit with a Pi 2 Model B, Clear Case, power supply, WiFi Dongle and a 8GB Micro SD.

In order to make the Raspberry Pi up, it's better to find a screen monitoring, or it will take huge pain to you.

After turning Dylos and Raspberry Pi on, the left process is quite simple. You need to connect the Dylos and Raspberry Pi with a serial to USB interface, the serial to USB cable is uncommon these days, if you are a network engineer, you should be quite familir with the cable, else, you can get one from online or somewhere else.

Now, write a tiny program to read the data from Dylos. You can make use of Python's pyserial module to read the data with a few lines. Here is mine. Besides that, you can use other language to implement, such as PHP. The interval depends on your Dylos collecting data interval, the minimum is 60s, ususally 3600s is enough.

Once got the data, you can feed them into different metric systems like Munin, or you can feed them into highcharts to get a more pretty look.

stdio 的 buffer 问题

下面会涉及到一些底层的函数库以及系统调用,不想看过程的直接跳到最后看结论好了。
一段代码,通过 tail -f 看打的 log,发现很长时间都没有输出,然后突然一下子输出了好多条,猜想可能跟 buffer 之类的有关系。这个问题其实很早就遇到过,最初以为是什么 bug,直到看到自己写的代码也出现类似的现象之后才决定看看是怎么回事。
先来看看下面这一小段代码。

$ cat demo1.py
import time, sys
for i in range(50):
  sys.stdout.write("test")
  time.sleep(0.2)

$ python demo1.py
testtesttesttesttesttes……ttesttesttesttesttesttesttesttesttesttesttesttesttesttesttesttesttest$
可以看到,这堆 test 字符串是等了若干秒之后一下子输出的。

如果我们把 sys.stdout.write("test") 改为 sys.stdout.write("test\n") 即加上换行符号,或者使用 print 函数来输出,发现现象不一样了:
$ cat demo2.py
import time, sys
for i in range(50):
  sys.stdout.write("test\n")
  time.sleep(0.2)

$ python demo2.py
test
test
test
test
test

$ cat demo3.py
import time, sys
for i in range(50):
  print "test"
  time.sleep(0.2)

发现不管是 demo2 还是 demo3,屏幕上均以平均 0.2s 的频率输出 test 字符。
把 demo3 的 print "test" 换成 print "test",(结尾加一个半角逗号)再看看是什么现象。
再用 python3 的 print("test") 试试,尝试加上 end 参数比如,print("test", end="\n"), print("test", end="\t"),print("test", end="") 再试试有什么不同的结果。

再来看一个 demo:
$ cat demo4.py
import time, sys
for i in range(50):
  sys.stdout.write("test")
  sys.stdout.flush()
  time.sleep(0.2)

加上 sys.stdout.flush() 看看跟上面的比有什么不同的效果。

最后一个,代码是 demo3.py,但是运行的方式不同:
$ python demo3.py > output
注意实时观察 output 文件的大小,发现并没有随时间而增大,而是 demo3.py 运行结束了之后才变化的。


上面就是之前遇到的一些现象,这里面涉及到其实是 UNIX 下面的 STDIO buffer 问题。下面会深入现象揭开本质,没时间的看最后的结论即可。

IOS C 标准定义了一套叫标准 I/O 的库,也叫 buffered I/O,这套库被包括 UNIX 在内的系统所实现,包括我们日常使用的众多发行版本。而大家熟知的 open, read, write, lseek, close 这些 I/O 系统调用函数则是 POSIX 定义的,他们通常称为 unbuffered I/O,就是为了跟标准 I/O 库作出区分。这些底层的系统调用函数,大多都是围绕 fd 展开,而标准 I/O 则是围绕着 STREAM 展开,标准 I/O 库其实可以理解为对系统 I/O 函数的封装,因为标准 I/O 库最终还是要调用对应的这些系统 I/O 函数,可以通过 fileno(FILE *FP) 获取到 STREAM 对应的 fd。
为什么说标准 I/O 库是 buffered I/O 了,因为他会自动的帮你处理 buffer 分配以及 I/O chunks 的选择,这样就不再需要为选择 block size 而操心了,这个在使用系统 I/O 调用的时候无法避免,比如 read/write 都需要考虑 buffer 地址以及读取写入的 buffer size,通常你需要在调用 read 时候定义一个 buffer size 的宏:
# define BUFFSIZE 4096

buffered I/O 的主要目的就是为了降低 read/write 这类的系统调用以及自动的为程序分配 buffer。但是他分为了下面三种类似的 buffering:
1. full buffer,当标准 I/O buffer 满了时候发生一次 flush 操作,可以调用 fflush() 来完成,他将 buffer 里面的数据 flush 到内核缓冲区中。
2. line buffer,遇到换行符(一般就是 "\n") 也就是写完一行的时候发生一次 flush,
3. unbuffered,有多少读写多少。

Linux 一般是这样实现的:
1. stderr 是 unbuffered,这会让错误信息及时的出现。
2. stdin/stdout stream 如果不跟终端相关联,比如 pipe,redirect,fopen 打开的文件,则是 full buffer;如果跟终端相关联,则是 line buffer
上面这两条规则其实就是速度跟系统之间的一个 tradoff,很好理解。

可以通过 setbuf/setvbuf 来修改 buffer 的模式,具体的使用方式 man 2,需要注意的是,这两个函数要在 stream 打开之后其余 I/O 操作之前调用,让然,如果你需要做一些特殊的事情,完全可以在昨晚某些 I/O 操作之后再调用,比如下面要举的第二个 demo。setvbuf 比 setbuf 有更大的优势,比如可以修改 buffer 的大小等等。

关于 STREM 对应的 buffer 类型,其大小可以通过这段代码来做一个验证,比如我的机器的几个 buffer size 都是 8KB。

而 int fflush(FILE *fp) 这个函数就是解决我们上面问题的核心了,该函数会将当前 STREAM 中的数据 flush 到内核缓冲区,如果 fp 是 NULL,则 stdout 流被 flush 一次。准确的说,fflush 只能用于输出流,而不能用于输入流,具体的原因见这里
这里的一个 demo 很好的解释了 fflush/setvbuf 做的事情,尝试把 setvbuf 中的 size_t size 参数从原先的 1024 调小到 20 试试看。
很明显,通过这种 buffer 的方式,把一部分的写先 buffer 起来然后统一调用一次系统调用,可以大量的减少 user space 跟 kernel space 之间的切换。

可能会有人想到 fsync 这个系统调用,它跟 fflush 做的事情好像是一样的,其实仔细辨别的,二者做的事情根本不在一个平面上
fflush(FILE *stream) 作用的是 FILE*,对于 stdout 来说,他是将标准 IO 流的 buffer 从用户空间 flush 到内核缓存中。这也是调用 exit 要做的事情。
fsync(int fd) 控制的是何时将 data&metadata 从内核缓冲区 flush 到磁盘中,他的传入参数是一个 fd。对 fsync 来说,FILE* 是透明的也就是所他并不知道 FILE* 的存在,一个是在 user space 一个是在 kernel space。

所以,如果我们不想有 full/line buffer 而是尽可能快的获取到输出流的话,就需要通过调用 fflush(stdout) 指明。

上面解释的仅仅是 C 的,对于 Python 而言,底层调用的东西几乎一样,Python 它自己通过 C 实现了 fflush(),具体的代码可以看这里。其实不单单是 fflush,不少包括 read/write 在内的底层调用 Python 都是用 C 实现的。
对用到 Python 的 fflush 则是 sys.stdout.flush()。

不管是 fflush() 还是 sys.stdout.flush(),都需要对立即返回的 stdout 手动的调用,比较麻烦。所幸的,上面提到的 setvbuf 就可以直接帮我们做这件事,在 stream 打开后调用 setvbuf() 即可,其 mode 参数可以选择下面三种:
1. _IOLBF,line buffer
2. _IOFBF, full buffer
3. _IONBF,no buffer
要完全禁用的话按照下面这种方式调用:
setvbuf(stdout, 0, _INNBF, 0);

对应到 python 的,至少还有下面的几种方式可以避免此类问题:
1. 直接关闭 stdout 的 buffer,类似 setvbuf:
sys.stdout = os.fdopen(sys.stdout.fileno(), 'w', 0)

2. 有个比较 ugly 的方式,把输出流改到 stderr 上,这样不管什么时候都能保证尽快的输出。

3. 直接脚本的时候加上 -u 参数。但是需要注意下,xreadlines(), readlines() 包含一个内部 buffer,不受 -u 影响,因此如果通过 stdin 来遍历会出现问题,可以看看这两个连接提供的内容(1, 2)。

4. 将其 stream 关联到 pseudo terminal(pty) 上,script 可以做这事情的:
script -q -c "command1" /dev/null | command2
或者通过 socat 这个工具实现,

再来看个跟 pipe 相关的问题, 这个命令常常回车之后没有反应:
$ tail -f logfile | grep "foo" | awk {print $1}

tail 的 stdout buffer 默认会做 full buffer,由于加上了 -f,表示会调用 fflush() 对输出流进行 flush,所以 tail -f 这部分没什么问题。关键在 grep 的 stdout buffer,因此它存在一个 8KB stdout buffer,要等该 buffer 满了之后 awk 才会接收到数据。awk 的 stdout buffer 跟终端相关联,所有默认是 line buffer。怎么解决这个问题了,其实 grep 提供了 –line-buffered 这个选项来做 line buffer,这会比 full buffer 快的多:
tail -f logfile | grep –line-buffered  "foo" | awk {print $1}

除了 grep,sed 有对应的 -u(–unbuffered),awk(我们默认的是 mawk) 有 -W 选项,tcpdump 有 -l 选项来将 full buffer 变成 line 或者 no buffer。

不仅仅是 stdin/stdout/stderr 有 buffer 问题,pipe 同样有 buffer 的问题,相关的文档可以看这里(1, 2)。

上面的方式都涉及到了具体的函数调用,修改参数的不具有普遍原理,对于普通用户来说,不大可能这么操作。其实 coreutils 已经给我们提供了一个叫 stdbuf 的工具。expect 还提供了一个叫 unbuffer 的工具,通过它可以将输出流的 buffer 给禁止掉,另外,在 pipe 的应用中,可能会出现一些问题,具体的 man 一下。因此,上面的问题可以更具有普遍性:
tail -f logfile | stdbuf -oL grep "foo" | awk {print $1}

看到这里最上面的几个问题现在应该非常容易回答了。

ref:
http://www.pixelbeat.org/programming/stdio_buffering/
http://stackoverflow.com/questions/16780908/understanding-the-need-of-fflush-and-problems-associated-with-it
http://stackoverflow.com/questions/23334147/misunderstand-line-buffer-in-unix
http://mywiki.wooledge.org/BashFAQ/009

resolv.conf 的超时(timeout)与重试(attempts)机制

/etc/resolv.conf 有两个默认的值至关重要,一个是超时的 timeout,一个是重试的 attempts,默认情况下,前者是 5s 后者是 2 次。
这个估计很多工程师都不是很在意,一般情况下,使用默认的值倒没什么大问题,特殊情况我会在最后说明。

要测试,不要使用 dig, host, nslook 这类工具,因为他们并没有调用 resolver 的库,可以使用 getent 来测试。上面提到的只是一些诊断的工具,对于日常的应用来说,包括 web server、mail client、db 以及各种 app server 等等,任何使用 glibc resolver 都需要经过 resolv.conf 文件。

对于 libresolv 来说,只认 resolv.conf 的前三个 nameserver,所以写的再多也没什么意义。正常情况下,resolver 会从上至下进行解析,每个 nameserver 等待 timeout 的时间,如果一直到第三个都没结果,resolver 会重复上面的步骤 (attempts – 1) 次。

为了真正理解,例如下面这个场景:
search test.example.com example.com  
nameserver 192.168.0.1  
nameserver 192.168.0.2

假设 192.168.0.1 不返回结果(可能根本就不是台 DNS),我们假设需要解析 "www.devel",而这个仅仅在 www.devel.example.com 里面有记录,下面是整个执行的步骤:
1. "www.devel" on 192.168.0.1, wait until timeout (default 5 secs)
2. "www.devel" on 192.168.0.2, get reply: no such hostname
3. "www.devel" on 192.168.0.1, wait until timeout (default 5 secs)
4. "www.devel" on 192.168.0.2, get reply: no such hostname
5. "www.devel.test.example.com" on 192.168.0.1, wait until timeout (default 5 secs)
6. "www.devel.test.example.com" on 192.168.0.2, reply no such hostname
7. "www.devel.test.example.com" on 192.168.0.1, wait until timeout (default 5 secs)
8. "www.devel.test.example.com" on 192.168.0.2, reply no such hostname
9. "www.devel.example.com" on 192.168.0.1, wait until timeout (default 5 secs)
10. "www.devel.example.com" on 192.168.0.2, reply with IP address

默认情况下是 5s 超时,我做了两个简单的测试,把 resolv.conf 的前三个 nameserver 全部换成不存在的 1.1.1.1, 2.2.2.2, 3.3.3.3,然后可以观察下面 strace 跟踪的结果,对于 ping 以及 getent 来说,已经算是上层的应用结果了。
1. strace -t getent hosts baidu.com
2. strace ping baidu.com

把 timeout 设置为 1s 的结果可以看下面这个测试结果:
strace -t ping baidu.com(options timeout:1)

对于生产有什么意义了?
对于任何的代码,不管何种形式的(HTTP 的也好,DB 的连接也罢),只要是一端对另外一端的连接,都应该加上超时重试以及异常处理的。上面其实一共涉及三个点:
1. 超时,目前绝大多数的 API 都支持这类参数,包括我们线上用的 grequestsMySQLdb 等等
2. 重试,对于代码层面同样重要,跟上面类似
3. 异常处理,好的代码对于无法连接或者连接超时等问题应该及时的抛出异常打 log,而不是什么都没有,否则会加大问题定位的工作量,后期维护起来也会异常的麻烦。

这里有个有意思的脚本能检测最佳的 DNS。

最后,记得 dig, nslook 只会解析 resolv.conf 的内容,而不会解析 hosts 里面内容,所以如果想让 dig 解析 hosts 里面的内容,可以通过 dnsmasq 实现。

ref:
https://access.redhat.com/solutions/21420
http://serverfault.com/questions/562079/adjusting-how-long-linux-takes-to-fail-over-to-backup-dns-server-listed-in-resol

一个月的艰辛稳定服务过程

业务大了成本问题更加的凸显,最重要的之一就是带宽,为了更好的优化资源,我们决定将目前 BGP 全线的流量切换一部分到双线上去。说白了很简单,网络方面不需要动什么大手脚,全网 10G 的链路半年之前就全部升级完毕,剩下的就是加前端,10G 服务器,LVS(nat), Keepalived,Nginx。接下来就是小流量的上线测试,从 10M 到 50M 到 100M 再到 300M 前后大概有一周的观察时间,整体还是很稳定的,当然也遇到了一些小问题,比如 10G 网卡不规则的出现了一些 rx_crc_errors/rx_missed_errors,通过优化一些硬件设备基本得到了解决,虽然后期还会时不时的冒出一些,但是从各个服务以及业务的监控方面没有看到潜在的影响,暂时略过。

正所谓稳定压倒一切,从开始小流量切换到正式全量上线的这一个月,为了稳定,充满了坎坷,下面是这一段时间遇到的一些比较有挑战的事件, 「很不幸的是」,全部是人为原因。

4xx 错误飙升
一周之后的某个早上收到报警,4xx, 5xx 的错误上升了大概一倍的样子:

可以确认的是这段时间没有任何的变更,从到后端的请求来看,这段时间的异常并没有对其有很大的影响,但是本着负责任的态度还是把当时的 log 归档拿出来分析了下详情:

可以看到,这段时间的 return code 主要是由 499 以及 500 错误引起,并且 499 的错误占了大部分的,那就从 499 的分析开始。G 了一番,发现这个 code 并非是一个标准的 RFC,唯一可以确认的就是是客户端主动的关闭了链接,至于是什么原因让客户端主动关闭的,原因就太多了。除此之外,还有一部分的稳定的 408 错误,这个比较好理解,对于由于 Nginx 读取客户端发来的请求会造成超时而返回 408。
看了上面的解释,基本得不到很明确的答案。接下来,至少还可以从 debug log 以及 error log 入手,看看能否得到一些信息。
首先看看 error log,关于 Nginx 的 access, error log 不少人都有误解,这里统一说明一下:
1. access log 的非 2xx 错误只有部分的会打到 err log 里面,仅仅是部分,而 access log 是所有的 return code 的集合
2. error log 并非是一些非 2xx code 的集合,里面很多都是开发定制的一些东西,代码都是写死的
3. 所以,任何的返回码(2xx, 4xx, 5xx)的问题都可以从 access log 里面找到问题
看 err log,大部分都是下面两种情形:
1. "no live upstreams while connecting to upstream"
2. "upstream timed out(110: Connection timed out) while reading response reader from upstream"
总结起来就是连不上 upstream 了,为什么会 time out 并不知道。再看看 debug log,这个需要在编译的时候加进 –with-debug,里面能得到的信息同样比较少:

2026/08/02 15:29:14 [debug] 58443#0: *26274947 http upstream recv(): -1 (11: Resource temporarily unavailable)

2026/08/02 15:29:14 [debug] 58443#0: *26274956 recv() not ready (11: Resource temporarily unavailable)

调查到了这里,基本从已有的信息没得到什么特别的结论,考虑到对后端本身并没有影响,这事就这么被放过去了。但是,再怎么逃避也逃避不了墨菲定律。

logrotate(gzip) 的问题
几天之后的某个晚上,突然收到报警,ipvs master 上的 rs 被移除,紧接着 ipvs slave 上的 rs 也被移除,接下来就是疯狂的短信轰炸了,一会儿 add,一会儿 remove。当时我不在现场,让我们同事先临时手动把 vip 从目前的 master 切换到了 slave,但是不见好转,当机立断,直接全部切换到全线,客户端由于会 cache 以及重发机制,所以这 20min 的 outage(发到后端的请求大概跌了 2/3) 对实际的影响并不是很大。回去之后开始重点分析这次事故。
首先是把 dr, rs 包括 traffic, req, lvs conn, Nginx return code/status, 各种 rt/delay 在内的核心监控一步一步分析回溯,理清了从问题开始一直到恢复这中间发生的每一步过程,发现的最大的收获是出问题的这段时间,lvs 到 rs 的延时大大增加:

其次,keepalived 打到 messages 里面的 log 也看到了不少的东西,比如这段时间,会频繁的 add, remove rs:
Sep  6 20:20:10 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.6]:80 success.
Sep  6 20:20:10 lvs-1 Keepalived_healthcheckers[107592]: Adding service [192.168.90.6]:80 to VS [111.111.111.4]:80
Sep  6 20:20:14 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 failed !!!
Sep  6 20:20:14 lvs-1 Keepalived_healthcheckers[107592]: Removing service [192.168.90.5]:80 from VS [111.111.111.4]:80
Sep  6 20:20:20 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 success.
Sep  6 20:20:20 lvs-1 Keepalived_healthcheckers[107592]: Adding service [192.168.90.5]:80 to VS [111.111.111.4]:80

把 log 的时间扩展到三天前,再仔细的观察观察,可以发现,每一次 add, remove 的操作都是出现在整点的时候:
Sep  6 12:00:15 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 failed !!!
Sep  6 12:00:15 lvs-1 Keepalived_healthcheckers[107592]: Removing service [192.168.90.5]:80 from VS [111.111.111.4]:80

Sep  6 15:00:11 lvs-1 Keepalived_healthcheckers[107592]: TCP connection to [192.168.90.5]:80 failed !!!
Sep  6 15:00:11 lvs-1 Keepalived_healthcheckers[107592]: Removing service [192.168.90.5]:80 from VS [111.111.111.4]:80

联想到整点 ngx 会进行 logrotate 的操作,期间会产生大量的 io,导致系统负载变高,再加上 ngx 本身处理 req 会有一定的负载,导致 lvs 监测到 rs 无法响应的状态。
通过监控可以发现,每个整点的 load 都会变大:

从上图可以发现,整点的这一小段时间,load 至少会超过 1,跟 24 核的机器比,似乎非常的小,但是需要考虑的一点是,我们的采集 load 的监控是 60s 一次,监控实现秒级的成本太大,实际在 60s 内系统的负载会比上图的大得多。
为了验证这个问题,手动的模拟一次 logrotate(gzip) 的操作,平均一小时的 log 量在 5G 左右。下面的是手动执行一次 logroate 操作得到的监控数据,可以看到高峰时段,这块普通的 SAS 盘的 io util 达到了 100%,磁盘写吞吐达到了 245M/s,load 峰值超过 10:
04:06:00 CST       DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz     await     svctm     %util
04:06:01 CST    dev8-0    702.06     24.74 711958.76   1014.13    145.91    208.25      1.47    103.20
04:06:02 CST    dev8-0    701.01      8.08 704840.40   1005.48    146.79    208.00      1.44    101.01
04:06:03 CST    dev8-0    677.55      0.00 681755.10   1006.20    144.27    213.12      1.51    102.04
04:06:04 CST    dev8-0    672.45      8.16 681608.16   1013.63    141.47    210.12      1.52    102.04
04:06:05 CST    dev8-0   1364.65      0.00 694884.85    509.21    122.71     91.27      0.74    100.91

这总算是找到 lvs 频发 add, remove 的原因了,接下来改进就相对比较简单了:
1. lvs 对 ngx 不要太敏感,这个在 timeout 的一些设置上适当的加大可以缓解
2. ngx 的 log 处理问题,最初有同学提议只开一台 rs 的log,其他的全部关闭,这个看上去似乎可行,开一台基本可以代表其他 rs 的情况,但是实际情况可能并非我们所能想像,如果没有开启 access 的机器出现了问题而开启的每有任何问题,后续的问题排查将会比较的麻烦。所以,不管如何,保留一分全量的 log 还是非常有必要的。对此,比较通用的做法将 Nginx 通过 syslog 直接传到的远端的机器上,本地保留一分全量的,但是不开启 logrotate 的 gzip 压缩。
3. 除此之外,还可以考虑通过 access_log, error_log 的 ratio 来控制产生 log 的比例

Nginx open file 的问题
这个问题到此结束,这样安稳的过了四天,某天晚上 messages 里面发现 keepalived 频繁的 add, remove rs 了,这次时间不是整点了,虽然只出现了一两次,但是可以暴露出整个集群还是处于一个不稳定的状态,最初我们认为是 TCP_CHECK 的检测机制有问题,太过敏感,于是换成了 HTTP_GET 的方式,但是第二天仍然时不时的报错,并且从时间上来看完全没有规律:
Sep 10 17:15:19 lvs-2-2399 Keepalived_healthcheckers[34943]: MD5 digest error to [192.168.90.6]:80 url[/], MD5SUM [f9943d27e3420479271984e01dfe85dd].
Sep 10 17:15:19 lvs-2-2399 Keepalived_healthcheckers[34943]: Removing service [192.168.90.6]:80 from VS [124.251.33.4]:80
Sep 10 17:15:22 lvs-2-2399 Keepalived_healthcheckers[34943]: MD5 digest success to [192.168.90.6]:80 url(1).
Sep 10 17:15:28 lvs-2-2399 Keepalived_healthcheckers[34943]: Remote Web server [192.168.90.6]:80 succeed on service.
根据 keepalived_healthcheckers 检测的逻辑来看,肯定是发现 http://192.168.90.6/ 返回的不是既定的 md5sum 值,才触发了 remove 操作,很可能 rs 返回的不是 200 的错误才导致的。
抓包,为此蹲守了很长的时间抓住了重现的机会:

果真,确实是 rs 返回了 500 的错误才导致被 remove 的。之前虽然 5xx, 4xx 会增大,但是几乎并不影响 200 的数量,这次却不是这样的情况,500 的增多,200 的却异常下跌。全量分析 err log,惊人的发现,这段时间内的错误条目是平时的 100 倍,并且,出现奇怪的出现了下面的错误:
2014/09/06 20:09:55 [alert] 3164#0: *4082964565 socket() failed (24: Too many open files) while connecting to upstream, client: 122.93.211.105, server: foo.example.com, request: "POST /fk HTTP/1.1", upstream: "http://192.168.90.53:8888/fk", host: "foo.example.com"

一查 /proc 下面的 limits,Ngx 的竟然变成了 1024:

看到 1024 的那一刹那突然想起了我们之前某个产品线同样的出现过一次这个文档,当时尝试了各种办法包括直接修改 limits 文件也无法提高 open file,后来直接 reboot 机器了(有自动的 failover 策略),恢复,这事后来就被慢慢淡忘了,但是真相依然不清楚。结果,这次墨菲又找上门来了。后来我们发现还是有些用户(1, 2)  出现了跟我们类似的情况,但是依然不清楚原因。
为了确认就是 open file 造成了,对比一下 5xx(too many open file) 跟非 200 错误的比例:

完全符合。
真正的原因我也没法说清楚,基本可以肯定的是在 Nginx 运行过程中 open file 被改成了 1024。不过现在应该可以完全避免这个问题了,除了通过 worker_rlimit_nofile 指定之外,我们把这些进程的 limits 文件全部监控起来,包括 fd 的数量,这样即使再次「诡异」的变成了 1024,我们也能及时的发现采取措施。

kernel panic 的一些问题

机器稳定的运行了几天之后,某天早上 master 突然 kernel panic 了。
能得到的信息非常少,接下来继续挖坟似的分析 messages log。5min 打出的几百条 log 一条一条的对着 timestamp 分析,从 log 看,slave 是成功切换了,在 master 起来之后,流量又逐渐的恢复到了 master 上,但是至此之后,rs 上的流量由于 master 出现了问题。开始 master 看上去像是 work 的,inacctive conn 开始恢复,但是 active conn 一直到 5min 之后才开始恢复,这期间发生了什么,lvs 的 log 并没有很详细的说明,看上去像是两台 lvs 都没有工作,slave 变成了 backup 自然不再工作,挂掉的那台 master 虽然起来之后进入了 master 并且也 enable 了两台 rs,但是正常的流量却没有过来。
出现上面这种情况的可能原因是什么?keepalived 的配置出现问题了,果真,没有指明 priority。这个问题复现还算比较容易,直接把 master 的搞 kernel panic 就可以出现跟生产环境一样的现象,严格指定 priority 之后则不会出现这么长时间内无人接收请求的情况。
拿来主义是非常可怕的,当时我没有 review 下 keepalived 的配置就直接开跑了,核心服务还是要亲自验证。
除了上面这个教训之外,既然是 HA,一定要自己做一些破坏性实验,验证各种可能的情况。真正上线之前不验证,及时发现问题,真的全量上了,到时候出现问题的影响更大。我们虽然在小流量切换时,也做了一些破坏性实验验证 HA,但是并没有缜密的把所有情况都列穷举出来。

上面仅仅解决了 keepalived 的一个问题,kernel panic 似乎没有引起我们的注意,之后几天接连的出现 kernel panic,我们才意识到,这是个非常严重的问题,虽然每次 kernel panic 都完全的切换成功了。想到现在 lvs 使用的 kernel 跟官方唯一不一样的地方就是我自己重新编译了 kernel,调大了 IP_VS_TAB_BITS。既然这么一个小的改动都会引发 kernel panic,那索性还是先切回官方的版本,毕竟我们现在线上 90% 的机器都已经成功的跑了很长时间了。没想到的是,即使使用了官方的版本,依然不停的 panic,后来发现是其实是个 bug,在给 ipvs 的连接做 hash&unhashing 的时候缺少对被修改连接的锁,导致内存奔溃。理论上,我们可以对目前的 src 打 patch,但是实际的效果不得而知,加上没有之前的成功案例以及团队缺少精通内核的人,不得放弃这个想法。后来想到了我们兄弟团队,在多方求助之后,终于用上了高大上的集团内核,至此内核运行的很稳定。


4xx 问题的最终调查
还记得最上面第一次出现的 4xx 飙升问题吧,从某日起,4xx 的错误又明显的增大,通过对历史数据的分析发现增多的 4xx 错误主要集中在 499,随着高峰的来临(白天工作时间至凌晨),499 的错误也显著性的增加:

再次回顾下 499, 408 的问题。
499 实际上是客户端先关连接的,原因很多(无法确定,客户端引起),比如:
1. 刷页面的时候连按了 2 次 F5,就会导致之前页面上的请求没有收到完的就 499
2. 网络太慢
3. ngx 刚转发请求往后端,后端还没来得及应答,前端就主动关连接了

408 问题的解释:
1. 408 是客户端连完整的请求也没有传完,从 access log 里面没每发现 ua,正常的上传应该是有 ua 的,所以这个问题很可能是由于网络问题造成的
2. 408 的复现也比较简单,发送 POST /app_log HTTP/1.1 给 ngx,不发数据,过 60s 就会返回 408 的错误

除了 4xx 错误的飙升之外,upstream java 的 fd 也会随之飙升,从上面的一些数据至少可以得到下面的一些结论:
1. 本身移动网络的质量相比会比较差,再加上刚切换完双线,有一定 4xx 的增加还是可以理解的
2. 正常的应用,比较稳定的 4xx 应该是比较正常的
3. 但是,我们的情况是连续数天的 4xx 频繁不稳定,所以,可以确定有问题

想到这段期间唯一的操作就是切换了流量,于是,直接回滚,全部切换到全线 BGP,观察了一天没有任何效果。在跟开发确认一些细节的时候发现,原来在 4xx 飙升的前一天,更新过一次代码,既然切回全线没效果,那继续回滚代码吧,结果大跌眼镜的是问题依然存在。

结合 upstream 发现,有大量的 CLOSE_WAIT  状态,并且 recv-Q 均为非 0:
# cat status
established
syn-sent
syn-recv
fin-wait-1
fin-wait-2
time-wait
closed
close-wait
last-ack
closing
# for i in $(cat status);  do echo -n  "$i: " && ss -o state $i src INTERNAL_IP | wc -l; done
# ss src INTERNAL_IP:PORT  | head


上面的非 0 字段表明,upstream 没能成功的接受发过来的请求将其放到网卡的 buffer 里面,导致其 queue 一直保持在非 0 状态。
问题分析到这里,基本可以确定是用户态的应用没法正确的接收请求才导致此类结果,再结合上面 return code 的分析以及 upstream 的分析:
1. 切换完双线之后,由于本身网络质量会有一定的下降,所有 4xx 的会增多,这个是可以容忍的
2. upstream 代码层面应该还存在一些问题,结合 fd 的监控,网上高峰 fd 可能会飙升到 100+K,是不是有可能 fd 没有及时的回收?(fd 泄漏有没有这种可能)
3. 出问题前一天更新过一次代码,在其他没有变化的情况下,从前端到后端的监控都有不同程度的异常,是不是上线的有问题

上面提到的 fd 飙升问题,既然飙升,那就在出问题的时候上去看看是哪些 fd 飙升,首先需要确认是确实是 java 的进程导致:
for x in `ps -eF| awk '{ print $2 }'`;do echo `ls /proc/$x/fd 2> /dev/null | wc -l` $x `cat /proc/$x/cmdline 2> /dev/null`;done | sort -n -r | head -n 20

在某天出问题的中午 12 点,我登录到出问题的机器上统计了 fd 的情况:
出问题的时间段 fd 在 ~40k,分解下来包含
* tcp estab: ~1.7k,跟正常的比没变化
* tcp close-wait: ~9k,这两者大概 10k
* 剩余的 30k 通过 lsof 观察全部是 can't identify protocol 的状态

而正常情况是:
* tcp estab: ~1.5k
* tcp close-wait: ~2k
* 剩余的一些是 can't xxx

也就是说出问题阶段,close-wait & can't identiy protocol 飙升了原来的数倍:
1. close-wait 的很好理解,跟之前的观点一样,tcp 一直在等待 user space 调用 close(),否则会一直处于 close-wait 状态
2. can't xxx 的暂时没法解释,等到下一次出问题的时候再观察

有这么多的 close wait,很容易让人联想到是 fd 泄漏,想关闭的一方发送 tcp fin,服务端收到之后,如果程序逻辑有问题,忘记调用 close(socketfd),则会造成 fd 泄漏,表象就是有大量的 close wait 状态。不过从监控来看,这部分的飙升的 fd 很快就会直线下降到正常值(后来分析 jvm 的时候发现其实是 mgc, fgc 导致的 fd 回收):

问题分析到这里,那就继续深入下去,从 JVM 层面看看有没有问题。
首先看看 java 的进程,不管是正常状态还是异常状态,某几个 thread 都消耗了大量的 cpu 以及 fd,也就是说目前的 thread 是非常不均匀的,某一个 thread 能消耗 50% 以上的 fd:

接下来,搞个脚本看看最耗资源的那个 thread dump 是什么样的,有了这个就可以很容易的看到某些方法的异常了。这我在前一篇博客已经总结过,这里假设我们已经得到了 TID,先转换成 hex 然后 for 循环就能找到真相了。
for i in {1..100}; do echo "—$(date +'%H:%M:%S')—" >> tiddump.log; LAB=$(date '+%s'); HEX=`echo "obase=16; $TID" |bc`; jstack {PID} >> ./jstack$LAB; grep -iA 20  $HEX  ./jstack$LAB –color >> tiddump.log; sleep5; done

到了这一步,真相大白了,从 log 里面发现某些方法调用常年的 hang 在那儿,源于系统在处理某个大 List,客户端的 SDK 层面逻辑判断有问题,不做检查的把一些巨型字段经过压缩都发到前端这边来,结果到了后端解压缩处理的时候发现处理不了。

如果依然发现不了问题了?其实这时候问题的范围已经被缩的很小了,除了继续通过 mat、btrace、perf 深层次的跟踪服务情况之外,还有个重要的方面遗漏了,确认我们使用的一些软件的版本有无 bug,不要以为那些 release log, changelog, readme 文档是写着玩的,开发没养成看这些细节文档的习惯如果 如果我们一线运维也不看,那最坏的结果就是折腾了十来天最后看到最新的发型版本的 release log 出现了一些特殊的 bugfix 字段以及最后的欲哭无泪。
最初我们怀疑是服务在关闭连接的处理逻辑上有问题,后来发现我们的代码里面并不涉及这方面的逻辑处理,连接的建立关闭全部由 Finagle 框架自己处理了,所以一个重要的疑点是我们使用的该框架的版本是否存在连接方面的 bug,查一下他的下一个以及下几个版本的 release log 很快就能确认。

以上分析的这些案例,虽然影响没有大到会让业务遭受严重的损失,但是不夸张的说,每一个都是一个重量级的定时炸弹,不及时排除,指不定哪天全线就都挂了。这些事件,可能绝大多数的公司都不会遇到,但是思考问题的思路方向比这些案例重要的多,拿这次来说,其实思路在一开始就跑偏了,在确认前端没有问题的情况下还在花了大量的时间而不是一开始就从 upstream 下手。

通过 execv(snoopy) 来做用户行为 audit

github 有个叫 snoopy 的项目,专门用来做 audit,比系统原生的 auditd 好用的多,思路很好,关键的就是执行任何的命令之前确保第一调用的是 /etc/ld.so/preload 里面的 snoopy.so 这个动态库文件,而他调用的则是 exec()。
* execl
* execlp
* execle
* execv
* execvp
* execve
上面 6 个 sys call 的区别仅仅在于 arg 是 list 还是 array,是否使用了当前的环境变量已经 PATH 的使用。详细的区别请看这里(1, 2)。  
顺便提下 fork 跟 exec 的区别

当然,该服务并不是那么的完全,最少有下面几个问题:
1. 默认只接受 4096 长度的 argv,超过的或直接 trunk,这个不是什么大问题,可以在源码里面直接修改其 MACRO SNOOPY_MAX_ARG_LENGTH,增大到你需要的长度就好了
2. 对于 pipe 的处理,snoopy 会分别记录每一个 pipe 下的命令,然后分别打到 syslog 里面
3. 性能,网上有说会对性能产生一定的影响,目前来看,当然会有影响,毕竟多调用 sys call,但是从我们线上使用的情况来看,微乎其微,不管什么方案,最终都是 tradeoff 的结果

有人想做 audit 就有人想 bypass,结果还真有人想出了一套方案,简单的说就是在加载 snoopy.so 之前通过 dlopen() 加载这段 bypass 的代码。这仅仅是从技术的角度来分析,实际的线上是通过制度保证绝对不允许有任何人突破这道红线的。

TCP queue 的一些问题

先来回顾下三次握手里面涉及到的问题:
1. 当 client 通过 connect 向 server 发出 SYN 包时,client 会维护一个 socket 等待队列,而 server 会维护一个 SYN 队列
2. 此时进入半链接的状态,如果 socket 等待队列满了,server 则会丢弃,而 client 也会由此返回 connection time out;只要是 client 没有收到 SYN+ACK,3s 之后,client 会再次发送,如果依然没有收到,9s 之后会继续发送
3. 半连接 syn 队列的长度为 max(64, /proc/sys/net/ipv4/tcp_max_syn_backlog)  决定
4. 当 server 收到 client 的 SYN 包后,会返回 SYN, ACK 的包加以确认,client 的 TCP 协议栈会唤醒 socket 等待队列,发出 connect 调用
5. client 返回 ACK 的包后,server 会进入一个新的叫 accept 的队列,该队列的长度为 min(backlog, somaxconn),默认情况下,somaxconn 的值为 128,表示最多有 129 的 ESTAB 的连接等待 accept(),而 backlog 的值则由 int listen(int sockfd, int backlog) 中的第二个参数指定,listen 里面的 backlog 的含义请看这里。需要注意的是,一些 Linux 的发型版本可能存在对 somaxcon 错误 truncating 方式
6. 当 accept 队列满了之后,即使 client 继续向 server 发送 ACK 的包,也会不被相应,此时,server 通过 /proc/sys/net/ipv4/tcp_abort_on_overflow 来决定如何返回,0 表示直接丢丢弃该 ACK,1 表示发送 RST 通知 client;相应的,client 则会分别返回 read timeout 或者 connection reset by peer。上面说的只是些理论,如果服务器不及时的调用 accept(),当 queue 满了之后,服务器并不会按照理论所述,不再对 SYN 进行应答,返回 ETIMEDOUT。根据这篇文档的描述,实际情况并非如此,服务器会随机的忽略收到的 SYN,建立起来的连接数可以无限的增加,只不过客户端会遇到延时以及超时的情况。

可以看到,整个 TCP stack 有如下的两个 queue:
1. 一个是 half open(syn queue) queue(max(tcp_max_syn_backlog, 64)),用来保存 SYN_SENT 以及 SYN_RECV 的信息。
2. 另外一个是 accept queue(min(somaxconn, backlog)),保存 ESTAB 的状态,但是调用 accept()。

注意,之前我对 Recv-Q/Send-Q 的理解有些误差,使用 ss 获取到的 Recv-Q/Send-Q 在 LISTEN 状态以及非 LISTEN 状态所表达的含义是不同的。从 tcp_diag.c 源码中可以看到二者的区别:

LISTEN 状态: Recv-Q 表示的当前等待服务端调用 accept 完成三次握手的 listen backlog 数值,也就是说,当客户端通过 connect() 去连接正在 listen() 的服务端时,这些连接会一直处于这个 queue 里面直到被服务端 accept();Send-Q 表示的则是最大的 listen backlog 数值,这就就是上面提到的 min(backlog, somaxconn) 的值。
其余状态: 非 LISTEN 状态之前理解的没有问题。Recv-Q 表示 receive queue 中的 bytes 数量;Send-Q 表示 send queue 中的 bytes 数值。

要理解上面总结的这些,可以参见下这两个案例(1, 2)。 

通过 "SYNs to LISTEN sockets dropped" 以及 "times the listen queue of a socket overflowed" 这两个 netstat -s 获取到的 TCP 状态,可以很快的发现系统存在的一些问题。
任何一个包含 "dropped" 或者 "overflowed" 并且数值一直居高不下的 metric 从字面含义理解来看,都不是一个好现象。

对于 Nginx 来说,backlog 的默认值为 511,这个可以通过 ss/netstat 的 Send-Q 确认:
State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
LISTEN     0      511                       *:80                       *:*     

可以通过适当的增大 nginx 的 backlog 以及 somaxconn 来增大队列:
listen 80 backlog=1638

上面说了这么多,其实就是为了引入下面这个问题。
我们线上一个基于 Netty 的代码,3.5.12 的版本,监控显示 "times the listen queue of a socket overflowed" 常年居高不下,动辄几十 K,通过 ss,我们发现其 backlog 的值只有 50:
Recv-Q Send-Q           Local Address:Port               Peer Address:Port   
0      50                           *:6928                          *:*        users:(("java",454409,196))

g 了一下,发现这个版本复用了 Java 默认的 50 这个值。将其增加到 1024 测试,监控曲线一下子降低到了 0。

除了上面这些,还有一个比较基础的 net.core.netdev_max_backlog,如果内核接受包的速度大于被 userspace 处理的速度,该值定义了可以在接口输入最大的的包数量。

chartbeat 分享了两篇很精彩的文档,其中涉及到了 queue 的一些问题。
Lessons learned tuning TCP and Nginx in EC2 1
Lessons learned tuning TCP and Nginx in EC2 2

ref:
http://madalanarayana.wordpress.com/2014/04/13/learnings-on-tcp-syn/