X-Git-Url: https://git.mxchange.org/?a=blobdiff_plain;f=src%2FCore%2FWorker.php;h=bb17e430c14ab736dee2934b9bc010ad22050e95;hb=69c7e9af2043404052cd488fd5edf18917dcdaa5;hp=04e4819cb265b926267c58ec31985eb4f5e79874;hpb=503c582a31876d3789b9f7d443f6b9f057c67ec7;p=friendica.git diff --git a/src/Core/Worker.php b/src/Core/Worker.php index 04e4819cb2..bb17e430c1 100644 --- a/src/Core/Worker.php +++ b/src/Core/Worker.php @@ -21,6 +21,7 @@ namespace Friendica\Core; +use Friendica\App\Mode; use Friendica\Core; use Friendica\Database\DBA; use Friendica\DI; @@ -49,6 +50,7 @@ class Worker private static $lock_duration = 0; private static $last_update; private static $state; + private static $daemon_mode = null; /** * Processes the tasks that are in the workerqueue table @@ -92,66 +94,104 @@ class Worker $last_check = $starttime = time(); self::$state = self::STATE_STARTUP; + $wait_interval = self::isDaemonMode() ? 360 : 10; + $start = time(); + + do { + // We fetch the next queue entry that is about to be executed + while ($r = self::workerProcess()) { + // Don't refetch when a worker fetches tasks for multiple workers + $refetched = DI::config()->get('system', 'worker_multiple_fetch'); + foreach ($r as $entry) { + // Assure that the priority is an integer value + $entry['priority'] = (int)$entry['priority']; + + // The work will be done + if (!self::execute($entry)) { + Logger::notice('Process execution failed, quitting.'); + return; + } - // We fetch the next queue entry that is about to be executed - while ($r = self::workerProcess()) { - // Don't refetch when a worker fetches tasks for multiple workers - $refetched = DI::config()->get('system', 'worker_multiple_fetch'); - foreach ($r as $entry) { - // Assure that the priority is an integer value - $entry['priority'] = (int)$entry['priority']; - - // The work will be done - if (!self::execute($entry)) { - Logger::info('Process execution failed, quitting.'); - return; - } - - // Trying to fetch new processes - but only once when successful - if (!$refetched && DI::lock()->acquire(self::LOCK_PROCESS, 0)) { - self::findWorkerProcesses(); - DI::lock()->release(self::LOCK_PROCESS); - self::$state = self::STATE_REFETCH; - $refetched = true; - } else { - self::$state = self::STATE_SHORT_LOOP; + // Trying to fetch new processes - but only once when successful + if (!$refetched && DI::lock()->acquire(self::LOCK_PROCESS, 0)) { + self::findWorkerProcesses(); + DI::lock()->release(self::LOCK_PROCESS); + self::$state = self::STATE_REFETCH; + $refetched = true; + } else { + self::$state = self::STATE_SHORT_LOOP; + } } - } - - // To avoid the quitting of multiple workers only one worker at a time will execute the check - if ((time() > $last_check + 5) && !self::getWaitingJobForPID()) { - self::$state = self::STATE_LONG_LOOP; - if (DI::lock()->acquire(self::LOCK_WORKER, 0)) { - // Count active workers and compare them with a maximum value that depends on the load - if (self::tooMuchWorkers()) { - Logger::info('Active worker limit reached, quitting.'); + // To avoid the quitting of multiple workers only one worker at a time will execute the check + if ((time() > $last_check + 5) && !self::getWaitingJobForPID()) { + self::$state = self::STATE_LONG_LOOP; + + if (DI::lock()->acquire(self::LOCK_WORKER, 0)) { + // Count active workers and compare them with a maximum value that depends on the load + if (self::tooMuchWorkers()) { + Logger::notice('Active worker limit reached, quitting.'); + DI::lock()->release(self::LOCK_WORKER); + return; + } + + // Check free memory + if (DI::process()->isMinMemoryReached()) { + Logger::warning('Memory limit reached, quitting.'); + DI::lock()->release(self::LOCK_WORKER); + return; + } DI::lock()->release(self::LOCK_WORKER); - return; } + $last_check = time(); + } - // Check free memory - if (DI::process()->isMinMemoryReached()) { - Logger::notice('Memory limit reached, quitting.'); - DI::lock()->release(self::LOCK_WORKER); - return; + // Quit the worker once every cron interval + if (time() > ($starttime + (DI::config()->get('system', 'cron_interval') * 60))) { + Logger::info('Process lifetime reached, respawning.'); + self::unclaimProcess(); + if (self::isDaemonMode()) { + self::IPCSetJobState(true); + } else { + self::spawnWorker(); } - DI::lock()->release(self::LOCK_WORKER); + return; } - $last_check = time(); + $start = time(); } - // Quit the worker once every cron interval - if (time() > ($starttime + (DI::config()->get('system', 'cron_interval') * 60))) { - Logger::info('Process lifetime reached, respawning.'); - self::unclaimProcess(); - self::spawnWorker(); - return; + $seconds = (time() - $start); + + // logarithmic wait time calculation. + $arg = (($seconds + 1) / ($wait_interval / 9)) + 1; + $sleep = min(1000000, round(log10($arg) * 1000000, 0)); + usleep($sleep); + + $timeout = ($seconds >= $wait_interval); + Logger::info('Timeout', ['timeout' => $timeout, 'seconds' => $seconds, 'sleep' => $sleep]); + + if (!$timeout) { + if (DI::process()->isMaxLoadReached()) { + Logger::notice('maximum load reached, quitting.'); + return; + } + + // Kill stale processes every 5 minutes + $last_cleanup = DI::config()->get('system', 'worker_last_cleaned', 0); + if (time() > ($last_cleanup + 300)) { + DI::config()->set('system', 'worker_last_cleaned', time()); + self::killStaleWorkers(); + } + + // Check if the system is ready + if (!self::isReady()) { + return; + } } - } + } while (!$timeout); // Cleaning up. Possibly not needed, but it doesn't harm anything. - if (DI::config()->get('system', 'worker_daemon_mode', false)) { + if (self::isDaemonMode()) { self::IPCSetJobState(false); } Logger::info("Couldn't select a workerqueue entry, quitting process", ['pid' => getmypid()]); @@ -168,28 +208,28 @@ class Worker { // Count active workers and compare them with a maximum value that depends on the load if (self::tooMuchWorkers()) { - Logger::info('Active worker limit reached, quitting.'); + Logger::notice('Active worker limit reached, quitting.'); return false; } // Do we have too few memory? if (DI::process()->isMinMemoryReached()) { - Logger::notice('Memory limit reached, quitting.'); + Logger::warning('Memory limit reached, quitting.'); return false; } // Possibly there are too much database connections if (self::maxConnectionsReached()) { - Logger::notice('Maximum connections reached, quitting.'); + Logger::warning('Maximum connections reached, quitting.'); return false; } // Possibly there are too much database processes that block the system if (DI::process()->isMaxProcessesReached()) { - Logger::notice('Maximum processes reached, quitting.'); + Logger::warning('Maximum processes reached, quitting.'); return false; } - + return true; } @@ -290,17 +330,21 @@ class Worker // Constantly check the number of parallel database processes if (DI::process()->isMaxProcessesReached()) { - Logger::notice("Max processes reached for process", ['pid' => $mypid]); + Logger::warning("Max processes reached for process", ['pid' => $mypid]); return false; } // Constantly check the number of available database connections to let the frontend be accessible at any time if (self::maxConnectionsReached()) { - Logger::notice("Max connection reached for process", ['pid' => $mypid]); + Logger::warning("Max connection reached for process", ['pid' => $mypid]); return false; } - $argv = json_decode($queue["parameter"], true); + $argv = json_decode($queue['parameter'], true); + if (!empty($queue['command'])) { + array_unshift($argv, $queue['command']); + } + if (empty($argv)) { Logger::warning('Parameter is empty', ['queue' => $queue]); return false; @@ -407,6 +451,12 @@ class Worker { $a = DI::app(); + $cooldown = DI::config()->get("system", "worker_cooldown", 0); + if ($cooldown > 0) { + Logger::info('Pre execution cooldown.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'cooldown' => $cooldown]); + sleep($cooldown); + } + Logger::enableWorker($funcname); Logger::info("Process start.", ['priority' => $queue["priority"], 'id' => $queue["id"]]); @@ -417,6 +467,11 @@ class Worker // For this reason the variables have to be initialized. DI::profiler()->reset(); + if (!in_array($queue['priority'], PRIORITIES)) { + Logger::warning('Invalid priority', ['queue' => $queue, 'callstack' => System::callstack(20)]); + $queue['priority'] = PRIORITY_MEDIUM; + } + $a->queue = $queue; $up_duration = microtime(true) - self::$up_start; @@ -474,10 +529,8 @@ class Worker DI::profiler()->saveLog(DI::logger(), "ID " . $queue["id"] . ": " . $funcname); - $cooldown = DI::config()->get("system", "worker_cooldown", 0); - if ($cooldown > 0) { - Logger::info('Cooldown.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'cooldown' => $cooldown]); + Logger::info('Post execution cooldown.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'cooldown' => $cooldown]); sleep($cooldown); } } @@ -531,7 +584,7 @@ class Worker $level = ($used / $max) * 100; if ($level >= $maxlevel) { - Logger::notice("Maximum level (".$maxlevel."%) of user connections reached: ".$used."/".$max); + Logger::warning("Maximum level (".$maxlevel."%) of user connections reached: ".$used."/".$max); return true; } } @@ -561,7 +614,7 @@ class Worker if ($level < $maxlevel) { return false; } - Logger::notice("Maximum level (".$level."%) of system connections reached: ".$used."/".$max); + Logger::warning("Maximum level (".$level."%) of system connections reached: ".$used."/".$max); return true; } @@ -576,7 +629,7 @@ class Worker $stamp = (float)microtime(true); $entries = DBA::select( 'workerqueue', - ['id', 'pid', 'executed', 'priority', 'parameter'], + ['id', 'pid', 'executed', 'priority', 'command', 'parameter'], ['NOT `done` AND `pid` != 0'], ['order' => ['priority', 'retrial', 'created']] ); @@ -603,17 +656,21 @@ class Worker $max_duration_defaults = [PRIORITY_CRITICAL => 720, PRIORITY_HIGH => 10, PRIORITY_MEDIUM => 60, PRIORITY_LOW => 180, PRIORITY_NEGLIGIBLE => 720]; $max_duration = $max_duration_defaults[$entry["priority"]]; - $argv = json_decode($entry["parameter"], true); - if (empty($argv)) { + $argv = json_decode($entry['parameter'], true); + if (!empty($entry['command'])) { + $command = $entry['command']; + } elseif (!empty($argv)) { + $command = array_shift($argv); + } else { return; } - $argv[0] = basename($argv[0]); + $command = basename($command); // How long is the process already running? $duration = (time() - strtotime($entry["executed"])) / 60; if ($duration > $max_duration) { - Logger::notice("Worker process ".$entry["pid"]." (".substr(json_encode($argv), 0, 50).") took more than ".$max_duration." minutes. It will be killed now."); + Logger::notice('Worker process took too much time - killed', ['duration' => number_format($duration, 3), 'max' => $max_duration, 'id' => $entry["id"], 'pid' => $entry["pid"], 'command' => $command]); posix_kill($entry["pid"], SIGTERM); // We killed the stale process. @@ -636,7 +693,7 @@ class Worker self::$db_duration += (microtime(true) - $stamp); self::$db_duration_write += (microtime(true) - $stamp); } else { - Logger::info('Process runtime is okay', ['pid' => $entry["pid"], 'duration' => $duration, 'max' => $max_duration, 'command' => substr(json_encode($argv), 0, 50)]); + Logger::info('Process runtime is okay', ['duration' => number_format($duration, 3), 'max' => $max_duration, 'id' => $entry["id"], 'pid' => $entry["pid"], 'command' => $command]); } } } @@ -757,7 +814,7 @@ class Worker // Are there fewer workers running as possible? Then fork a new one. if (!DI::config()->get("system", "worker_dont_fork", false) && ($queues > ($active + 1)) && self::entriesExists()) { Logger::info("There are fewer workers as possible, fork a new worker.", ['active' => $active, 'queues' => $queues]); - if (DI::config()->get('system', 'worker_daemon_mode', false)) { + if (self::isDaemonMode()) { self::IPCSetJobState(true); } else { self::spawnWorker(); @@ -766,7 +823,7 @@ class Worker } // if there are too much worker, we don't spawn a new one. - if (DI::config()->get('system', 'worker_daemon_mode', false) && ($active > $queues)) { + if (self::isDaemonMode() && ($active > $queues)) { self::IPCSetJobState(false); } @@ -848,12 +905,17 @@ class Worker $ids = []; $stamp = (float)microtime(true); $condition = ["`priority` = ? AND `pid` = 0 AND NOT `done` AND `next_try` < ?", $priority, DateTimeFormat::utcNow()]; - $tasks = DBA::select('workerqueue', ['id', 'parameter'], $condition, ['limit' => $limit, 'order' => ['retrial', 'created']]); + $tasks = DBA::select('workerqueue', ['id', 'command', 'parameter'], $condition, ['limit' => $limit, 'order' => ['retrial', 'created']]); self::$db_duration += (microtime(true) - $stamp); while ($task = DBA::fetch($tasks)) { $ids[] = $task['id']; // Only continue that loop while we are storing commands that can be processed quickly - $command = json_decode($task['parameter'])[0]; + if (!empty($task['command'])) { + $command = $task['command']; + } else { + $command = json_decode($task['parameter'])[0]; + } + if (!in_array($command, self::FAST_COMMANDS)) { break; } @@ -968,13 +1030,17 @@ class Worker if ($limit > 0) { $stamp = (float)microtime(true); $condition = ["`pid` = 0 AND NOT `done` AND `next_try` < ?", DateTimeFormat::utcNow()]; - $tasks = DBA::select('workerqueue', ['id', 'parameter'], $condition, ['limit' => $limit, 'order' => ['priority', 'retrial', 'created']]); + $tasks = DBA::select('workerqueue', ['id', 'command', 'parameter'], $condition, ['limit' => $limit, 'order' => ['priority', 'retrial', 'created']]); self::$db_duration += (microtime(true) - $stamp); while ($task = DBA::fetch($tasks)) { $ids[] = $task['id']; // Only continue that loop while we are storing commands that can be processed quickly - $command = json_decode($task['parameter'])[0]; + if (!empty($task['command'])) { + $command = $task['command']; + } else { + $command = json_decode($task['parameter'])[0]; + } if (!in_array($command, self::FAST_COMMANDS)) { break; } @@ -1073,6 +1139,8 @@ class Worker */ public static function executeIfIdle() { + self::checkDaemonState(); + if (!DI::config()->get("system", "frontend_worker")) { return; } @@ -1156,6 +1224,60 @@ class Worker self::killStaleWorkers(); } + /** + * Fork a child process + * + * @param boolean $do_cron + * @return void + */ + private static function forkProcess(bool $do_cron) + { + if (DI::process()->isMinMemoryReached()) { + Logger::warning('Memory limit reached - quitting'); + return; + } + + // Children inherit their parent's database connection. + // To avoid problems we disconnect and connect both parent and child + DBA::disconnect(); + $pid = pcntl_fork(); + if ($pid == -1) { + DBA::connect(); + Logger::warning('Could not spawn worker'); + return; + } elseif ($pid) { + // The parent process continues here + DBA::connect(); + Logger::info('Spawned new worker', ['cron' => $do_cron, 'pid' => $pid]); + return; + } + + // We now are in the new worker + DBA::connect(); + Logger::info('Worker spawned', ['cron' => $do_cron, 'pid' => getmypid()]); + + DI::process()->start(); + + self::processQueue($do_cron); + + self::unclaimProcess(); + + DI::process()->end(); + Logger::info('Worker ended', ['cron' => $do_cron, 'pid' => getmypid()]); + + DBA::disconnect(); +/* + $php = '/usr/bin/php'; + $param = ['bin/worker.php']; + if ($do_cron) { + $param[] = 'no_cron'; + } + pcntl_exec($php, $param); + Logger::warning('Error calling worker', ['cron' => $do_cron, 'pid' => getmypid()]); +*/ + exit(); + } + /** * Spawns a new worker * @@ -1165,17 +1287,13 @@ class Worker */ public static function spawnWorker($do_cron = false) { - $command = 'bin/worker.php'; - - $args = ['no_cron' => !$do_cron]; - - $a = DI::app(); - $process = new Core\Process(DI::logger(), DI::mode(), DI::config(), DI::modelProcess(), $a->getBasePath(), getmypid()); - $process->run($command, $args); - - // after spawning we have to remove the flag. - if (DI::config()->get('system', 'worker_daemon_mode', false)) { + if (self::isDaemonMode()) { + self::forkProcess($do_cron); self::IPCSetJobState(false); + } else { + $process = new Core\Process(DI::logger(), DI::mode(), DI::config(), + DI::modelProcess(), DI::app()->getBasePath(), getmypid()); + $process->run('bin/worker.php', ['no_cron' => !$do_cron]); } } @@ -1215,6 +1333,7 @@ class Worker // Don't fork from frontend tasks by default $dont_fork = DI::config()->get("system", "worker_dont_fork", false) || !DI::mode()->isBackend(); $created = DateTimeFormat::utcNow(); + $delayed = DBA::NULL_DATETIME; $force_priority = false; $run_parameter = array_shift($args); @@ -1222,6 +1341,9 @@ class Worker if (is_int($run_parameter)) { $priority = $run_parameter; } elseif (is_array($run_parameter)) { + if (isset($run_parameter['delayed'])) { + $delayed = $run_parameter['delayed']; + } if (isset($run_parameter['priority'])) { $priority = $run_parameter['priority']; } @@ -1236,29 +1358,38 @@ class Worker } } + $command = array_shift($args); $parameters = json_encode($args); - $found = DBA::exists('workerqueue', ['parameter' => $parameters, 'done' => false]); + $found = DBA::exists('workerqueue', ['command' => $command, 'parameter' => $parameters, 'done' => false]); $added = false; + if (!in_array($priority, PRIORITIES)) { + Logger::warning('Invalid priority', ['priority' => $priority, 'command' => $command, 'callstack' => System::callstack(20)]); + $priority = PRIORITY_MEDIUM; + } + // Quit if there was a database error - a precaution for the update process to 3.5.3 if (DBA::errorNo() != 0) { return false; } if (!$found) { - $added = DBA::insert('workerqueue', ['parameter' => $parameters, 'created' => $created, 'priority' => $priority]); + $added = DBA::insert('workerqueue', ['command' => $command, 'parameter' => $parameters, 'created' => $created, + 'priority' => $priority, 'next_try' => $delayed]); if (!$added) { return false; } } elseif ($force_priority) { - DBA::update('workerqueue', ['priority' => $priority], ['parameter' => $parameters, 'done' => false, 'pid' => 0]); + DBA::update('workerqueue', ['priority' => $priority], ['command' => $command, 'parameter' => $parameters, 'done' => false, 'pid' => 0]); } // Set the IPC flag to ensure an immediate process execution via daemon - if (DI::config()->get('system', 'worker_daemon_mode', false)) { + if (self::isDaemonMode()) { self::IPCSetJobState(true); } + self::checkDaemonState(); + // Should we quit and wait for the worker to be called as a cronjob? if ($dont_fork) { return $added; @@ -1278,7 +1409,7 @@ class Worker } // Quit on daemon mode - if (DI::config()->get('system', 'worker_daemon_mode', false)) { + if (self::isDaemonMode()) { return $added; } @@ -1288,6 +1419,11 @@ class Worker return $added; } + public static function countWorkersByCommand(string $command) + { + return DBA::count('workerqueue', ['done' => false, 'pid' => 0, 'command' => $command]); + } + /** * Returns the next retrial level for worker jobs. * This function will skip levels when jobs are older. @@ -1310,7 +1446,7 @@ class Worker $new_retrial = $retrial; } } - Logger::info('New retrial for task', ['id' => $queue['id'], 'created' => $queue['created'], 'old' => $queue['retrial'], 'new' => $new_retrial]); + Logger::notice('New retrial for task', ['id' => $queue['id'], 'created' => $queue['created'], 'old' => $queue['retrial'], 'new' => $new_retrial]); return $new_retrial; } @@ -1336,7 +1472,7 @@ class Worker $new_retrial = self::getNextRetrial($queue, $max_level); if ($new_retrial > $max_level) { - Logger::info('The task exceeded the maximum retry count', ['id' => $id, 'created' => $queue['created'], 'old_prio' => $queue['priority'], 'old_retrial' => $queue['retrial'], 'max_level' => $max_level, 'retrial' => $new_retrial]); + Logger::notice('The task exceeded the maximum retry count', ['id' => $id, 'created' => $queue['created'], 'old_prio' => $queue['priority'], 'old_retrial' => $queue['retrial'], 'max_level' => $max_level, 'retrial' => $new_retrial]); return false; } @@ -1397,6 +1533,110 @@ class Worker return (bool)$row['jobs']; } + /** + * Checks if the worker is running in the daemon mode. + * + * @return boolean + */ + public static function isDaemonMode() + { + if (!is_null(self::$daemon_mode)) { + return self::$daemon_mode; + } + + if (DI::mode()->getExecutor() == Mode::DAEMON) { + return true; + } + + $daemon_mode = DI::config()->get('system', 'worker_daemon_mode', false, true); + if ($daemon_mode) { + return $daemon_mode; + } + + if (!function_exists('pcntl_fork')) { + self::$daemon_mode = false; + return false; + } + + $pidfile = DI::config()->get('system', 'pidfile'); + if (empty($pidfile)) { + // No pid file, no daemon + self::$daemon_mode = false; + return false; + } + + if (!is_readable($pidfile)) { + // No pid file. We assume that the daemon had been intentionally stopped. + self::$daemon_mode = false; + return false; + } + + $pid = intval(file_get_contents($pidfile)); + $running = posix_kill($pid, 0); + + self::$daemon_mode = $running; + return $running; + } + + /** + * Test if the daemon is running. If not, it will be started + * + * @return void + */ + private static function checkDaemonState() + { + if (!DI::config()->get('system', 'daemon_watchdog', false)) { + return; + } + + if (!DI::mode()->isNormal()) { + return; + } + + // Check every minute if the daemon is running + if (DI::config()->get('system', 'last_daemon_check', 0) + 60 > time()) { + return; + } + + DI::config()->set('system', 'last_daemon_check', time()); + + $pidfile = DI::config()->get('system', 'pidfile'); + if (empty($pidfile)) { + // No pid file, no daemon + return; + } + + if (!is_readable($pidfile)) { + // No pid file. We assume that the daemon had been intentionally stopped. + return; + } + + $pid = intval(file_get_contents($pidfile)); + if (posix_kill($pid, 0)) { + Logger::info('Daemon process is running', ['pid' => $pid]); + return; + } + + Logger::warning('Daemon process is not running', ['pid' => $pid]); + + self::spawnDaemon(); + } + + /** + * Spawn a new daemon process + * + * @return void + */ + private static function spawnDaemon() + { + Logger::notice('Starting new daemon process'); + $command = 'bin/daemon.php'; + $a = DI::app(); + $process = new Core\Process(DI::logger(), DI::mode(), DI::config(), DI::modelProcess(), $a->getBasePath(), getmypid()); + $process->run($command, ['start']); + Logger::notice('New daemon process started'); + } + /** * Check if the system is inside the defined maintenance window *