nginx响应504的超时问题及php的慢日志事宜以及php中测试使用beanstalk消息队列的所有可用方法

一、nginx响应504的超时问题及php的慢日志事宜

    服务器最近偶尔报504，属于接口处理超时,排查在proxy服务器上发现部分接口在执行时有时达到了超时时间60ms,有的接口为59.999  publish:March 16, 2018 -Friday :

221.229.202.75 - - [15/Mar/2018:10:25:25 +0800] api..com 504 176 192.168.162.14:80 60.000 - 504 "-" "-" "-" "GET /caindex?uid=866067031604590&scre=30&unet=1&operator=3&loc=DH.EGJIK%2CCCK.BKGCFE&active_id=1521074825304&areq=5&preload=0&card_id=13618&content_id=15231295&pageid=1&platf=andid&g=31&mtype=high&ver=7.03&td=0&s=4D853567BFC1B92570667AAAC4EF209B8EB93C08 HTTP/1.1" "-" "Dalvik/2.1.0 (Linux; U; Android 7.1.2; vivo Y79 Build/N2G47H)" "117.29.145.24" 504

    追溯至上游WEB服务器192.168.162.14,在WEB处理服务器上发现一些错误日志，从日志上来看，其记录了上端的127.0.0.1:9000的PHP处理超时，错误提示主要部分：upstream timed out (110: Connection timed out) while reading response header from upstream，具体详细如下： 

2018/03/15 04:08:21 [error] 15842#0: *335771996 upstream timed out (110: Connection timed out) while reading response header from upstream, c
lient: 192.168.168.6, server: api..com, request: "GET /index?platf=ine&scrn=2&pageid=4&uid=7C4D9169-719B-42FF-8C99
-A4B6D4DC47EA&mtype=high&ver=0&g=1&unet=1&operator=2&lo=EBIDCDJ,CDB.CFCBCJ&ie_id=B853037A-9616-45B33-70C2A85ECE95&areq=5&preload=0
&carid=&connt_id=&s=f9e627802878e099e52ace10accbbfa29fb09b HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "api.com"

    此时就到了PHP层了，这时如果PHP没有打开慢日志就不好再往下一步排查，打开了PHP的慢日志的话，PHP程序中就能自动记录执行时间超过了阈值的程序所在的行以及整个调用过程：

#. 关于php慢日志的打开：

        找到php-fpm.conf配置文件，或者如果有加载*.conf文件，需要找一下对应目录下的配置文件，我这里在php-fpm.d文件夹中有www.conf文件，在里面找到以下两项配置：

; The log file for slow requests
; Default Value: not set
; Note: slowlog is mandatory if request_slowlog_timeout is set
;slowlog = log/$pool.log.slow
;将上面这行配置去除前面的分号并改为以下内容：
slowlog = var/log/$pool.slow.log

; The timeout for serving a single request after which a PHP backtrace will be
; dumped to the 'slowlog' file. A value of '0s' means 'off'.
; Available units: s(econds)(default), m(inutes), h(ours), or d(ays)
; Default Value: 0
;request_slowlog_timeout = 0
;将上面这行配置去除前面的分号并改为以下内容：
request_slowlog_timeout = 5

    说明：slowlog = var/log/$pool.slow.log这项直接写成绝对地址更好，我开始用的log/$pool.slow.log这个文件地址，发现PHP在加载的时候去加载PHP安装目录下这个目录，而不是自动去加载var/log/这个目录，而因为安装目录下不存在log目录，导致php重启失败。
request_slowlog_timeout 这项根据提示，默认单位是秒，我这里设置的3秒，可根据需要设置。
    重启PHP后即可在var/log/目录下发现www.slow.log 
注：上方的配置中有一个$pool，这个是利用了此配置文件中配置的pool name：,文件名称自动成为www.slow.log。

; pool name ('www' here)
[www]

 二、php中测试使用beanstalk消息队列的所有可用方法

    beanstalk消息队列轻型但功能很强大，值得一看，今天把它的方法再次完整熟悉了一遍。示例的php代码文件下载地址：见本文章最上方绑定的资源关联  publish:January 16, 2018 -Tuesday。

1. php端的消息生产的PHP程序文件代码如下：

require_once 'Beanstalk.php';

$beanstalk = new Socket_Beanstalk(array(
    'persistent' => false, //是否长连接
    'host' => '192.168.168.8',
    'port' => 11300, //端口号默认11300
    'timeout' => 3 //连接超时时间
));

#通过connect方法判断是否已连接
print_r("\n---------通过connect方法判断是否已连接-------------\n");
var_dump($beanstalk->connect());

