]> git.mxchange.org Git - friendica.git/blob - src/Core/Worker.php
bfe70c39c8db69d3c3a9b8ced3c15b3ae4678169
[friendica.git] / src / Core / Worker.php
1 <?php
2 /**
3  * @file src/Core/Worker.php
4  */
5 namespace Friendica\Core;
6
7 use Friendica\BaseObject;
8 use Friendica\Database\DBA;
9 use Friendica\Model\Process;
10 use Friendica\Util\DateTimeFormat;
11 use Friendica\Util\Logger\WorkerLogger;
12 use Friendica\Util\Network;
13
14 /**
15  * @file src/Core/Worker.php
16  *
17  * @brief Contains the class for the worker background job processing
18  */
19
20 /**
21  * @brief Worker methods
22  */
23 class Worker
24 {
25         private static $up_start;
26         private static $db_duration = 0;
27         private static $db_duration_count = 0;
28         private static $db_duration_write = 0;
29         private static $db_duration_stat = 0;
30         private static $lock_duration = 0;
31         private static $last_update;
32
33         /**
34          * @brief Processes the tasks that are in the workerqueue table
35          *
36          * @param boolean $run_cron Should the cron processes be executed?
37          * @return void
38          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
39          */
40         public static function processQueue($run_cron = true)
41         {
42                 $a = \get_app();
43
44                 // Ensure that all "strtotime" operations do run timezone independent
45                 date_default_timezone_set('UTC');
46
47                 self::$up_start = microtime(true);
48
49                 // At first check the maximum load. We shouldn't continue with a high load
50                 if ($a->isMaxLoadReached()) {
51                         Logger::log('Pre check: maximum load reached, quitting.', Logger::DEBUG);
52                         return;
53                 }
54
55                 // We now start the process. This is done after the load check since this could increase the load.
56                 self::startProcess();
57
58                 // Kill stale processes every 5 minutes
59                 $last_cleanup = Config::get('system', 'worker_last_cleaned', 0);
60                 if (time() > ($last_cleanup + 300)) {
61                         Config::set('system', 'worker_last_cleaned', time());
62                         self::killStaleWorkers();
63                 }
64
65                 // Count active workers and compare them with a maximum value that depends on the load
66                 if (self::tooMuchWorkers()) {
67                         Logger::log('Pre check: Active worker limit reached, quitting.', Logger::DEBUG);
68                         return;
69                 }
70
71                 // Do we have too few memory?
72                 if ($a->isMinMemoryReached()) {
73                         Logger::log('Pre check: Memory limit reached, quitting.', Logger::DEBUG);
74                         return;
75                 }
76
77                 // Possibly there are too much database connections
78                 if (self::maxConnectionsReached()) {
79                         Logger::log('Pre check: maximum connections reached, quitting.', Logger::DEBUG);
80                         return;
81                 }
82
83                 // Possibly there are too much database processes that block the system
84                 if ($a->isMaxProcessesReached()) {
85                         Logger::log('Pre check: maximum processes reached, quitting.', Logger::DEBUG);
86                         return;
87                 }
88
89                 // Now we start additional cron processes if we should do so
90                 if ($run_cron) {
91                         self::runCron();
92                 }
93
94                 $starttime = time();
95
96                 // We fetch the next queue entry that is about to be executed
97                 while ($r = self::workerProcess()) {
98                         foreach ($r as $entry) {
99                                 // Assure that the priority is an integer value
100                                 $entry['priority'] = (int)$entry['priority'];
101
102                                 // The work will be done
103                                 if (!self::execute($entry)) {
104                                         Logger::log('Process execution failed, quitting.', Logger::DEBUG);
105                                         return;
106                                 }
107
108                                 // If possible we will fetch new jobs for this worker
109                                 if (!self::getWaitingJobForPID() && Lock::acquire('worker_process', 0)) {
110                                         self::findWorkerProcesses();
111                                         Lock::release('worker_process');
112                                 }
113                         }
114
115                         // To avoid the quitting of multiple workers only one worker at a time will execute the check
116                         if (Lock::acquire('worker', 0)) {
117                                 // Count active workers and compare them with a maximum value that depends on the load
118                                 if (self::tooMuchWorkers()) {
119                                         Logger::log('Active worker limit reached, quitting.', Logger::DEBUG);
120                                         Lock::release('worker');
121                                         return;
122                                 }
123
124                                 // Check free memory
125                                 if ($a->isMinMemoryReached()) {
126                                         Logger::log('Memory limit reached, quitting.', Logger::DEBUG);
127                                         Lock::release('worker');
128                                         return;
129                                 }
130                                 Lock::release('worker');
131                         }
132
133                         // Quit the worker once every 5 minutes
134                         if (time() > ($starttime + 300)) {
135                                 Logger::log('Process lifetime reached, quitting.', Logger::DEBUG);
136                                 return;
137                         }
138                 }
139
140                 // Cleaning up. Possibly not needed, but it doesn't harm anything.
141                 if (Config::get('system', 'worker_daemon_mode', false)) {
142                         self::IPCSetJobState(false);
143                 }
144                 Logger::log("Couldn't select a workerqueue entry, quitting process " . getmypid() . ".", Logger::DEBUG);
145         }
146
147         /**
148          * @brief Check if non executed tasks do exist in the worker queue
149          *
150          * @return boolean Returns "true" if tasks are existing
151          * @throws \Exception
152          */
153         private static function entriesExists()
154         {
155                 $stamp = (float)microtime(true);
156                 $exists = DBA::exists('workerqueue', ["NOT `done` AND `pid` = 0 AND `next_try` < ?", DateTimeFormat::utcNow()]);
157                 self::$db_duration += (microtime(true) - $stamp);
158                 return $exists;
159         }
160
161         /**
162          * @brief Returns the number of deferred entries in the worker queue
163          *
164          * @return integer Number of deferred entries in the worker queue
165          * @throws \Exception
166          */
167         private static function deferredEntries()
168         {
169                 $stamp = (float)microtime(true);
170                 $count = DBA::count('workerqueue', ["NOT `done` AND `pid` = 0 AND `next_try` > ?", DateTimeFormat::utcNow()]);
171                 self::$db_duration += (microtime(true) - $stamp);
172                 self::$db_duration_count += (microtime(true) - $stamp);
173                 return $count;
174         }
175
176         /**
177          * @brief Returns the number of non executed entries in the worker queue
178          *
179          * @return integer Number of non executed entries in the worker queue
180          * @throws \Exception
181          */
182         private static function totalEntries()
183         {
184                 $stamp = (float)microtime(true);
185                 $count = DBA::count('workerqueue', ['done' => false, 'pid' => 0]);
186                 self::$db_duration += (microtime(true) - $stamp);
187                 self::$db_duration_count += (microtime(true) - $stamp);
188                 return $count;
189         }
190
191         /**
192          * @brief Returns the highest priority in the worker queue that isn't executed
193          *
194          * @return integer Number of active worker processes
195          * @throws \Exception
196          */
197         private static function highestPriority()
198         {
199                 $stamp = (float)microtime(true);
200                 $condition = ["`pid` = 0 AND NOT `done` AND `next_try` < ?", DateTimeFormat::utcNow()];
201                 $workerqueue = DBA::selectFirst('workerqueue', ['priority'], $condition, ['order' => ['priority']]);
202                 self::$db_duration += (microtime(true) - $stamp);
203                 if (DBA::isResult($workerqueue)) {
204                         return $workerqueue["priority"];
205                 } else {
206                         return 0;
207                 }
208         }
209
210         /**
211          * @brief Returns if a process with the given priority is running
212          *
213          * @param integer $priority The priority that should be checked
214          *
215          * @return integer Is there a process running with that priority?
216          * @throws \Exception
217          */
218         private static function processWithPriorityActive($priority)
219         {
220                 $condition = ["`priority` <= ? AND `pid` != 0 AND NOT `done`", $priority];
221                 return DBA::exists('workerqueue', $condition);
222         }
223
224         /**
225          * @brief Execute a worker entry
226          *
227          * @param array $queue Workerqueue entry
228          *
229          * @return boolean "true" if further processing should be stopped
230          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
231          */
232         public static function execute($queue)
233         {
234                 $a = \get_app();
235
236                 $mypid = getmypid();
237
238                 // Quit when in maintenance
239                 if (Config::get('system', 'maintenance', false, true)) {
240                         Logger::log("Maintenance mode - quit process ".$mypid, Logger::DEBUG);
241                         return false;
242                 }
243
244                 // Constantly check the number of parallel database processes
245                 if ($a->isMaxProcessesReached()) {
246                         Logger::log("Max processes reached for process ".$mypid, Logger::DEBUG);
247                         return false;
248                 }
249
250                 // Constantly check the number of available database connections to let the frontend be accessible at any time
251                 if (self::maxConnectionsReached()) {
252                         Logger::log("Max connection reached for process ".$mypid, Logger::DEBUG);
253                         return false;
254                 }
255
256                 $argv = json_decode($queue["parameter"], true);
257
258                 // Check for existance and validity of the include file
259                 $include = $argv[0];
260
261                 if (method_exists(sprintf('Friendica\Worker\%s', $include), 'execute')) {
262                         // We constantly update the "executed" date every minute to avoid being killed too soon
263                         if (!isset(self::$last_update)) {
264                                 self::$last_update = strtotime($queue["executed"]);
265                         }
266
267                         $age = (time() - self::$last_update) / 60;
268                         self::$last_update = time();
269
270                         if ($age > 1) {
271                                 $stamp = (float)microtime(true);
272                                 DBA::update('workerqueue', ['executed' => DateTimeFormat::utcNow()], ['pid' => $mypid, 'done' => false]);
273                                 self::$db_duration += (microtime(true) - $stamp);
274                                 self::$db_duration_write += (microtime(true) - $stamp);
275                         }
276
277                         array_shift($argv);
278
279                         self::execFunction($queue, $include, $argv, true);
280
281                         $stamp = (float)microtime(true);
282                         $condition = ["`id` = ? AND `next_try` < ?", $queue['id'], DateTimeFormat::utcNow()];
283                         if (DBA::update('workerqueue', ['done' => true], $condition)) {
284                                 Config::set('system', 'last_worker_execution', DateTimeFormat::utcNow());
285                         }
286                         self::$db_duration = (microtime(true) - $stamp);
287                         self::$db_duration_write += (microtime(true) - $stamp);
288
289                         return true;
290                 }
291
292                 // The script could be provided as full path or only with the function name
293                 if ($include == basename($include)) {
294                         $include = "include/".$include.".php";
295                 }
296
297                 if (!validate_include($include)) {
298                         Logger::log("Include file ".$argv[0]." is not valid!");
299                         $stamp = (float)microtime(true);
300                         DBA::delete('workerqueue', ['id' => $queue["id"]]);
301                         self::$db_duration = (microtime(true) - $stamp);
302                         self::$db_duration_write += (microtime(true) - $stamp);
303                         return true;
304                 }
305
306                 require_once $include;
307
308                 $funcname = str_replace(".php", "", basename($argv[0]))."_run";
309
310                 if (function_exists($funcname)) {
311                         // We constantly update the "executed" date every minute to avoid being killed too soon
312                         if (!isset(self::$last_update)) {
313                                 self::$last_update = strtotime($queue["executed"]);
314                         }
315
316                         $age = (time() - self::$last_update) / 60;
317                         self::$last_update = time();
318
319                         if ($age > 1) {
320                                 $stamp = (float)microtime(true);
321                                 DBA::update('workerqueue', ['executed' => DateTimeFormat::utcNow()], ['pid' => $mypid, 'done' => false]);
322                                 self::$db_duration += (microtime(true) - $stamp);
323                                 self::$db_duration_write += (microtime(true) - $stamp);
324                         }
325
326                         self::execFunction($queue, $funcname, $argv, false);
327
328                         $stamp = (float)microtime(true);
329                         if (DBA::update('workerqueue', ['done' => true], ['id' => $queue["id"]])) {
330                                 Config::set('system', 'last_worker_execution', DateTimeFormat::utcNow());
331                         }
332                         self::$db_duration = (microtime(true) - $stamp);
333                         self::$db_duration_write += (microtime(true) - $stamp);
334                 } else {
335                         Logger::log("Function ".$funcname." does not exist");
336                         $stamp = (float)microtime(true);
337                         DBA::delete('workerqueue', ['id' => $queue["id"]]);
338                         self::$db_duration = (microtime(true) - $stamp);
339                         self::$db_duration_write += (microtime(true) - $stamp);
340                 }
341
342                 return true;
343         }
344
345         /**
346          * @brief Execute a function from the queue
347          *
348          * @param array   $queue       Workerqueue entry
349          * @param string  $funcname    name of the function
350          * @param array   $argv        Array of values to be passed to the function
351          * @param boolean $method_call boolean
352          * @return void
353          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
354          */
355         private static function execFunction($queue, $funcname, $argv, $method_call)
356         {
357                 $a = \get_app();
358
359                 $mypid = getmypid();
360
361                 $argc = count($argv);
362
363                 $logger = $a->getLogger();
364                 $workerLogger = new WorkerLogger($logger, $funcname);
365
366                 $workerLogger ->info("Process start.", ['process' => $mypid, 'priority' => $queue["priority"], 'id' => $queue["id"]]);
367
368                 $stamp = (float)microtime(true);
369
370                 // We use the callstack here to analyze the performance of executed worker entries.
371                 // For this reason the variables have to be initialized.
372                 $a->getProfiler()->reset();
373
374                 $up_duration = microtime(true) - self::$up_start;
375
376                 // Reset global data to avoid interferences
377                 unset($_SESSION);
378
379                 Logger::init($workerLogger);
380                 if ($method_call) {
381                         call_user_func_array(sprintf('Friendica\Worker\%s::execute', $funcname), $argv);
382                 } else {
383                         $funcname($argv, $argc);
384                 }
385                 Logger::init($logger);
386
387                 unset($a->queue);
388
389                 $duration = (microtime(true) - $stamp);
390
391                 /* With these values we can analyze how effective the worker is.
392                  * The database and rest time should be low since this is the unproductive time.
393                  * The execution time is the productive time.
394                  * By changing parameters like the maximum number of workers we can check the effectivness.
395                 */
396                 $dbtotal = number_format(self::$db_duration - (self::$db_duration_count + self::$db_duration_write + self::$db_duration_stat), 4);
397                 $dbcount = number_format(self::$db_duration_count, 4);
398                 $dbstat  = number_format(self::$db_duration_stat, 4);
399                 $dbwrite = number_format(self::$db_duration_write, 4);
400                 $dblock  = number_format(self::$lock_duration, 4);
401                 $rest    = number_format(max(0, $up_duration - (self::$db_duration + self::$lock_duration)), 4);
402                 $exec    = number_format($duration, 4);
403
404                 Logger::info('Performance:', ['total' => $dbtotal, 'count' => $dbcount, 'stat' => $dbstat, 'write' => $dbwrite, 'block' => $dblock, 'rest' => $rest, 'exec' => $exec]);
405
406                 self::$up_start = microtime(true);
407                 self::$db_duration = 0;
408                 self::$db_duration_count = 0;
409                 self::$db_duration_stat = 0;
410                 self::$db_duration_write = 0;
411                 self::$lock_duration = 0;
412
413                 if ($duration > 3600) {
414                         Logger::log("Prio ".$queue["priority"].": ".$queue["parameter"]." - longer than 1 hour (".round($duration/60, 3).")", Logger::DEBUG);
415                 } elseif ($duration > 600) {
416                         Logger::log("Prio ".$queue["priority"].": ".$queue["parameter"]." - longer than 10 minutes (".round($duration/60, 3).")", Logger::DEBUG);
417                 } elseif ($duration > 300) {
418                         Logger::log("Prio ".$queue["priority"].": ".$queue["parameter"]." - longer than 5 minutes (".round($duration/60, 3).")", Logger::DEBUG);
419                 } elseif ($duration > 120) {
420                         Logger::log("Prio ".$queue["priority"].": ".$queue["parameter"]." - longer than 2 minutes (".round($duration/60, 3).")", Logger::DEBUG);
421                 }
422
423                 Logger::log("Process ".$mypid." - Prio ".$queue["priority"]." - ID ".$queue["id"].": ".$funcname." - done in ".number_format($duration, 4)." seconds.");
424
425                 $a->getProfiler()->saveLog($a->getLogger(), "ID " . $queue["id"] . ": " . $funcname);
426
427                 $cooldown = Config::get("system", "worker_cooldown", 0);
428
429                 if ($cooldown > 0) {
430                         Logger::log("Process ".$mypid." - Prio ".$queue["priority"]." - ID ".$queue["id"].": ".$funcname." - in cooldown for ".$cooldown." seconds");
431                         sleep($cooldown);
432                 }
433         }
434
435         /**
436          * @brief Checks if the number of database connections has reached a critical limit.
437          *
438          * @return bool Are more than 3/4 of the maximum connections used?
439          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
440          */
441         private static function maxConnectionsReached()
442         {
443                 // Fetch the max value from the config. This is needed when the system cannot detect the correct value by itself.
444                 $max = Config::get("system", "max_connections");
445
446                 // Fetch the percentage level where the worker will get active
447                 $maxlevel = Config::get("system", "max_connections_level", 75);
448
449                 if ($max == 0) {
450                         // the maximum number of possible user connections can be a system variable
451                         $r = DBA::fetchFirst("SHOW VARIABLES WHERE `variable_name` = 'max_user_connections'");
452                         if (DBA::isResult($r)) {
453                                 $max = $r["Value"];
454                         }
455                         // Or it can be granted. This overrides the system variable
456                         $stamp = (float)microtime(true);
457                         $r = DBA::p('SHOW GRANTS');
458                         self::$db_duration += (microtime(true) - $stamp);
459                         while ($grants = DBA::fetch($r)) {
460                                 $grant = array_pop($grants);
461                                 if (stristr($grant, "GRANT USAGE ON")) {
462                                         if (preg_match("/WITH MAX_USER_CONNECTIONS (\d*)/", $grant, $match)) {
463                                                 $max = $match[1];
464                                         }
465                                 }
466                         }
467                         DBA::close($r);
468                 }
469
470                 // If $max is set we will use the processlist to determine the current number of connections
471                 // The processlist only shows entries of the current user
472                 if ($max != 0) {
473                         $stamp = (float)microtime(true);
474                         $r = DBA::p('SHOW PROCESSLIST');
475                         self::$db_duration += (microtime(true) - $stamp);
476                         $used = DBA::numRows($r);
477                         DBA::close($r);
478
479                         Logger::log("Connection usage (user values): ".$used."/".$max, Logger::DEBUG);
480
481                         $level = ($used / $max) * 100;
482
483                         if ($level >= $maxlevel) {
484                                 Logger::log("Maximum level (".$maxlevel."%) of user connections reached: ".$used."/".$max);
485                                 return true;
486                         }
487                 }
488
489                 // We will now check for the system values.
490                 // This limit could be reached although the user limits are fine.
491                 $r = DBA::fetchFirst("SHOW VARIABLES WHERE `variable_name` = 'max_connections'");
492                 if (!DBA::isResult($r)) {
493                         return false;
494                 }
495                 $max = intval($r["Value"]);
496                 if ($max == 0) {
497                         return false;
498                 }
499                 $r = DBA::fetchFirst("SHOW STATUS WHERE `variable_name` = 'Threads_connected'");
500                 if (!DBA::isResult($r)) {
501                         return false;
502                 }
503                 $used = intval($r["Value"]);
504                 if ($used == 0) {
505                         return false;
506                 }
507                 Logger::log("Connection usage (system values): ".$used."/".$max, Logger::DEBUG);
508
509                 $level = $used / $max * 100;
510
511                 if ($level < $maxlevel) {
512                         return false;
513                 }
514                 Logger::log("Maximum level (".$level."%) of system connections reached: ".$used."/".$max);
515                 return true;
516         }
517
518         /**
519          * @brief fix the queue entry if the worker process died
520          * @return void
521          * @throws \Exception
522          */
523         private static function killStaleWorkers()
524         {
525                 $stamp = (float)microtime(true);
526                 $entries = DBA::select(
527                         'workerqueue',
528                         ['id', 'pid', 'executed', 'priority', 'parameter'],
529                         ['NOT `done` AND `pid` != 0'],
530                         ['order' => ['priority', 'created']]
531                 );
532                 self::$db_duration += (microtime(true) - $stamp);
533
534                 while ($entry = DBA::fetch($entries)) {
535                         if (!posix_kill($entry["pid"], 0)) {
536                                 $stamp = (float)microtime(true);
537                                 DBA::update(
538                                         'workerqueue',
539                                         ['executed' => DBA::NULL_DATETIME, 'pid' => 0],
540                                         ['id' => $entry["id"]]
541                                 );
542                                 self::$db_duration += (microtime(true) - $stamp);
543                                 self::$db_duration_write += (microtime(true) - $stamp);
544                         } else {
545                                 // Kill long running processes
546                                 // Check if the priority is in a valid range
547                                 if (!in_array($entry["priority"], [PRIORITY_CRITICAL, PRIORITY_HIGH, PRIORITY_MEDIUM, PRIORITY_LOW, PRIORITY_NEGLIGIBLE])) {
548                                         $entry["priority"] = PRIORITY_MEDIUM;
549                                 }
550
551                                 // Define the maximum durations
552                                 $max_duration_defaults = [PRIORITY_CRITICAL => 720, PRIORITY_HIGH => 10, PRIORITY_MEDIUM => 60, PRIORITY_LOW => 180, PRIORITY_NEGLIGIBLE => 720];
553                                 $max_duration = $max_duration_defaults[$entry["priority"]];
554
555                                 $argv = json_decode($entry["parameter"], true);
556                                 $argv[0] = basename($argv[0]);
557
558                                 // How long is the process already running?
559                                 $duration = (time() - strtotime($entry["executed"])) / 60;
560                                 if ($duration > $max_duration) {
561                                         Logger::log("Worker process ".$entry["pid"]." (".substr(json_encode($argv), 0, 50).") took more than ".$max_duration." minutes. It will be killed now.");
562                                         posix_kill($entry["pid"], SIGTERM);
563
564                                         // We killed the stale process.
565                                         // To avoid a blocking situation we reschedule the process at the beginning of the queue.
566                                         // Additionally we are lowering the priority. (But not PRIORITY_CRITICAL)
567                                         $new_priority = $entry["priority"];
568                                         if ($entry["priority"] == PRIORITY_HIGH) {
569                                                 $new_priority = PRIORITY_MEDIUM;
570                                         } elseif ($entry["priority"] == PRIORITY_MEDIUM) {
571                                                 $new_priority = PRIORITY_LOW;
572                                         } elseif ($entry["priority"] != PRIORITY_CRITICAL) {
573                                                 $new_priority = PRIORITY_NEGLIGIBLE;
574                                         }
575                                         $stamp = (float)microtime(true);
576                                         DBA::update(
577                                                 'workerqueue',
578                                                 ['executed' => DBA::NULL_DATETIME, 'created' => DateTimeFormat::utcNow(), 'priority' => $new_priority, 'pid' => 0],
579                                                 ['id' => $entry["id"]]
580                                         );
581                                         self::$db_duration += (microtime(true) - $stamp);
582                                         self::$db_duration_write += (microtime(true) - $stamp);
583                                 } else {
584                                         Logger::log("Worker process ".$entry["pid"]." (".substr(json_encode($argv), 0, 50).") now runs for ".round($duration)." of ".$max_duration." allowed minutes. That's okay.", Logger::DEBUG);
585                                 }
586                         }
587                 }
588         }
589
590         /**
591          * @brief Checks if the number of active workers exceeds the given limits
592          *
593          * @return bool Are there too much workers running?
594          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
595          */
596         private static function tooMuchWorkers()
597         {
598                 $queues = Config::get("system", "worker_queues", 4);
599
600                 $maxqueues = $queues;
601
602                 $active = self::activeWorkers();
603
604                 // Decrease the number of workers at higher load
605                 $load = System::currentLoad();
606                 if ($load) {
607                         $maxsysload = intval(Config::get("system", "maxloadavg", 50));
608
609                         /* Default exponent 3 causes queues to rapidly decrease as load increases.
610                          * If you have 20 max queues at idle, then you get only 5 queues at 37.1% of $maxsysload.
611                          * For some environments, this rapid decrease is not needed.
612                          * With exponent 1, you could have 20 max queues at idle and 13 at 37% of $maxsysload.
613                          */
614                         $exponent = intval(Config::get('system', 'worker_load_exponent', 3));
615                         $slope = pow(max(0, $maxsysload - $load) / $maxsysload, $exponent);
616                         $queues = intval(ceil($slope * $maxqueues));
617
618                         $processlist = '';
619
620                         if (Config::get('system', 'worker_jpm')) {
621                                 $intervals = explode(',', Config::get('system', 'worker_jpm_range'));
622                                 $jobs_per_minute = [];
623                                 foreach ($intervals as $interval) {
624                                         if ($interval == 0) {
625                                                 continue;
626                                         } else {
627                                                 $interval = (int)$interval;
628                                         }
629
630                                         $stamp = (float)microtime(true);
631                                         $jobs = DBA::p("SELECT COUNT(*) AS `jobs` FROM `workerqueue` WHERE `done` AND `executed` > UTC_TIMESTAMP() - INTERVAL ? MINUTE", $interval);
632                                         self::$db_duration += (microtime(true) - $stamp);
633                                         self::$db_duration_stat += (microtime(true) - $stamp);
634                                         if ($job = DBA::fetch($jobs)) {
635                                                 $jobs_per_minute[$interval] = number_format($job['jobs'] / $interval, 0);
636                                         }
637                                         DBA::close($jobs);
638                                 }
639                                 $processlist = ' - jpm: '.implode('/', $jobs_per_minute);
640                         }
641
642                         // Create a list of queue entries grouped by their priority
643                         $listitem = [0 => ''];
644
645                         $idle_workers = $active;
646
647                         $deferred = self::deferredEntries();
648
649                         if (Config::get('system', 'worker_debug')) {
650                                 $waiting_processes = 0;
651                                 // Now adding all processes with workerqueue entries
652                                 $stamp = (float)microtime(true);
653                                 $jobs = DBA::p("SELECT COUNT(*) AS `entries`, `priority` FROM `workerqueue` WHERE NOT `done` AND `next_try` < ? GROUP BY `priority`", DateTimeFormat::utcNow());
654                                 self::$db_duration += (microtime(true) - $stamp);
655                                 self::$db_duration_stat += (microtime(true) - $stamp);
656                                 while ($entry = DBA::fetch($jobs)) {
657                                         $stamp = (float)microtime(true);
658                                         $processes = DBA::p("SELECT COUNT(*) AS `running` FROM `process` INNER JOIN `workerqueue` ON `workerqueue`.`pid` = `process`.`pid` WHERE NOT `done` AND `priority` = ?", $entry["priority"]);
659                                         self::$db_duration += (microtime(true) - $stamp);
660                                         self::$db_duration_stat += (microtime(true) - $stamp);
661                                         if ($process = DBA::fetch($processes)) {
662                                                 $idle_workers -= $process["running"];
663                                                 $waiting_processes += $entry["entries"];
664                                                 $listitem[$entry["priority"]] = $entry["priority"].":".$process["running"]."/".$entry["entries"];
665                                         }
666                                         DBA::close($processes);
667                                 }
668                                 DBA::close($jobs);
669                                 $entries = $deferred + $waiting_processes;
670                         } else {
671                                 $entries = self::totalEntries();
672                                 $waiting_processes = max(0, $entries - $deferred);
673                                 $stamp = (float)microtime(true);
674                                 $jobs = DBA::p("SELECT COUNT(*) AS `running`, `priority` FROM `process` INNER JOIN `workerqueue` ON `workerqueue`.`pid` = `process`.`pid` AND NOT `done` GROUP BY `priority` ORDER BY `priority`");
675                                 self::$db_duration += (microtime(true) - $stamp);
676                                 self::$db_duration_stat += (microtime(true) - $stamp);
677
678                                 while ($entry = DBA::fetch($jobs)) {
679                                         $idle_workers -= $entry["running"];
680                                         $listitem[$entry["priority"]] = $entry["priority"].":".$entry["running"];
681                                 }
682                                 DBA::close($jobs);
683                         }
684
685                         $listitem[0] = "0:" . max(0, $idle_workers);
686
687                         $processlist .= ' ('.implode(', ', $listitem).')';
688
689                         if (Config::get("system", "worker_fastlane", false) && ($queues > 0) && self::entriesExists() && ($active >= $queues)) {
690                                 $top_priority = self::highestPriority();
691                                 $high_running = self::processWithPriorityActive($top_priority);
692
693                                 if (!$high_running && ($top_priority > PRIORITY_UNDEFINED) && ($top_priority < PRIORITY_NEGLIGIBLE)) {
694                                         Logger::log("There are jobs with priority ".$top_priority." waiting but none is executed. Open a fastlane.", Logger::DEBUG);
695                                         $queues = $active + 1;
696                                 }
697                         }
698
699                         Logger::log("Load: " . $load ."/" . $maxsysload . " - processes: " . $deferred . "/" . $active . "/" . $waiting_processes . $processlist . " - maximum: " . $queues . "/" . $maxqueues, Logger::DEBUG);
700
701                         // Are there fewer workers running as possible? Then fork a new one.
702                         if (!Config::get("system", "worker_dont_fork", false) && ($queues > ($active + 1)) && ($entries > 1)) {
703                                 Logger::log("Active workers: ".$active."/".$queues." Fork a new worker.", Logger::DEBUG);
704                                 if (Config::get('system', 'worker_daemon_mode', false)) {
705                                         self::IPCSetJobState(true);
706                                 } else {
707                                         self::spawnWorker();
708                                 }
709                         }
710                 }
711
712                 // if there are too much worker, we don't spawn a new one.
713                 if (Config::get('system', 'worker_daemon_mode', false) && ($active > $queues)) {
714                         self::IPCSetJobState(false);
715                 }
716
717                 return $active > $queues;
718         }
719
720         /**
721          * @brief Returns the number of active worker processes
722          *
723          * @return integer Number of active worker processes
724          * @throws \Exception
725          */
726         private static function activeWorkers()
727         {
728                 $stamp = (float)microtime(true);
729                 $count = DBA::count('process', ['command' => 'Worker.php']);
730                 self::$db_duration += (microtime(true) - $stamp);
731                 return $count;
732         }
733
734         /**
735          * @brief Returns waiting jobs for the current process id
736          *
737          * @return array waiting workerqueue jobs
738          * @throws \Exception
739          */
740         private static function getWaitingJobForPID()
741         {
742                 $stamp = (float)microtime(true);
743                 $r = DBA::select('workerqueue', [], ['pid' => getmypid(), 'done' => false]);
744                 self::$db_duration += (microtime(true) - $stamp);
745                 if (DBA::isResult($r)) {
746                         return DBA::toArray($r);
747                 }
748                 DBA::close($r);
749
750                 return false;
751         }
752
753         /**
754          * @brief Returns the next jobs that should be executed
755          *
756          * @return array array with next jobs
757          * @throws \Exception
758          */
759         private static function nextProcess()
760         {
761                 $priority = self::nextPriority();
762                 if (empty($priority)) {
763                         Logger::info('No tasks found');
764                         return [];
765                 }
766
767                 if ($priority <= PRIORITY_MEDIUM) {
768                         $limit = Config::get('system', 'worker_fetch_limit', 1);
769                 } else {
770                         $limit = 1;
771                 }
772
773                 $ids = [];
774                 $stamp = (float)microtime(true);
775                 $condition = ["`priority` = ? AND `pid` = 0 AND NOT `done` AND `next_try` < ?", $priority, DateTimeFormat::utcNow()];
776                 $tasks = DBA::select('workerqueue', ['id'], $condition, ['limit' => $limit, 'order' => ['created']]);
777                 self::$db_duration += (microtime(true) - $stamp);
778                 while ($task = DBA::fetch($tasks)) {
779                         $ids[] = $task['id'];
780                 }
781                 DBA::close($tasks);
782
783                 Logger::info('Found:', ['id' => $ids, 'priority' => $priority]);
784                 return $ids;
785         }
786
787         /**
788          * @brief Returns the priority of the next workerqueue job
789          *
790          * @return string priority
791          * @throws \Exception
792          */
793         private static function nextPriority()
794         {
795                 $waiting = [];
796                 $priorities = [PRIORITY_CRITICAL, PRIORITY_HIGH, PRIORITY_MEDIUM, PRIORITY_LOW, PRIORITY_NEGLIGIBLE];
797                 foreach ($priorities as $priority) {
798                         $stamp = (float)microtime(true);
799                         if (DBA::exists('workerqueue', ["`priority` = ? AND `pid` = 0 AND NOT `done` AND `next_try` < ?", $priority, DateTimeFormat::utcNow()])) {
800                                 $waiting[$priority] = true;
801                         }
802                         self::$db_duration += (microtime(true) - $stamp);
803                 }
804
805                 if (!empty($waiting[PRIORITY_CRITICAL])) {
806                         return PRIORITY_CRITICAL;
807                 }
808
809                 $running = [];
810                 $running_total = 0;
811                 $stamp = (float)microtime(true);
812                 $processes = DBA::p("SELECT COUNT(DISTINCT(`process`.`pid`)) AS `running`, `priority` FROM `process`
813                         INNER JOIN `workerqueue` ON `workerqueue`.`pid` = `process`.`pid`
814                         WHERE NOT `done` GROUP BY `priority`");
815                 self::$db_duration += (microtime(true) - $stamp);
816                 while ($process = DBA::fetch($processes)) {
817                         $running[$process['priority']] = $process['running'];
818                         $running_total += $process['running'];
819                 }
820                 DBA::close($processes);
821
822                 foreach ($priorities as $priority) {
823                         if (!empty($waiting[$priority]) && empty($running[$priority])) {
824                                 Logger::info('No running worker found with priority {priority} - assigning it.', ['priority' => $priority]);
825                                 return $priority;
826                         }
827                 }
828
829                 $active = max(self::activeWorkers(), $running_total);
830                 $priorities = max(count($waiting), count($running));
831                 $exponent = 2;
832
833                 $total = 0;
834                 for ($i = 1; $i <= $priorities; ++$i) {
835                         $total += pow($i, $exponent);
836                 }
837
838                 $limit = [];
839                 for ($i = 1; $i <= $priorities; ++$i) {
840                         $limit[$priorities - $i] = max(1, round($active * (pow($i, $exponent) / $total)));
841                 }
842
843                 $i = 0;
844                 foreach ($running as $priority => $workers) {
845                         if ($workers < $limit[$i++]) {
846                                 Logger::info('Priority {priority} has got {workers} workers out of a limit of {limit}', ['priority' => $priority, 'workers' => $workers, 'limit' => $limit[$i - 1]]);
847                                 return $priority;
848                         }
849                 }
850
851                 if (!empty($waiting)) {
852                         $priority =  array_shift(array_keys($waiting));
853                         Logger::info('No underassigned priority found, now taking the highest priority.', ['priority' => $priority]);
854                         return $priority;
855                 }
856
857                 return false;
858         }
859
860         /**
861          * @brief Find and claim the next worker process for us
862          *
863          * @return boolean Have we found something?
864          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
865          */
866         private static function findWorkerProcesses()
867         {
868                 $mypid = getmypid();
869
870                 $ids = self::nextProcess();
871
872                 // If there is no result we check without priority limit
873                 if (empty($ids)) {
874                         $stamp = (float)microtime(true);
875                         $condition = ["`pid` = 0 AND NOT `done` AND `next_try` < ?", DateTimeFormat::utcNow()];
876                         $result = DBA::select('workerqueue', ['id'], $condition, ['limit' => 1, 'order' => ['priority', 'created']]);
877                         self::$db_duration += (microtime(true) - $stamp);
878
879                         while ($id = DBA::fetch($result)) {
880                                 $ids[] = $id["id"];
881                         }
882                         DBA::close($result);
883                 }
884
885                 if (!empty($ids)) {
886                         $stamp = (float)microtime(true);
887                         $condition = ['id' => $ids, 'done' => false, 'pid' => 0];
888                         DBA::update('workerqueue', ['executed' => DateTimeFormat::utcNow(), 'pid' => $mypid], $condition);
889                         self::$db_duration += (microtime(true) - $stamp);
890                         self::$db_duration_write += (microtime(true) - $stamp);
891                 }
892
893                 return !empty($ids);
894         }
895
896         /**
897          * @brief Returns the next worker process
898          *
899          * @return string SQL statement
900          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
901          */
902         public static function workerProcess()
903         {
904                 // There can already be jobs for us in the queue.
905                 $waiting = self::getWaitingJobForPID();
906                 if (!empty($waiting)) {
907                         return $waiting;
908                 }
909
910                 $stamp = (float)microtime(true);
911                 if (!Lock::acquire('worker_process')) {
912                         return false;
913                 }
914                 self::$lock_duration += (microtime(true) - $stamp);
915
916                 $found = self::findWorkerProcesses();
917
918                 Lock::release('worker_process');
919
920                 if ($found) {
921                         $stamp = (float)microtime(true);
922                         $r = DBA::select('workerqueue', [], ['pid' => getmypid(), 'done' => false]);
923                         self::$db_duration += (microtime(true) - $stamp);
924                         return DBA::toArray($r);
925                 }
926                 return false;
927         }
928
929         /**
930          * @brief Removes a workerqueue entry from the current process
931          * @return void
932          * @throws \Exception
933          */
934         public static function unclaimProcess()
935         {
936                 $mypid = getmypid();
937
938                 $stamp = (float)microtime(true);
939                 DBA::update('workerqueue', ['executed' => DBA::NULL_DATETIME, 'pid' => 0], ['pid' => $mypid, 'done' => false]);
940                 self::$db_duration += (microtime(true) - $stamp);
941                 self::$db_duration_write += (microtime(true) - $stamp);
942         }
943
944         /**
945          * @brief Call the front end worker
946          * @return void
947          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
948          */
949         public static function callWorker()
950         {
951                 if (!Config::get("system", "frontend_worker")) {
952                         return;
953                 }
954
955                 $url = System::baseUrl()."/worker";
956                 Network::fetchUrl($url, false, $redirects, 1);
957         }
958
959         /**
960          * @brief Call the front end worker if there aren't any active
961          * @return void
962          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
963          */
964         public static function executeIfIdle()
965         {
966                 if (!Config::get("system", "frontend_worker")) {
967                         return;
968                 }
969
970                 // Do we have "proc_open"? Then we can fork the worker
971                 if (function_exists("proc_open")) {
972                         // When was the last time that we called the worker?
973                         // Less than one minute? Then we quit
974                         if ((time() - Config::get("system", "worker_started")) < 60) {
975                                 return;
976                         }
977
978                         Config::set("system", "worker_started", time());
979
980                         // Do we have enough running workers? Then we quit here.
981                         if (self::tooMuchWorkers()) {
982                                 // Cleaning dead processes
983                                 self::killStaleWorkers();
984                                 Process::deleteInactive();
985
986                                 return;
987                         }
988
989                         self::runCron();
990
991                         Logger::log('Call worker', Logger::DEBUG);
992                         self::spawnWorker();
993                         return;
994                 }
995
996                 // We cannot execute background processes.
997                 // We now run the processes from the frontend.
998                 // This won't work with long running processes.
999                 self::runCron();
1000
1001                 self::clearProcesses();
1002
1003                 $workers = self::activeWorkers();
1004
1005                 if ($workers == 0) {
1006                         self::callWorker();
1007                 }
1008         }
1009
1010         /**
1011          * @brief Removes long running worker processes
1012          * @return void
1013          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
1014          */
1015         public static function clearProcesses()
1016         {
1017                 $timeout = Config::get("system", "frontend_worker_timeout", 10);
1018
1019                 /// @todo We should clean up the corresponding workerqueue entries as well
1020                 $stamp = (float)microtime(true);
1021                 $condition = ["`created` < ? AND `command` = 'worker.php'",
1022                                 DateTimeFormat::utc("now - ".$timeout." minutes")];
1023                 DBA::delete('process', $condition);
1024                 self::$db_duration = (microtime(true) - $stamp);
1025                 self::$db_duration_write += (microtime(true) - $stamp);
1026         }
1027
1028         /**
1029          * @brief Runs the cron processes
1030          * @return void
1031          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
1032          */
1033         private static function runCron()
1034         {
1035                 Logger::log('Add cron entries', Logger::DEBUG);
1036
1037                 // Check for spooled items
1038                 self::add(['priority' => PRIORITY_HIGH, 'force_priority' => true], 'SpoolPost');
1039
1040                 // Run the cron job that calls all other jobs
1041                 self::add(['priority' => PRIORITY_MEDIUM, 'force_priority' => true], 'Cron');
1042
1043                 // Cleaning dead processes
1044                 self::killStaleWorkers();
1045         }
1046
1047         /**
1048          * @brief Spawns a new worker
1049          * @param bool $do_cron
1050          * @return void
1051          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
1052          */
1053         public static function spawnWorker($do_cron = false)
1054         {
1055                 $command = 'bin/worker.php';
1056
1057                 $args = ['no_cron' => !$do_cron];
1058
1059                 get_app()->proc_run($command, $args);
1060
1061                 // after spawning we have to remove the flag.
1062                 if (Config::get('system', 'worker_daemon_mode', false)) {
1063                         self::IPCSetJobState(false);
1064                 }
1065         }
1066
1067         /**
1068          * @brief Adds tasks to the worker queue
1069          *
1070          * @param (integer|array) priority or parameter array, strings are deprecated and are ignored
1071          *
1072          * next args are passed as $cmd command line
1073          * or: Worker::add(PRIORITY_HIGH, "Notifier", "drop", $drop_id);
1074          * or: Worker::add(array('priority' => PRIORITY_HIGH, 'dont_fork' => true), "CreateShadowEntry", $post_id);
1075          *
1076          * @return boolean "false" if proc_run couldn't be executed
1077          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
1078          * @note $cmd and string args are surrounded with ""
1079          *
1080          * @hooks 'proc_run'
1081          *    array $arr
1082          *
1083          */
1084         public static function add($cmd)
1085         {
1086                 $args = func_get_args();
1087
1088                 if (!count($args)) {
1089                         return false;
1090                 }
1091
1092                 $arr = ['args' => $args, 'run_cmd' => true];
1093
1094                 Hook::callAll("proc_run", $arr);
1095                 if (!$arr['run_cmd'] || !count($args)) {
1096                         return true;
1097                 }
1098
1099                 $priority = PRIORITY_MEDIUM;
1100                 $dont_fork = Config::get("system", "worker_dont_fork", false);
1101                 $created = DateTimeFormat::utcNow();
1102                 $force_priority = false;
1103
1104                 $run_parameter = array_shift($args);
1105
1106                 if (is_int($run_parameter)) {
1107                         $priority = $run_parameter;
1108                 } elseif (is_array($run_parameter)) {
1109                         if (isset($run_parameter['priority'])) {
1110                                 $priority = $run_parameter['priority'];
1111                         }
1112                         if (isset($run_parameter['created'])) {
1113                                 $created = $run_parameter['created'];
1114                         }
1115                         if (isset($run_parameter['dont_fork'])) {
1116                                 $dont_fork = $run_parameter['dont_fork'];
1117                         }
1118                         if (isset($run_parameter['force_priority'])) {
1119                                 $force_priority = $run_parameter['force_priority'];
1120                         }
1121                 }
1122
1123                 $parameters = json_encode($args);
1124                 $found = DBA::exists('workerqueue', ['parameter' => $parameters, 'done' => false]);
1125
1126                 // Quit if there was a database error - a precaution for the update process to 3.5.3
1127                 if (DBA::errorNo() != 0) {
1128                         return false;
1129                 }
1130
1131                 if (!$found) {
1132                         DBA::insert('workerqueue', ['parameter' => $parameters, 'created' => $created, 'priority' => $priority]);
1133                 } elseif ($force_priority) {
1134                         DBA::update('workerqueue', ['priority' => $priority], ['parameter' => $parameters, 'done' => false, 'pid' => 0]);
1135                 }
1136
1137                 // Should we quit and wait for the worker to be called as a cronjob?
1138                 if ($dont_fork) {
1139                         return true;
1140                 }
1141
1142                 // If there is a lock then we don't have to check for too much worker
1143                 if (!Lock::acquire('worker', 0)) {
1144                         return true;
1145                 }
1146
1147                 // If there are already enough workers running, don't fork another one
1148                 $quit = self::tooMuchWorkers();
1149                 Lock::release('worker');
1150
1151                 if ($quit) {
1152                         return true;
1153                 }
1154
1155                 // We tell the daemon that a new job entry exists
1156                 if (Config::get('system', 'worker_daemon_mode', false)) {
1157                         // We don't have to set the IPC flag - this is done in "tooMuchWorkers"
1158                         return true;
1159                 }
1160
1161                 // Now call the worker to execute the jobs that we just added to the queue
1162                 self::spawnWorker();
1163
1164                 return true;
1165         }
1166
1167         /**
1168          * Defers the current worker entry
1169          */
1170         public static function defer()
1171         {
1172                 if (empty(BaseObject::getApp()->queue)) {
1173                         return;
1174                 }
1175
1176                 $queue = BaseObject::getApp()->queue;
1177
1178                 $retrial = $queue['retrial'];
1179                 $id = $queue['id'];
1180                 $priority = $queue['priority'];
1181
1182                 if ($retrial > 14) {
1183                         Logger::log('Id ' . $id . ' had been tried 14 times. We stop now.', Logger::DEBUG);
1184                         return;
1185                 }
1186
1187                 // Calculate the delay until the next trial
1188                 $delay = (($retrial + 3) ** 4) + (rand(1, 30) * ($retrial + 1));
1189                 $next = DateTimeFormat::utc('now + ' . $delay . ' seconds');
1190
1191                 if (($priority < PRIORITY_MEDIUM) && ($retrial > 2)) {
1192                         $priority = PRIORITY_MEDIUM;
1193                 } elseif (($priority < PRIORITY_LOW) && ($retrial > 5)) {
1194                         $priority = PRIORITY_LOW;
1195                 } elseif (($priority < PRIORITY_NEGLIGIBLE) && ($retrial > 7)) {
1196                         $priority = PRIORITY_NEGLIGIBLE;
1197                 }
1198
1199                 Logger::log('Defer execution ' . $retrial . ' of id ' . $id . ' to ' . $next . ' - priority old/new: ' . $queue['priority'] . '/' . $priority, Logger::DEBUG);
1200
1201                 $stamp = (float)microtime(true);
1202                 $fields = ['retrial' => $retrial + 1, 'next_try' => $next, 'executed' => DBA::NULL_DATETIME, 'pid' => 0, 'priority' => $priority];
1203                 DBA::update('workerqueue', $fields, ['id' => $id]);
1204                 self::$db_duration += (microtime(true) - $stamp);
1205                 self::$db_duration_write += (microtime(true) - $stamp);
1206         }
1207
1208         /**
1209          * Log active processes into the "process" table
1210          *
1211          * @brief Log active processes into the "process" table
1212          */
1213         public static function startProcess()
1214         {
1215                 $trace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 1);
1216
1217                 $command = basename($trace[0]['file']);
1218
1219                 Process::deleteInactive();
1220
1221                 Process::insert($command);
1222         }
1223
1224         /**
1225          * Remove the active process from the "process" table
1226          *
1227          * @brief Remove the active process from the "process" table
1228          * @return bool
1229          * @throws \Exception
1230          */
1231         public static function endProcess()
1232         {
1233                 return Process::deleteByPid();
1234         }
1235
1236         /**
1237          * Set the flag if some job is waiting
1238          *
1239          * @brief Set the flag if some job is waiting
1240          * @param boolean $jobs Is there a waiting job?
1241          * @throws \Exception
1242          */
1243         public static function IPCSetJobState($jobs)
1244         {
1245                 $stamp = (float)microtime(true);
1246                 DBA::update('worker-ipc', ['jobs' => $jobs], ['key' => 1], true);
1247                 self::$db_duration += (microtime(true) - $stamp);
1248                 self::$db_duration_write += (microtime(true) - $stamp);
1249         }
1250
1251         /**
1252          * Checks if some worker job waits to be executed
1253          *
1254          * @brief Checks if some worker job waits to be executed
1255          * @return bool
1256          * @throws \Exception
1257          */
1258         public static function IPCJobsExists()
1259         {
1260                 $stamp = (float)microtime(true);
1261                 $row = DBA::selectFirst('worker-ipc', ['jobs'], ['key' => 1]);
1262                 self::$db_duration += (microtime(true) - $stamp);
1263
1264                 // When we don't have a row, no job is running
1265                 if (!DBA::isResult($row)) {
1266                         return false;
1267                 }
1268
1269                 return (bool)$row['jobs'];
1270         }
1271 }