Nov 23

记Yii2的一个坑 不指定

felix021 @ 2016-11-23 00:33 [IT » 网络] 评论(1) , 引用(0) , 阅读(2041) | Via 本站原创 | |
最近发现有些服务器会定期出现磁盘过载问题,这里记录一下追查过程,供参考。

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)


转载请注明出自 ,如是转载文则注明原出处,谢谢:)
RSS订阅地址: http://www.felix021.com/blog/feed.php
依云 Email Homepage
2016-11-23 10:20
Yii2 给我的感觉就是一个字:糙。

比如多进程同时写一个文件会出现混乱,它就 flock 了再写。

比如 Redis 缓存部分,把缓存键先 md5 再写到 Redis,这样想要查看不容易,想要根据 Redis 键反查它是干什么的就更难了。

比如它连不上 Redis,只会报错说连不上,既不说是什么原因连不上(操作系统返回的错误信息),也不说是连不上哪个(我们有使用多个 Redis)。
felix021 回复于 2016-11-23 22:38
我也觉得它先md5搞key的这个做法太操蛋了。redis,我干脆就用自己写的。
分页: 1/1 第一页 1 最后页
发表评论
表情
emotemotemotemotemot
emotemotemotemotemot
emotemotemotemotemot
emotemotemotemotemot
emotemotemotemotemot
打开HTML
打开UBB
打开表情
隐藏
记住我
昵称   密码   *非必须
网址   电邮   [注册]