#beanstalk类所有方法
print_r("\n---------beanstalk类所有方法-------------\n");
print_r(get_class_methods($beanstalk));

#列出所有的tubes
print_r("\n---------列出所有管道-------------\n");
print_r( $beanstalk->listTubes());

#选用指定tube
print_r("\n---------选用管道student,返回管道名称------------\n");
var_dump($beanstalk->useTube('student'));

#useTube一个不存在的管道则会创建管道
print_r("\n---------useTube一个不存在的管道则会创建管道------------\n");
var_dump($beanstalk->useTube('studenaat'));

#测试发现此处不管是使用useTube还是choose，其执行结果都会影响后面listTubeUsed和listTubeChosen的结果
$beanstalk->choose('student');

#useTube当前只能是一个，上方use了student。后面use了studenaat。则最终只会是studenaat
print_r("\n---------listTubeUsed列出当前选用的管道------------\n");
print_r($beanstalk->listTubeUsed());

#listTubeChosen的结果和listTubeUsed是一样的
print_r("\n---------listTubeChosen列出当前选用的管道------------\n");
print_r($beanstalk->listTubeChosen());

#查看所有队列的统计信息
print_r("\n---------stats查看所有队列的统计信息------------\n");
print_r($beanstalk->stats());

#查看指定队列的统计信息
print_r("\n---------statsTube查看某队列的统计信息------------\n");
print_r($beanstalk->statsTube('student'));

//往tube增加数据
print_r("\n---------使用put向上面choose的队列插入数据，返回job的ID------------\n");
for($i=1; $i<11; $i++)
{
    $data = json_encode(array('key'=>$i, 'age'=>rand(18,25), 'name'=>'stu-'.$i));
    $put = $beanstalk->put(10, 0, 60, $data);
    echo $put.',';
}

#statsTube查看插入后的tube的统计信息
print_r("\n---------statsTube查看插入后的tube的统计信息------------\n");
print_r($beanstalk->statsTube('student'));

#上面插入的最后一个job内容是
print_r("\n---------上面插入的最后一个job内容是------------\n");
print_r($data."   这个job插入后得到的ID是:".$put."\n");

#使用statsJob通过job的ID来取内容
print_r("\n--------使用statsJob查看job的统计信息------------\n");
$job = $beanstalk->statsJob($put);
print_r($job);

#使用bury方法埋葬这个job,见bury方法会返回false.因为bury等都需要在消费场景中执行。
print_r("\n--------使用bury方法埋葬这个job--可见bury方法会返回false.--------\n");
var_dump($beanstalk->bury($put, 15));

#再查看tube的统计信息
print_r("\n---------再查看tube的统计信息------------\n");
print_r($beanstalk->statsTube('student'));

#使用statsJob通过job的ID来取内容
print_r("\n--------使用statsJob再查看job的统计信息------------\n");
$job = $beanstalk->statsJob($put);
print_r($job);

#errors列出执行时的错误
print_r("\n---------errors列出执行时的错误------------\n");
echo "\n";print_r($beanstalk->errors());

2. php端的消息消费的PHP程序文件代码如下：

require_once 'Beanstalk.php';
$beanstalk = new Socket_Beanstalk(array(
    'persistent' => false, //是否长连接
    'host' => '192.168.168.8',
    'port' => 11300, //端口号默认11300
    'timeout' => 3 //连接超时时间
));


#列出所有的tubes
print_r("\n---------列出所有的tubes------------\n");  
$tubes = $beanstalk->listTubes();
print_r($tubes);

//使用tube
print_r("\n---------watch两个tubes,包括student和default------------\n");
var_dump($beanstalk->useTube('student'));
var_dump($beanstalk->watch('student'));
var_dump($beanstalk->watch('default'));

print_r("\n---------使用listTubesWatched列出watch的tubes------------\n");
print_r($beanstalk->listTubesWatched());

print_r("\n---------使用ignore忽略一个tube------------\n");
var_dump($beanstalk->ignore('default'));

print_r("\n---------使用listTubesWatched再列出watch的tubes------------\n");
print_r($beanstalk->listTubesWatched());

$i=1;
while(true)
{
    $job=$beanstalk->reserve();
    if($job)
    {
        echo date("Y-m-d H:i:s").'---开始--';
        if(!($job['id']%3)) var_dump($job['id'] .'--bury-' . $beanstalk->bury($job['id'], 33));
        elseif(!($job['id']%5)) var_dump($job['id'] .'--release-'.$beanstalk->release($job['id'], 55, 30));
        else var_dump($job['id'] .'--delete-'.$beanstalk->delete($job['id']));
    }
    $i++;
    if($i>=12) break;
}

print_r("\n---------最后处理的job数据------------\n");
echo $i.'. '.date("Y-m-d H:i:s").' new job:';print_r($job);

