Swoole slowlog 乱码修复

先说结果：fork 了 swoole 的源码，修复之后打了个 v1.10.7 的版本。

发现问题

由于各种原因项目在使用 swoole 的 v1.x 远古版本跑 TCP 服务，基础环境如下。

  • CentOS 6.9
  • PHP 5.5.38

然后遇到了程序偶发性超时情况严重。怀疑是版本bug，首先将 swoole 升级到了当前环境可用的最高版本 v1.10.6，问题依然没有解决。但是这个版本已经有了慢日志功能，将慢日志功能开起来，模拟程序阻塞超时，试试看功能可用否。

tcp_server.php

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
<?php

class tcpTest {
    static public function aa() {
        self::bb();
    }
    static public function bb() {
        sleep(3);
    }
}

class Server {

    static private $serv = null;

    private function __construct() {
        $serv = new \swoole_server("0.0.0.0", 9577);
        $serv->set([
            'reactor_num' => 2,
            'worker_num' => 8,
            'task_worker_num' => 0,
            'dispatch_mode' => 2,
            'daemonize' => false,
            'tcp_fastopen' => true,
            'request_slowlog_timeout' => 2,
            'request_slowlog_file' => '/tmp/swoole_slow.log',
            'trace_event_worker' => true,
        ]);

        $serv->on('Start', array($this, 'onStart'));
        $serv->on('Connect', array($this, 'onConnect'));
        $serv->on('Receive', array($this, 'onReceive'));
        $serv->on('Close', array($this, 'onClose'));
        $serv->start();
    }

    public function onStart($serv) {
        echo __METHOD__ . PHP_EOL;
    }

    public function onConnect($serv, $fd, $from_id) {
        echo __METHOD__ . " worker_id:{$serv->worker_id} work_pid:{$serv->worker_pid} fd:{$fd} from_id:{$from_id}" . PHP_EOL;
    }

    public function onReceive($serv, $fd, $from_id, $data) {
        $fdinfo = $serv->connection_info($fd,$from_id,true);
        echo __METHOD__ . " ip:{$fdinfo['remote_ip']} worker_id:{$serv->worker_id} work_pid:{$serv->worker_pid} fd:{$fd} from_id:{$from_id} data:{$data}" . PHP_EOL;

        \tcpTest::aa();
        $res_data = ['time' => date('Y-m-d H:i:s')];
        $serv->send($fd, json_encode($res_data));
    }

    public function onClose($serv, $fd, $from_id) {
        echo __METHOD__ . " worker_id:{$serv->worker_id} work_pid:{$serv->worker_pid} fd:{$fd} from_id:{$from_id}" . PHP_EOL . PHP_EOL;
    }

    static public function inst() {
        if (!(self::$serv instanceof self)) {
            self::$serv = new self;
        }
        return self::$serv;
    }

}
$res = \Server::inst();

tcp_client.php

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
<?php

function getTime() {
    list($micro, $time) = explode(' ', microtime());
    return $time + $micro;
}

$begin = getTime();
$_client = new \swoole_client(SWOOLE_SOCK_TCP | SWOOLE_KEEP);
if (false == $_client->connect("127.0.0.1", 9577, 10)) {
    printf("err_msg: %s err_code: %s" . PHP_EOL, var_export($_client->errMsg, true), var_export($_client->errCode, true));
}

$_client->send('hello');

$res = $_client->recv();
$end = getTime();

$data = json_decode($res, true);
printf("res: %s" . PHP_EOL, var_export($data, true));
echo $end - $begin . PHP_EOL;

分别运行服务端和客户端，slowlog内容出现乱码。

怎么会乱码了，太诡异了。vim 打开各种调编码没用，而且只是一部分乱码，可以猜出每行最后的是行号。
谷歌下好像也没有人遇到这问题，看下github issues发现这个功能后续版本都砍掉了，真是令人痛心。
编译个 PHP 5.6 的试下如果没问题，升级个小版本的 PHP 还是可以接受的，但结果依然是乱码。
这上古版本的扩展，可如何是好，天塌了有高个子顶着，没办法咱就的是那个高个子，下个扩展源码看看到底哪出问题了。

逻辑梳理与修复

结合swoole slowlog的文档与源码，梳理了slowlog执行逻辑：

  • 首先在服务端 start 的方法中增加了一个MANAGER_TIMER类型的 hook，通过双向链表存储。在服务端启动后 manage 进程开始事件循环，调用alarm(request_slowlog_timeout)，在 request_slowlog_timeout 秒之后向当前进程发送SIGALRM信号，当 manage 进程收到SIGALRM信号后，会设置一个alarm()，再回调所有MANAGER_TIMER类型的 hook。
  • 在回调函数中，会遍历所有 Work/Task 进程，检查是否超时，如果超时则调用 ptrace 开启跟踪，同时进程进入中止状态。
  • 现在开始slowlog逻辑，使用ptrace通过current_execute_data加上结构体属性的偏移量后的内存地址获取函数名、文件与行号后写入日志文件。
  • slowlog记录完成再次调用ptrace结束跟踪，进程继续执行。

当获取函数、文件时相当于从一段内存连续的读取然后拼接。而行号一次就行。这块逻辑简单，但是需要对内部结构体指针和内存非常熟悉才行，真是触及到了我的知识盲区。各种尝试修改后发现先获取下一个地址再进行后续处理就可以取到正确的字符串。

swoole_trace.c中

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
static int trace_get_strz(pid_t traced_pid, char *buf, size_t sz, long addr)
{
    int i;
    long l = addr;
    char *lc = (char *) &l;

    // 添加这个代码块，先获取下一个地址，再进行处理
    if (0 > trace_get_long(traced_pid, addr, &l)) {
        return -1;
    }

    i = l % SIZEOF_LONG;
    l -= i;
    for (addr = l;; addr += SIZEOF_LONG)
    {
        if (0 > trace_get_long(traced_pid, addr, &l))
        {
            return -1;
        }
        for (; i < SIZEOF_LONG; i++)
        {
            --sz;
            if (sz && lc[i])
            {
                *buf++ = lc[i];
                continue;
            }
            *buf = '\0';
            return 0;
        }
        i = 0;
    }
    return 0;
}

static int trace_get_long(pid_t traced_pid, long addr, long *data)
{
    errno = 0;
    *data = ptrace(PTRACE_PEEKDATA, traced_pid, (void *) addr, 0);
    if (*data < 0)
    {
        return -1;
    }
    return 0;
}

重新编译后再运行测试，一切正常了。

总结

至此，乱码修复了，但可真是没少调试。明白了实现逻辑也就明白了为何后续版本这个功能被砍掉了。

  • 完全依赖 alarm 所以最小粒度是秒。
  • 循环检测所以跨两个时间窗口的超时是无法记录的。
  • 通过内存地址结构体偏移获取函数、文件，当数据结构变动相当于重新写。