标题：记Yii2的一个坑
出处：Felix021
时间：Wed, 23 Nov 2016 00:33:47 +0000
作者：felix021
地址：https://www.felix021.com/blog/read.php?2170

内容：
最近发现有些服务器会定期出现磁盘过载问题，这里记录一下追查过程，供参考。

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



可以看出，所有的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));
                }
            }
        }
    }
}


可以看出，罪魁祸首是 $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)



Generated by Bo-blog 2.1.0