多进程log4j日志混乱问题分析
Posted
tags:
篇首语：本文由小常识网(cha138.com)小编为大家整理，主要介绍了多进程log4j日志混乱问题分析相关的知识，希望对你有一定的参考价值。
参考技术A后台有很多任务，每个任务都是一个main函数（JVM或进程），但是所有的任务都往同一份日志文件中输出日志。任务上线当天，日志没有问题，当第二天后，日志输出混乱
我们来分析下，在 log4j 的 DailyRollingFileAppender 类：
该方法的作用是：在滚动备份时间间隔到的时刻，将前一时间间隔的日志备份，同时以非追加模式将新日志打到新日志文件中；
假设A进程先进行滚动备份，B进程后进行滚动备份
1、对于A进程：
a. 先将data.log备份(renameTo())为data.log.2017.11.30，然后创建data.log文件，并将日志写在data.log中；
b. 此时A进程持有data.log的文件句柄；而B进程仍然持有data.log.2017.11.30的文件句柄(尽管被重命名，但句柄不变)；
2、对于B进程：
发现以data.log.2017.11.30为文件名的文件已经存在，则将其删除(前一时间段的所有日志全没了)，并将以data.log为文件名的文件重命名为data.log.2017.11.30，然后创建data.log文件；
3、此时A进程持有data.log.2017.11.30的文件句柄(被B进程重命名过)），而B进程持有最新创建的data.log；
4、结果导致：前一时间段日志丢失，A、B进程在不同的文件里打日志。
1、改变 rollOver()方法的实现方式
定义 TaskDailyRollingFileAppender 类，该类继承至 FileAppender ，它与 DailyRollingFileAppender 的主要区别在于以下方法：
改进后的 rollOver()方法主要作用是：A进程先将日志重命名，然后创建新日志文件，B进程发现已经存在，则直接以追加模式切换到新的日志文件上去。
2、根据启动参数taskName属性区分日志文件
如果是任务，根据启动参数taskName属性区分日志文件，每个日志文件仅受一个线程控制，即一个日志对应一个任务。
a. 目前所有后台任务在启动脚本里都加上了 -DtaskName属性；
b. 定义 TaskDailyRollingFileAppender类，该类继承 DailyRollingFileAppender，并覆盖其 setFile(String file) 方法：
c.对于不同的任务，日志文件名以不同的.taskName结尾，实现日志与任务一对一的关系。
php多进程总结
场景：日常任务中，有时需要通过php脚本执行一些日志分析，队列处理等任务，当数据量比较大时，可以使用多进程来处理。
准备：php多进程需要pcntl，posix扩展支持，可以通过 php - m 查看，没安装的话需要重新编译php，加上参数--enable-pcntl，posix一般默认会有。
注意：
多进程实现只能在cli模式下，在web服务器环境下，会出现无法预期的结果,我测试报错：Call to undefined function: pcntl_fork()
一个错误 pcntl_fork causing “errno=32 Broken pipe” #474 ，看https://github.com/phpredis/phpredis/issues/474
注意两点：如果是在循环中创建子进程,那么子进程中最后要exit,防止子进程进入循环。
子进程中的打开连接不能拷贝，使用的还是主进程的，需要用多例模式。
pcntl_fork:
一次调用两次返回，在父进程中返回子进程pid，在子进程中返回0，出错返回-1。
pcntl_wait ( int &$status [, int $options ] )：
阻塞当前进程，直到任意一个子进程退出或收到一个结束当前进程的信号,注意是结束当前进程的信号,子进程结束发送的SIGCHLD不算。使用$status返回子进程的状态码，并可以指定第二个参数来说明是否以阻塞状态调用
阻塞方式调用的，函数返回值为子进程的pid,如果没有子进程返回值为-1；
非阻塞方式调用，函数还可以在有子进程在运行但没有结束的子进程时返回0。
/** 确保这个函数只能运行在SHELL中 */
if (substr(php_sapi_name(), 0, 3) !== ‘cli‘) {
die("cli mode only");
}
#!/bin/bash
for((i=1;i<=8;i++))
do
/usr/local/bin/php multiprocessTest.php &
done
wait
上面的shell程序，列了一个很简单的多进程程序，用一个for循环，实现了8进程并发来跑multiprocessTest.php这个程序。最后的wait语句，也可以使主进程，再等待所有进程都执行完后再往下执行的需求。
这个程序是没有问题的，很多现有的代码也都这样实现，但是这个程序的并发数是不可控的，即我们无法根据机器的核数去调度每一个进程的开关。
若我们的机器有8核或者更多，上面的程序是没有问题的，所有核都能充分利用，并且互相之间，没有争抢资源的情况出现。
但我们的机器要没有8核的话会是什么情况，同一时间运行的进程数多于核数，那么系统就会出现进程分配调度的问题，争抢资源也跟着相应而来，一个进程不能保证独立连续的执行，所有的进程运行会听从系统的调度，这样就会有更多的不确定因素出现。
<?php
//最大的子进程数量
$maxChildPro = 8;
//当前的子进程数量
$curChildPro = 0;
//当子进程退出时，会触发该函数,当前子进程数-1
function sig_handler($sig)
{
global $curChildPro;
switch ($sig) {
case SIGCHLD:
echo ‘SIGCHLD‘, PHP_EOL;
$curChildPro--;
break;
}
}
//配合pcntl_signal使用，简单的说，是为了让系统产生时间云，让信号捕捉函数能够捕捉到信号量
declare(ticks = 1);
//注册子进程退出时调用的函数。SIGCHLD：在一个进程终止或者停止时，将SIGCHLD信号发送给其父进程。
pcntl_signal(SIGCHLD, "sig_handler");
while (true) {
$curChildPro++;
$pid = pcntl_fork();
if ($pid) {
//父进程运行代码,达到上限时父进程阻塞等待任一子进程退出后while循环继续
if ($curChildPro >= $maxChildPro) {
pcntl_wait($status);
}
} else {
//子进程运行代码
$s = rand(2, 6);
sleep($s);
echo "child sleep $s second quit", PHP_EOL;
exit;
}
}
<?php
$childs = array();
// Fork10个子进程
for ($i = 0; $i < 10; $i++) {
$pid = pcntl_fork();
if ($pid == -1)
die(‘Could not fork‘);
if ($pid) {
echo "parent
";
$childs[] = $pid;
} else {
// Sleep $i+1 (s). 子进程可以得到$i参数
sleep($i + 1);
// 子进程需要exit,防止子进程也进入for循环
exit();
}
}
while (count($childs) > 0) {
foreach ($childs as $key => $pid) {
$res = pcntl_waitpid($pid, $status, WNOHANG);
//-1代表error, 大于0代表子进程已退出,返回的是子进程的pid,非阻塞时0代表没取到退出子进程
if ($res == -1 || $res > 0)
unset($childs[$key]);
}
sleep(1);
}
<?php
function _fetchLog()
{
$password = $this->_getPassword();
$online_log_path = NginxConf::getArchiveDir($this->_stat_day);
$task_log_path = QFrameConfig::getConfig(‘LOG_PATH‘);
$children = array();
$success = true;
foreach($this->_server_list as $host => $value)
{
$local_dir = $this->_prepareLocalDir($host);
$task_log = "$task_log_path/fetch_log.$host";
$cmd = "sshpass -p $password rsync -av -e ‘ssh -o StrictHostKeyChecking=no‘ $host:$online_log_path/* $local_dir >> $task_log 2>&1";
$pid = pcntl_fork();
if(-1 === $pid)
{
LogSvc::log(‘stat_pv_by_citycode_error‘, ‘could not fork‘);
exit(‘could not fork‘);
}
else if(0 === $pid)
{
system($cmd, $return_value);
if(0 !== $return_value)
{
LogSvc::log(‘stat_pv_by_citycode_error‘, "rsync $host error");
}
exit($return_value);
}
else
{
$children[$pid] = 1;
}
}
while(!empty($children))
{
$pid = pcntl_waitpid(-1, $status, WNOHANG);
if(0 === $pid)
{
sleep(1);
}
else
{
if(0 !== pcntl_wexitstatus($status))
{
$success = false;
}
unset($children[$pid]);
}
}
return $success;
}
posix_kill(posix_getpid(), SIGHUP); 为自己生成SIGHUP信号 declare(ticks = 1); //php < 5.3pcntl_signal()函数仅仅是注册信号和它的处理方法，真正接收到信号并调用其处理方法的是pcntl_signal_dispatch()函数必须在循环里调用，为了检测是否有新的信号等待dispatching。pcntl_signal_dispatch()declare(ticks = 1);表示每执行一条低级指令，就检查一次信号，如果检测到注册的信号，就调用其信号处理器。kill [PID]命令，未加任何其他参数的话，程序会接收到一个SIGTERM信号。 <?php
// 定义一个处理器，接收到SIGINT信号后只输出一行信息
function signalHandler($signal)
{
if ($signal == SIGINT) {
echo ‘SIGINT‘, PHP_EOL;
}
}
// 信号注册：当接收到SIGINT信号时，调用signalHandler()函数
pcntl_signal(SIGINT, ‘signalHandler‘);
/**
* PHP < 5.3 使用
* 配合pcntl_signal使用,表示每执行一条低级指令，就检查一次信号，如果检测到注册的信号，就调用其信号处理器。
*/
if (!function_exists("pcntl_signal_dispatch")) {
declare(ticks=1);
}
while (true) {
$s = sleep(10);
echo $s, PHP_EOL; //信号会唤醒sleep,返回剩余的秒数。
// do something
for ($i = 0; $i < 5; $i++) {
echo $i . PHP_EOL;
usleep(100000);
}
/**
* PHP >= 5.3
* 调用已安装的信号处理器
* 必须在循环里调用，为了检测是否有新的信号等待dispatching。
*/
if (!function_exists("pcntl_signal_dispatch")) {
pcntl_signal_dispatch();
}
}
<?php
declare(ticks = 1);
function signal_handler($signal) {
print "Caught SIGALRM
";
pcntl_alarm(5);
}
pcntl_signal(SIGALRM, "signal_handler", true);
pcntl_alarm(5);
for(;;) {
}
<?php
/**
* 父进程通过pcntl_wait等待子进程退出
* 子进程通过信号kill自己,也可以在父进程中发送kil信号结束子进程
*/
//生成子进程
$pid = pcntl_fork();
if($pid == -1){
die(‘could not fork‘);
}else{
if($pid){
$status = 0;
//阻塞父进程，直到子进程结束，不适合需要长时间运行的脚本.
//可使用pcntl_wait($status, WNOHANG)实现非阻塞式
pcntl_wait($status);
exit;
}else{
//结束当前子进程，以防止生成僵尸进程
if(function_exists("posix_kill")){
posix_kill(getmypid(), SIGTERM);
}else{
system(‘kill -9‘. getmypid());
}
exit;
}
}
（1） 父进程通过wait和waitpid等函数等待子进程结束，这会导致父进程挂起。它不适合子进程需要长时间运行的情况(会导致超时)。
执行wait（）或waitpid（）系统调用，则子进程在终止后会立即把它在进程表中的数据返回给父进程，此时系统会立即删除该进入点。在这种情形下就不会产生defunct进程。
（2） 如果父进程很忙，那么可以用signal函数为SIGCHLD安装handler。在子进程结束后，父进程会收到该信号，可以在handler中调用wait回收。
（3） 如果父进程不关心子进程什么时候结束，那么可以用signal（SIGCLD, SIG_IGN）或signal（SIGCHLD, SIG_IGN）通知内核，自己对子进程的结束不感兴趣，那么子进程结束后，内核会回收，并不再给父进程发送信号
（4）fork两次，父进程fork一个子进程，然后继续工作，子进程fork一个孙进程后退出，那么孙进程被init接管，孙进程结束后，init会回收。不过子进程的回收还要自己做。
ps -A -ostat,ppid,pid,cmd | grep -e ‘^[Zz]‘
命令注解：
-A 参数列出所有进程
-o 自定义输出字段 我们设定显示字段为 stat（状态）, ppid（进程父id）, pid(进程id)，cmd（命令）这四个参数
状态为 z或者Z 的进程为僵尸进程，所以我们使用grep抓取stat状态为zZ进程
运行结果如下：
这时，可以使用 kill -HUP 5255 杀掉这个进程。如果再次查看僵尸进程还存在，可以kill -HUP 5253（父进程）。
如果有多个僵尸进程，可以通过 ps -A -ostat,ppid,pid,cmd | grep -e ‘^[Zz]‘|awk ‘print{$2}‘|xargs kill -9
处理。
多进程--进程间通信（IPC）
以上是关于多进程log4j日志混乱问题分析的主要内容，如果未能解决你的问题，请参考以下文章