print_r("\n---------使用peekBuried列出jobs------------\n");
print_r($beanstalk->peekBuried());

print_r("\n---------查看tube的统计信息------------\n");
print_r($beanstalk->statsTube('student'));

print_r("\n---------使用peekReady列出jobs------------\n");
print_r($beanstalk->peekReady());

print_r("\n---------使用kick从bury中踢除2个jobs------------\n");
print_r($beanstalk->kick(2));

print_r("\n---------再查看tube的统计信息------------\n");
print_r($beanstalk->statsTube('student'));

3. 消息生产的程序在命令行下执行结果如下：

[root@test data]$ /opt/modules/php70/bin/php producer.php 

---------通过connect方法判断是否已连接-------------
bool(true)

---------beanstalk类所有方法-------------
Array
(
    [0] => __construct
    [1] => __destruct
    [2] => connect
    [3] => disconnect
    [4] => errors
    [5] => put
    [6] => choose
    [7] => useTube
    [8] => reserve
    [9] => delete
    [10] => release
    [11] => bury
    [12] => touch
    [13] => watch
    [14] => ignore
    [15] => peek
    [16] => peekReady
    [17] => peekDelayed
    [18] => peekBuried
    [19] => kick
    [20] => statsJob
    [21] => statsTube
    [22] => stats
    [23] => listTubes
    [24] => listTubeUsed
    [25] => listTubeChosen
    [26] => listTubesWatched
)

---------列出所有管道-------------
Array
(
    [0] => default
    [1] => studenaat
    [2] => student
)

---------选用管道student,返回管道名称------------
string(7) "student"

---------useTube一个不存在的管道则会创建管道------------
string(9) "studenaat"

---------listTubeUsed列出当前选用的管道------------
student
---------listTubeChosen列出当前选用的管道------------
student
---------stats查看所有队列的统计信息------------
Array
(
    [current-jobs-urgent] => 1479
    [current-jobs-ready] => 1479
    [current-jobs-reserved] => 0
    [current-jobs-delayed] => 0
    [current-jobs-buried] => 3
    [cmd-put] => 2911
    [cmd-peek] => 1
    [cmd-peek-ready] => 31
    [cmd-peek-delayed] => 1
    [cmd-peek-buried] => 33
    [cmd-reserve] => 1542142
    [cmd-reserve-with-timeout] => 0
    [cmd-delete] => 1428
    [cmd-release] => 37159
    [cmd-use] => 152
    [cmd-watch] => 94
    [cmd-ignore] => 38
    [cmd-bury] => 21
    [cmd-kick] => 3
    [cmd-touch] => 0
    [cmd-stats] => 33
    [cmd-stats-job] => 24
    [cmd-stats-tube] => 127
    [cmd-list-tubes] => 109
    [cmd-list-tube-used] => 62
    [cmd-list-tubes-watched] => 77
    [cmd-pause-tube] => 0
    [job-timeouts] => 163
    [total-jobs] => 2910
    [max-job-size] => 65535
    [current-tubes] => 3
    [current-connections] => 2
    [current-producers] => 0
    [current-workers] => 1
    [current-waiting] => 0
    [total-connections] => 116
    [pid] => 18336
    [version] => 1.1
    [rusage-utime] => 5.291195
    [rusage-stime] => 20.546876
    [uptime] => 103956
    [binlog-oldest-index] => 4
    [binlog-current-index] => 4
    [binlog-records-migrated] => 0
    [binlog-records-written] => 4359
    [binlog-max-size] => 10485760
    [id] => 4743fcafbd5c6d38
    [hostname] => BFG-OSER-4472
)

---------statsTube查看某队列的统计信息------------
Array
(
    [name] => student
    [current-jobs-urgent] => 1
    [current-jobs-ready] => 1
    [current-jobs-reserved] => 0
    [current-jobs-delayed] => 0
    [current-jobs-buried] => 3
    [total-jobs] => 328
    [current-using] => 2
    [current-watching] => 1
    [current-waiting] => 0
    [cmd-delete] => 324
    [cmd-pause-tube] => 0
    [pause] => 0
    [pause-time-left] => 0
)

---------使用put向上面choose的队列插入数据，返回job的ID------------
2912,2913,2914,2915,2916,2917,2918,2919,2920,2921,
---------statsTube查看插入后的tube的统计信息------------
Array
(
    [name] => student
    [current-jobs-urgent] => 11
    [current-jobs-ready] => 11
    [current-jobs-reserved] => 0
    [current-jobs-delayed] => 0
    [current-jobs-buried] => 3
    [total-jobs] => 338
    [current-using] => 2
    [current-watching] => 1
    [current-waiting] => 0
    [cmd-delete] => 324
    [cmd-pause-tube] => 0
    [pause] => 0
    [pause-time-left] => 0
)

