RSA: Java bouncy castle 与 PHP openssl_pu
sudo玩弄小记
Nov
23
最近发现有些服务器会定期出现磁盘过载问题，这里记录一下追查过程，供参考。
11月10日，立山向我反映我们线上的某 service 出现了一小段时间的无响应，查看 error log，发现有几百条"208203204 connect() to unix:/var/run/php5-fpm.sock failed (11: Resource temporarily unavailable) while connecting to upstream"错误，期间 zabbix 报警 server disk io overloaded，这让我想起确实每隔 3 ~ 4 天 zabbix 都会上报 server disk io overloaded（但出现的时间点并不固定在早上或晚上，也不一定是钱牛牛的访问高峰期），与 service 的error log时间也吻合，由于该 server 也是我们钱牛牛的两台 web 服务之一，因此在磁盘过载期间，钱牛牛对外提供的服务也收到了一定影响（error log也能证实这一点）。
用于 zabbix 的监控报警和 error log 的信息都太少，无法判断发生原因，因此没有继续追查下去；但是13日早晨这个问题又出现，因此决定重视起来。我在 server 上安装了 iotop 这个工具，使用 crontab 每分钟执行：
每隔 1s 记录一次当前访问磁盘的进程及访问速度等信息，记录 5 次后退出。
在17号捕捉到又一次磁盘过载，通过 iotop 的输出：
可以看到除了知道是 php-fpm 进程在写磁盘之外，并没有什么卵用，但至少还是指明了方向，只要找出 php 在写什么文件，就能离发现原因更近。
因此我写了另一个 monitor.py (后附)，实时监控 iotop 的输出，筛选出磁盘 io 过大的进程，找出这些进程打开的文件(ls -lh /proc/$PID/fd)，上报到sentry:
又等了5天，今天（22号）终于抓到罪魁祸首：
server: PID(4252) IS USING TOO MUCH DISK IO
{
"iotop": "07:44:17 4252 be/4 nginx 288.76 K/s 94813.59 K/s 0.00 % 75.15 % php-fpm: pool www",
"proc": "/proc/4252/fd:
total 0
lrwx------ 1 nginx users 64 Nov 22 07:44 0 -> socket:[1286391831]
lrwx------ 1 nginx users 64 Nov 22 07:44 1 -> /dev/null
lrwx------ 1 nginx users 64 Nov 22 07:44 2 -> /dev/null
lrwx------ 1 nginx users 64 Nov 22 07:44 3 -> socket:[2138228391]
lrwx------ 1 nginx users 64 Nov 22 07:44 4 -> socket:[2138229146]
l-wx------ 1 nginx users 64 Nov 22 07:44 5 -> /data/www/xxx-service/runtime/logs/app.log
lr-x------ 1 nginx users 64 Nov 22 07:44 6 -> /data/www/xxx-service/runtime/logs/app.log
",
"time": "2016-11-21 07:44:17"
}
从这里可以看出，php-fpm是在读写 service 的log。log文件内容有点琐碎，但是跟往常比起来确实没有什么异常，但是文件本身有点异常：
可以看出，所有的log文件都是在磁盘负载特别高的时候修改的，可见，磁盘负载高的直接原因是 yii 框架的 logrotate 机制导致的。
以下是从 yii2/framework2/vendor/yiisoft/yii2/log/FileTarget.php 拷贝出来的内容：
可以看出，罪魁祸首是 $rotateByCopy 默认值是 true ，而 yii2 之所以这么做，（根据框架的注释）是因为在 windows 下 log文件 很可能正被另一个文件打开，导致 rename 失败（吐槽：难道就不能多写一行代码根据检测到的os的type设置这个值吗？？？）。这也解释了为什么每个被 rotate 的 log 文件的修改时间间隔1分钟。
既然找到了问题的原因，解决方案就很简单了，把这个属性修改为false即可，当然，更完善的方案是能够根据OS的类型自动检测这个值。根据这个思路，我向 yii2 官方提交了一个pull requests：https://github.com/yiisoft/yii2/pull/13057，希望能被 merge 进去吧。
完。
monitor.py:
转载请注明出自 ，如是转载文则注明原出处，谢谢:)
RSS订阅地址: https://www.felix021.com/blog/feed.php 。
11月10日，立山向我反映我们线上的某 service 出现了一小段时间的无响应，查看 error log，发现有几百条"208203204 connect() to unix:/var/run/php5-fpm.sock failed (11: Resource temporarily unavailable) while connecting to upstream"错误，期间 zabbix 报警 server disk io overloaded，这让我想起确实每隔 3 ~ 4 天 zabbix 都会上报 server disk io overloaded（但出现的时间点并不固定在早上或晚上，也不一定是钱牛牛的访问高峰期），与 service 的error log时间也吻合，由于该 server 也是我们钱牛牛的两台 web 服务之一，因此在磁盘过载期间，钱牛牛对外提供的服务也收到了一定影响（error log也能证实这一点）。
用于 zabbix 的监控报警和 error log 的信息都太少，无法判断发生原因，因此没有继续追查下去；但是13日早晨这个问题又出现，因此决定重视起来。我在 server 上安装了 iotop 这个工具，使用 crontab 每分钟执行：
引用
$ /usr/sbin/iotop -btoqqqk --iter=5
每隔 1s 记录一次当前访问磁盘的进程及访问速度等信息，记录 5 次后退出。
在17号捕捉到又一次磁盘过载，通过 iotop 的输出：
引用
19:09:05 9663 be/4 nginx 31583.10 K/s 31551.68 K/s 0.00 % 93.86 % php-fpm: pool www
可以看到除了知道是 php-fpm 进程在写磁盘之外，并没有什么卵用，但至少还是指明了方向，只要找出 php 在写什么文件，就能离发现原因更近。
因此我写了另一个 monitor.py (后附)，实时监控 iotop 的输出，筛选出磁盘 io 过大的进程，找出这些进程打开的文件(ls -lh /proc/$PID/fd)，上报到sentry:
引用
$ /usr/sbin/iotop -btoqqqk | ./monitor.py
又等了5天，今天（22号）终于抓到罪魁祸首：
server: PID(4252) IS USING TOO MUCH DISK IO
{
"iotop": "07:44:17 4252 be/4 nginx 288.76 K/s 94813.59 K/s 0.00 % 75.15 % php-fpm: pool www",
"proc": "/proc/4252/fd:
total 0
lrwx------ 1 nginx users 64 Nov 22 07:44 0 -> socket:[1286391831]
lrwx------ 1 nginx users 64 Nov 22 07:44 1 -> /dev/null
lrwx------ 1 nginx users 64 Nov 22 07:44 2 -> /dev/null
lrwx------ 1 nginx users 64 Nov 22 07:44 3 -> socket:[2138228391]
lrwx------ 1 nginx users 64 Nov 22 07:44 4 -> socket:[2138229146]
l-wx------ 1 nginx users 64 Nov 22 07:44 5 -> /data/www/xxx-service/runtime/logs/app.log
lr-x------ 1 nginx users 64 Nov 22 07:44 6 -> /data/www/xxx-service/runtime/logs/app.log
",
"time": "2016-11-21 07:44:17"
}
从这里可以看出，php-fpm是在读写 service 的log。log文件内容有点琐碎，但是跟往常比起来确实没有什么异常，但是文件本身有点异常：
引用
nginx@server:logs$ ls -lah
total 5.0G
drwxrwxrwx 2 nginx users 4.0K Nov 22 10:54 .
drwxrwxrwx 3 nginx users 4.0K Jul 28 15:15 ..
-rwxrwxrwx 1 nginx users 55M Nov 22 12:04 app.log
-rw-r--r-- 1 nginx users 1001M Nov 22 07:44 app.log.1
-rw-r--r-- 1 nginx users 1001M Nov 22 07:43 app.log.2
-rw-r--r-- 1 nginx users 1001M Nov 22 07:42 app.log.3
-rw-r--r-- 1 nginx users 1001M Nov 22 07:41 app.log.4
-rw-r--r-- 1 nginx users 1001M Nov 22 07:40 app.log.5
total 5.0G
drwxrwxrwx 2 nginx users 4.0K Nov 22 10:54 .
drwxrwxrwx 3 nginx users 4.0K Jul 28 15:15 ..
-rwxrwxrwx 1 nginx users 55M Nov 22 12:04 app.log
-rw-r--r-- 1 nginx users 1001M Nov 22 07:44 app.log.1
-rw-r--r-- 1 nginx users 1001M Nov 22 07:43 app.log.2
-rw-r--r-- 1 nginx users 1001M Nov 22 07:42 app.log.3
-rw-r--r-- 1 nginx users 1001M Nov 22 07:41 app.log.4
-rw-r--r-- 1 nginx users 1001M Nov 22 07:40 app.log.5
可以看出，所有的log文件都是在磁盘负载特别高的时候修改的，可见，磁盘负载高的直接原因是 yii 框架的 logrotate 机制导致的。
以下是从 yii2/framework2/vendor/yiisoft/yii2/log/FileTarget.php 拷贝出来的内容：
public $rotateByCopy = true;
...
protected function rotateFiles()
{
$file = $this->logFile;
for ($i = $this->maxLogFiles; $i >= 0; --$i) {
// $i == 0 is the original log file
$rotateFile = $file . ($i === 0 ? '' : '.' . $i);
if (is_file($rotateFile)) {
// suppress errors because it's possible multiple processes enter into this section
if ($i === $this->maxLogFiles) {
@unlink($rotateFile);
} else {
if ($this->rotateByCopy) {
@copy($rotateFile, $file . '.' . ($i + 1));
if ($fp = @fopen($rotateFile, 'a')) {
@ftruncate($fp, 0);
@fclose($fp);
}
} else {
@rename($rotateFile, $file . '.' . ($i + 1));
}
}
}
}
}
...
protected function rotateFiles()
{
$file = $this->logFile;
for ($i = $this->maxLogFiles; $i >= 0; --$i) {
// $i == 0 is the original log file
$rotateFile = $file . ($i === 0 ? '' : '.' . $i);
if (is_file($rotateFile)) {
// suppress errors because it's possible multiple processes enter into this section
if ($i === $this->maxLogFiles) {
@unlink($rotateFile);
} else {
if ($this->rotateByCopy) {
@copy($rotateFile, $file . '.' . ($i + 1));
if ($fp = @fopen($rotateFile, 'a')) {
@ftruncate($fp, 0);
@fclose($fp);
}
} else {
@rename($rotateFile, $file . '.' . ($i + 1));
}
}
}
}
}
可以看出，罪魁祸首是 $rotateByCopy 默认值是 true ，而 yii2 之所以这么做，（根据框架的注释）是因为在 windows 下 log文件 很可能正被另一个文件打开，导致 rename 失败（吐槽：难道就不能多写一行代码根据检测到的os的type设置这个值吗？？？）。这也解释了为什么每个被 rotate 的 log 文件的修改时间间隔1分钟。
既然找到了问题的原因，解决方案就很简单了，把这个属性修改为false即可，当然，更完善的方案是能够根据OS的类型自动检测这个值。根据这个思路，我向 yii2 官方提交了一个pull requests：https://github.com/yiisoft/yii2/pull/13057，希望能被 merge 进去吧。
完。
monitor.py:
#!/usr/bin/python
#coding:utf-8
import sys
import re
import time
import datetime
import socket
try:
import simplejson as json
except:
import json
import subprocess
from raven import Client
import requests
last_sent = 0
dsn = '__SENTRY_DSN__'
#00 - '19:07:03'
#01 - '9663'
#02 - 'be/4'
#03 - 'nginx'
#04 - '10423.06'
#05 - 'K/s'
#06 - '10423.06'
#07 - 'K/s'
#08 - '0.00'
#09 - '%'
#10 - '99.99'
#11 - '%'
#12 - 'php-fpm: pool www'
def should_skip(program):
if program == '[kjournald]':
return True
for prefix in ['gzip', 'rsync', 'ssh', 'logrotate', 'sap100', 'sar ', 'rpm ', 'updatedb', 'mysql', 'nginx', 'vim', 'cat']:
if program.startswith(prefix):
return True
return False
def run_command(*cmd):
try:
p = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
out, err = p.communicate()
if err:
raise Exception(err.strip())
return out
except Exception, e:
return 'run %s failed: %s' % (str(cmd), e)
while True:
try:
line = sys.stdin.readline().strip()
except KeyboardInterrupt:
print >>sys.stderr, "user abort"
sys.exit(0)
fields = re.split(' +', line.strip(), 12)
if len(fields) != 13:
continue
if should_skip(fields[12]):
continue
read_speed = float(fields[4])
write_speed = float(fields[6])
if read_speed > 1000 or write_speed > 1000:
date = time.strftime('%Y-%m-%d')
pid = fields[1]
client = Client(dsn)
message = '%s: PID(%s) IS USING TOO MUCH DISK IO' % (socket.gethostname(), pid)
args = {
'time' : date + ' ' + fields[0],
'iotop' : line.strip(),
'proc' : run_command('ls', '-lhR', '/proc/%s/fd' % pid),
}
print >>sys.stderr, message
print >>sys.stderr, json.dumps(args, indent=4)
client.capture('raven.events.Message', message=message, extra=args)
#coding:utf-8
import sys
import re
import time
import datetime
import socket
try:
import simplejson as json
except:
import json
import subprocess
from raven import Client
import requests
last_sent = 0
dsn = '__SENTRY_DSN__'
#00 - '19:07:03'
#01 - '9663'
#02 - 'be/4'
#03 - 'nginx'
#04 - '10423.06'
#05 - 'K/s'
#06 - '10423.06'
#07 - 'K/s'
#08 - '0.00'
#09 - '%'
#10 - '99.99'
#11 - '%'
#12 - 'php-fpm: pool www'
def should_skip(program):
if program == '[kjournald]':
return True
for prefix in ['gzip', 'rsync', 'ssh', 'logrotate', 'sap100', 'sar ', 'rpm ', 'updatedb', 'mysql', 'nginx', 'vim', 'cat']:
if program.startswith(prefix):
return True
return False
def run_command(*cmd):
try:
p = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
out, err = p.communicate()
if err:
raise Exception(err.strip())
return out
except Exception, e:
return 'run %s failed: %s' % (str(cmd), e)
while True:
try:
line = sys.stdin.readline().strip()
except KeyboardInterrupt:
print >>sys.stderr, "user abort"
sys.exit(0)
fields = re.split(' +', line.strip(), 12)
if len(fields) != 13:
continue
if should_skip(fields[12]):
continue
read_speed = float(fields[4])
write_speed = float(fields[6])
if read_speed > 1000 or write_speed > 1000:
date = time.strftime('%Y-%m-%d')
pid = fields[1]
client = Client(dsn)
message = '%s: PID(%s) IS USING TOO MUCH DISK IO' % (socket.gethostname(), pid)
args = {
'time' : date + ' ' + fields[0],
'iotop' : line.strip(),
'proc' : run_command('ls', '-lhR', '/proc/%s/fd' % pid),
}
print >>sys.stderr, message
print >>sys.stderr, json.dumps(args, indent=4)
client.capture('raven.events.Message', message=message, extra=args)
欢迎扫码关注：
转载请注明出自 ，如是转载文则注明原出处，谢谢:)
RSS订阅地址: https://www.felix021.com/blog/feed.php 。
比如多进程同时写一个文件会出现混乱，它就 flock 了再写。
比如 Redis 缓存部分，把缓存键先 md5 再写到 Redis，这样想要查看不容易，想要根据 Redis 键反查它是干什么的就更难了。
比如它连不上 Redis，只会报错说连不上，既不说是什么原因连不上（操作系统返回的错误信息），也不说是连不上哪个（我们有使用多个 Redis）。