---------上面插入的最后一个job内容是------------
{"key":10,"age":19,"name":"stu-10"}   这个job插入后得到的ID是:2921

--------使用statsJob查看job的统计信息------------
Array
(
    [id] => 2921
    [tube] => student
    [state] => ready
    [pri] => 10
    [age] => 0
    [delay] => 0
    [ttr] => 60
    [time-left] => 0
    [file] => 4
    [reserves] => 0
    [timeouts] => 0
    [releases] => 0
    [buries] => 0
    [kicks] => 0
)

--------使用bury方法埋葬这个job--可见bury方法会返回false.--------
bool(false)

---------再查看tube的统计信息------------
Array
(
    [name] => student
    [current-jobs-urgent] => 11
    [current-jobs-ready] => 11
    [current-jobs-reserved] => 0
    [current-jobs-delayed] => 0
    [current-jobs-buried] => 3
    [total-jobs] => 338
    [current-using] => 2
    [current-watching] => 1
    [current-waiting] => 0
    [cmd-delete] => 324
    [cmd-pause-tube] => 0
    [pause] => 0
    [pause-time-left] => 0
)

--------使用statsJob再查看job的统计信息------------
Array
(
    [id] => 2921
    [tube] => student
    [state] => ready
    [pri] => 10
    [age] => 0
    [delay] => 0
    [ttr] => 60
    [time-left] => 0
    [file] => 4
    [reserves] => 0
    [timeouts] => 0
    [releases] => 0
    [buries] => 0
    [kicks] => 0
)

---------errors列出执行时的错误------------
Array
(
    [0] => NOT_FOUND
)

4. 消息消费的程序在命令行下执行结果如下：

[root@test data]$ /opt/modules/php70/bin/php consumer.php

---------列出所有的tubes------------
Array
(
    [0] => default
    [1] => studenaat
    [2] => student
)

---------watch两个tubes,包括student和default------------
string(7) "student"
int(2)
int(2)

---------使用listTubesWatched列出watch的tubes------------
Array
(
    [0] => default
    [1] => student
)

---------使用ignore忽略一个tube------------
int(1)

---------使用listTubesWatched再列出watch的tubes------------
Array
(
    [0] => student
)
2018-01-16 08:05:29---开始--string(14) "2912--delete-1"
2018-01-16 08:05:29---开始--string(12) "2913--bury-1"
2018-01-16 08:05:29---开始--string(14) "2914--delete-1"
2018-01-16 08:05:29---开始--string(15) "2915--release-1"
2018-01-16 08:05:29---开始--string(12) "2916--bury-1"
2018-01-16 08:05:29---开始--string(14) "2917--delete-1"
2018-01-16 08:05:29---开始--string(14) "2918--delete-1"
2018-01-16 08:05:29---开始--string(12) "2919--bury-1"
2018-01-16 08:05:29---开始--string(15) "2920--release-1"
2018-01-16 08:05:29---开始--string(14) "2921--delete-1"
2018-01-16 08:05:29---开始--string(15) "2905--release-1"

---------最后处理的job数据------------
12. 2018-01-16 08:05:29 new job:Array
(
    [id] => 2905
    [body] => {"key":4,"age":25,"name":"stu-4"}
)

---------使用peekBuried列出jobs------------
Array
(
    [id] => 2910
    [body] => {"key":9,"age":24,"name":"stu-9"}
)

---------查看tube的统计信息------------
Array
(
    [name] => student
    [current-jobs-urgent] => 0
    [current-jobs-ready] => 0
    [current-jobs-reserved] => 0
    [current-jobs-delayed] => 3
    [current-jobs-buried] => 6
    [total-jobs] => 338
    [current-using] => 2
    [current-watching] => 2
    [current-waiting] => 0
    [cmd-delete] => 329
    [cmd-pause-tube] => 0
    [pause] => 0
    [pause-time-left] => 0
)

---------使用peekReady列出jobs------------

---------使用kick从bury中踢除2个jobs------------
2
---------再查看tube的统计信息------------
Array
(
    [name] => student
    [current-jobs-urgent] => 2
    [current-jobs-ready] => 2
    [current-jobs-reserved] => 0
    [current-jobs-delayed] => 3
    [current-jobs-buried] => 4
    [total-jobs] => 338
    [current-using] => 2
    [current-watching] => 2
    [current-waiting] => 0
    [cmd-delete] => 329
    [cmd-pause-tube] => 0
    [pause] => 0
    [pause-time-left] => 0
)