]> git.mxchange.org Git - friendica.git/blob - src/Core/Worker.php
Formatting logger to new style
[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                 $argc = count($argv);
360
361                 $logger = $a->getLogger();
362                 $workerLogger = new WorkerLogger($logger, $funcname);
363
364                 $workerLogger ->info("Process start.", ['priority' => $queue["priority"], 'id' => $queue["id"]]);
365
366                 $stamp = (float)microtime(true);
367
368                 // We use the callstack here to analyze the performance of executed worker entries.
369                 // For this reason the variables have to be initialized.
370                 $a->getProfiler()->reset();
371
372                 $up_duration = microtime(true) - self::$up_start;
373
374                 // Reset global data to avoid interferences
375                 unset($_SESSION);
376
377                 // Set the workerLogger as new default logger
378                 Logger::init($workerLogger);
379                 if ($method_call) {
380                         call_user_func_array(sprintf('Friendica\Worker\%s::execute', $funcname), $argv);
381                 } else {
382                         $funcname($argv, $argc);
383                 }
384                 Logger::init($logger);
385
386                 unset($a->queue);
387
388                 $duration = (microtime(true) - $stamp);
389
390                 /* With these values we can analyze how effective the worker is.
391                  * The database and rest time should be low since this is the unproductive time.
392                  * The execution time is the productive time.
393                  * By changing parameters like the maximum number of workers we can check the effectivness.
394                 */
395                 $dbtotal = number_format(self::$db_duration - (self::$db_duration_count + self::$db_duration_write + self::$db_duration_stat), 4);
396                 $dbcount = number_format(self::$db_duration_count, 4);
397                 $dbstat  = number_format(self::$db_duration_stat, 4);
398                 $dbwrite = number_format(self::$db_duration_write, 4);
399                 $dblock  = number_format(self::$lock_duration, 4);
400                 $rest    = number_format(max(0, $up_duration - (self::$db_duration + self::$lock_duration)), 4);
401                 $exec    = number_format($duration, 4);
402
403                 $workerLogger->info('Performance log.', ['total' => $dbtotal, 'count' => $dbcount, 'stat' => $dbstat, 'write' => $dbwrite, 'block' => $dblock, 'rest' => $rest, 'exec' => $exec]);
404
405                 self::$up_start = microtime(true);
406                 self::$db_duration = 0;
407                 self::$db_duration_count = 0;
408                 self::$db_duration_stat = 0;
409                 self::$db_duration_write = 0;
410                 self::$lock_duration = 0;
411
412                 if ($duration > 3600) {
413                         $workerLogger->info('Longer than 1 hour.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
414                 } elseif ($duration > 600) {
415                         $workerLogger->info('Longer than 10 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
416                 } elseif ($duration > 300) {
417                         $workerLogger->info('Longer than 5 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
418                 } elseif ($duration > 120) {
419                         $workerLogger->info('Longer than 2 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
420                 }
421
422                 $workerLogger->info('Process done. ', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   number_format($duration, 4)]);
423
424                 $a->getProfiler()->saveLog($a->getLogger(), "ID " . $queue["id"] . ": " . $funcname);
425
426                 $cooldown = Config::get("system", "worker_cooldown", 0);
427
428                 if ($cooldown > 0) {
429                         $workerLogger->info('Cooldown.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'cooldown' => $cooldown]);
430                         sleep($cooldown);
431                 }
432         }
433
434         /**
435          * @brief Checks if the number of database connections has reached a critical limit.
436          *
437          * @return bool Are more than 3/4 of the maximum connections used?
438          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
439          */
440         private static function maxConnectionsReached()
441         {
442                 // Fetch the max value from the config. This is needed when the system cannot detect the correct value by itself.
443                 $max = Config::get("system", "max_connections");
444
445                 // Fetch the percentage level where the worker will get active
446                 $maxlevel = Config::get("system", "max_connections_level", 75);
447
448                 if ($max == 0) {
449                         // the maximum number of possible user connections can be a system variable
450                         $r = DBA::fetchFirst("SHOW VARIABLES WHERE `variable_name` = 'max_user_connections'");
451                         if (DBA::isResult($r)) {
452                                 $max = $r["Value"];
453                         }
454                         // Or it can be granted. This overrides the system variable
455                         $stamp = (float)microtime(true);
456                         $r = DBA::p('SHOW GRANTS');
457                         self::$db_duration += (microtime(true) - $stamp);
458                         while ($grants = DBA::fetch($r)) {
459                                 $grant = array_pop($grants);
460                                 if (stristr($grant, "GRANT USAGE ON")) {
461                                         if (preg_match("/WITH MAX_USER_CONNECTIONS (\d*)/", $grant, $match)) {
462                                                 $max = $match[1];
463                                         }
464                                 }
465                         }
466                         DBA::close($r);
467                 }
468
469                 // If $max is set we will use the processlist to determine the current number of connections
470                 // The processlist only shows entries of the current user
471                 if ($max != 0) {
472                         $stamp = (float)microtime(true);
473                         $r = DBA::p('SHOW PROCESSLIST');
474                         self::$db_duration += (microtime(true) - $stamp);
475                         $used = DBA::numRows($r);
476                         DBA::close($r);
477
478                         Logger::log("Connection usage (user values): ".$used."/".$max, Logger::DEBUG);
479
480                         $level = ($used / $max) * 100;
481
482                         if ($level >= $maxlevel) {
483                                 Logger::log("Maximum level (".$maxlevel."%) of user connections reached: ".$used."/".$max);
484                                 return true;
485                         }
486                 }
487
488                 // We will now check for the system values.
489                 // This limit could be reached although the user limits are fine.
490                 $r = DBA::fetchFirst("SHOW VARIABLES WHERE `variable_name` = 'max_connections'");
491                 if (!DBA::isResult($r)) {
492                         return false;
493                 }
494                 $max = intval($r["Value"]);
495                 if ($max == 0) {
496                         return false;
497                 }
498                 $r = DBA::fetchFirst("SHOW STATUS WHERE `variable_name` = 'Threads_connected'");
499                 if (!DBA::isResult($r)) {
500                         return false;
501                 }
502                 $used = intval($r["Value"]);
503                 if ($used == 0) {
504                         return false;
505                 }
506                 Logger::log("Connection usage (system values): ".$used."/".$max, Logger::DEBUG);
507
508                 $level = $used / $max * 100;
509
510                 if ($level < $maxlevel) {
511                         return false;
512                 }
513                 Logger::log("Maximum level (".$level."%) of system connections reached: ".$used."/".$max);
514                 return true;
515         }
516
517         /**
518          * @brief fix the queue entry if the worker process died
519          * @return void
520          * @throws \Exception
521          */
522         private static function killStaleWorkers()
523         {
524                 $stamp = (float)microtime(true);
525                 $entries = DBA::select(
526                         'workerqueue',
527                         ['id', 'pid', 'executed', 'priority', 'parameter'],
528                         ['NOT `done` AND `pid` != 0'],
529                         ['order' => ['priority', 'created']]
530                 );
531                 self::$db_duration += (microtime(true) - $stamp);
532
533                 while ($entry = DBA::fetch($entries)) {
534                         if (!posix_kill($entry["pid"], 0)) {
535                                 $stamp = (float)microtime(true);
536                                 DBA::update(
537                                         'workerqueue',
538                                         ['executed' => DBA::NULL_DATETIME, 'pid' => 0],
539                                         ['id' => $entry["id"]]
540                                 );
541                                 self::$db_duration += (microtime(true) - $stamp);
542                                 self::$db_duration_write += (microtime(true) - $stamp);
543                         } else {
544                                 // Kill long running processes
545                                 // Check if the priority is in a valid range
546                                 if (!in_array($entry["priority"], [PRIORITY_CRITICAL, PRIORITY_HIGH, PRIORITY_MEDIUM, PRIORITY_LOW, PRIORITY_NEGLIGIBLE])) {
547                                         $entry["priority"] = PRIORITY_MEDIUM;
548                                 }
549
550                                 // Define the maximum durations
551                                 $max_duration_defaults = [PRIORITY_CRITICAL => 720, PRIORITY_HIGH => 10, PRIORITY_MEDIUM => 60, PRIORITY_LOW => 180, PRIORITY_NEGLIGIBLE => 720];
552                                 $max_duration = $max_duration_defaults[$entry["priority"]];
553
554                                 $argv = json_decode($entry["parameter"], true);
555                                 $argv[0] = basename($argv[0]);
556
557                                 // How long is the process already running?
558                                 $duration = (time() - strtotime($entry["executed"])) / 60;
559                                 if ($duration > $max_duration) {
560                                         Logger::log("Worker process ".$entry["pid"]." (".substr(json_encode($argv), 0, 50).") took more than ".$max_duration." minutes. It will be killed now.");
561                                         posix_kill($entry["pid"], SIGTERM);
562
563                                         // We killed the stale process.
564                                         // To avoid a blocking situation we reschedule the process at the beginning of the queue.
565                                         // Additionally we are lowering the priority. (But not PRIORITY_CRITICAL)
566                                         $new_priority = $entry["priority"];
567                                         if ($entry["priority"] == PRIORITY_HIGH) {
568                                                 $new_priority = PRIORITY_MEDIUM;
569                                         } elseif ($entry["priority"] == PRIORITY_MEDIUM) {
570                                                 $new_priority = PRIORITY_LOW;
571                                         } elseif ($entry["priority"] != PRIORITY_CRITICAL) {
572                                                 $new_priority = PRIORITY_NEGLIGIBLE;
573                                         }
574                                         $stamp = (float)microtime(true);
575                                         DBA::update(
576                                                 'workerqueue',
577                                                 ['executed' => DBA::NULL_DATETIME, 'created' => DateTimeFormat::utcNow(), 'priority' => $new_priority, 'pid' => 0],
578                                                 ['id' => $entry["id"]]
579                                         );
580                                         self::$db_duration += (microtime(true) - $stamp);
581                                         self::$db_duration_write += (microtime(true) - $stamp);
582                                 } else {
583                                         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);
584                                 }
585                         }
586                 }
587         }
588
589         /**
590          * @brief Checks if the number of active workers exceeds the given limits
591          *
592          * @return bool Are there too much workers running?
593          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
594          */
595         private static function tooMuchWorkers()
596         {
597                 $queues = Config::get("system", "worker_queues", 4);
598
599                 $maxqueues = $queues;
600
601                 $active = self::activeWorkers();
602
603                 // Decrease the number of workers at higher load
604                 $load = System::currentLoad();
605                 if ($load) {
606                         $maxsysload = intval(Config::get("system", "maxloadavg", 50));
607
608                         /* Default exponent 3 causes queues to rapidly decrease as load increases.
609                          * If you have 20 max queues at idle, then you get only 5 queues at 37.1% of $maxsysload.
610                          * For some environments, this rapid decrease is not needed.
611                          * With exponent 1, you could have 20 max queues at idle and 13 at 37% of $maxsysload.
612                          */
613                         $exponent = intval(Config::get('system', 'worker_load_exponent', 3));
614                         $slope = pow(max(0, $maxsysload - $load) / $maxsysload, $exponent);
615                         $queues = intval(ceil($slope * $maxqueues));
616
617                         $processlist = '';
618
619                         if (Config::get('system', 'worker_jpm')) {
620                                 $intervals = explode(',', Config::get('system', 'worker_jpm_range'));
621                                 $jobs_per_minute = [];
622                                 foreach ($intervals as $interval) {
623                                         if ($interval == 0) {
624                                                 continue;
625                                         } else {
626                                                 $interval = (int)$interval;
627                                         }
628
629                                         $stamp = (float)microtime(true);
630                                         $jobs = DBA::p("SELECT COUNT(*) AS `jobs` FROM `workerqueue` WHERE `done` AND `executed` > UTC_TIMESTAMP() - INTERVAL ? MINUTE", $interval);
631                                         self::$db_duration += (microtime(true) - $stamp);
632                                         self::$db_duration_stat += (microtime(true) - $stamp);
633                                         if ($job = DBA::fetch($jobs)) {
634                                                 $jobs_per_minute[$interval] = number_format($job['jobs'] / $interval, 0);
635                                         }
636                                         DBA::close($jobs);
637                                 }
638                                 $processlist = ' - jpm: '.implode('/', $jobs_per_minute);
639                         }
640
641                         // Create a list of queue entries grouped by their priority
642                         $listitem = [0 => ''];
643
644                         $idle_workers = $active;
645
646                         $deferred = self::deferredEntries();
647
648                         if (Config::get('system', 'worker_debug')) {
649                                 $waiting_processes = 0;
650                                 // Now adding all processes with workerqueue entries
651                                 $stamp = (float)microtime(true);
652                                 $jobs = DBA::p("SELECT COUNT(*) AS `entries`, `priority` FROM `workerqueue` WHERE NOT `done` AND `next_try` < ? GROUP BY `priority`", DateTimeFormat::utcNow());
653                                 self::$db_duration += (microtime(true) - $stamp);
654                                 self::$db_duration_stat += (microtime(true) - $stamp);
655                                 while ($entry = DBA::fetch($jobs)) {
656                                         $stamp = (float)microtime(true);
657                                         $processes = DBA::p("SELECT COUNT(*) AS `running` FROM `process` INNER JOIN `workerqueue` ON `workerqueue`.`pid` = `process`.`pid` WHERE NOT `done` AND `priority` = ?", $entry["priority"]);
658                                         self::$db_duration += (microtime(true) - $stamp);
659                                         self::$db_duration_stat += (microtime(true) - $stamp);
660                                         if ($process = DBA::fetch($processes)) {
661                                                 $idle_workers -= $process["running"];
662                                                 $waiting_processes += $entry["entries"];
663                                                 $listitem[$entry["priority"]] = $entry["priority"].":".$process["running"]."/".$entry["entries"];
664                                         }
665                                         DBA::close($processes);
666                                 }
667                                 DBA::close($jobs);
668                                 $entries = $deferred + $waiting_processes;
669                         } else {
670                                 $entries = self::totalEntries();
671                                 $waiting_processes = max(0, $entries - $deferred);
672                                 $stamp = (float)microtime(true);
673                                 $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`");
674                                 self::$db_duration += (microtime(true) - $stamp);
675                                 self::$db_duration_stat += (microtime(true) - $stamp);
676
677                                 while ($entry = DBA::fetch($jobs)) {
678                                         $idle_workers -= $entry["running"];
679                                         $listitem[$entry["priority"]] = $entry["priority"].":".$entry["running"];
680                                 }
681                                 DBA::close($jobs);
682                         }
683
684                         $listitem[0] = "0:" . max(0, $idle_workers);
685
686                         $processlist .= ' ('.implode(', ', $listitem).')';
687
688                         if (Config::get("system", "worker_fastlane", false) && ($queues > 0) && self::entriesExists() && ($active >= $queues)) {
689                                 $top_priority = self::highestPriority();
690                                 $high_running = self::processWithPriorityActive($top_priority);
691
692                                 if (!$high_running && ($top_priority > PRIORITY_UNDEFINED) && ($top_priority < PRIORITY_NEGLIGIBLE)) {
693                                         Logger::log("There are jobs with priority ".$top_priority." waiting but none is executed. Open a fastlane.", Logger::DEBUG);
694                                         $queues = $active + 1;
695                                 }
696                         }
697
698                         Logger::log("Load: " . $load ."/" . $maxsysload . " - processes: " . $deferred . "/" . $active . "/" . $waiting_processes . $processlist . " - maximum: " . $queues . "/" . $maxqueues, Logger::DEBUG);
699
700                         // Are there fewer workers running as possible? Then fork a new one.
701                         if (!Config::get("system", "worker_dont_fork", false) && ($queues > ($active + 1)) && ($entries > 1)) {
702                                 Logger::log("Active workers: ".$active."/".$queues." Fork a new worker.", Logger::DEBUG);
703                                 if (Config::get('system', 'worker_daemon_mode', false)) {
704                                         self::IPCSetJobState(true);
705                                 } else {
706                                         self::spawnWorker();
707                                 }
708                         }
709                 }
710
711                 // if there are too much worker, we don't spawn a new one.
712                 if (Config::get('system', 'worker_daemon_mode', false) && ($active > $queues)) {
713                         self::IPCSetJobState(false);
714                 }
715
716                 return $active > $queues;
717         }
718
719         /**
720          * @brief Returns the number of active worker processes
721          *
722          * @return integer Number of active worker processes
723          * @throws \Exception
724          */
725         private static function activeWorkers()
726         {
727                 $stamp = (float)microtime(true);
728                 $count = DBA::count('process', ['command' => 'Worker.php']);
729                 self::$db_duration += (microtime(true) - $stamp);
730                 return $count;
731         }
732
733         /**
734          * @brief Returns waiting jobs for the current process id
735          *
736          * @return array waiting workerqueue jobs
737          * @throws \Exception
738          */
739         private static function getWaitingJobForPID()
740         {
741                 $stamp = (float)microtime(true);
742                 $r = DBA::select('workerqueue', [], ['pid' => getmypid(), 'done' => false]);
743                 self::$db_duration += (microtime(true) - $stamp);
744                 if (DBA::isResult($r)) {
745                         return DBA::toArray($r);
746                 }
747                 DBA::close($r);
748
749                 return false;
750         }
751
752         /**
753          * @brief Returns the next jobs that should be executed
754          *
755          * @return array array with next jobs
756          * @throws \Exception
757          */
758         private static function nextProcess()
759         {
760                 $priority = self::nextPriority();
761                 if (empty($priority)) {
762                         Logger::info('No tasks found');
763                         return [];
764                 }
765
766                 if ($priority <= PRIORITY_MEDIUM) {
767                         $limit = Config::get('system', 'worker_fetch_limit', 1);
768                 } else {
769                         $limit = 1;
770                 }
771
772                 $ids = [];
773                 $stamp = (float)microtime(true);
774                 $condition = ["`priority` = ? AND `pid` = 0 AND NOT `done` AND `next_try` < ?", $priority, DateTimeFormat::utcNow()];
775                 $tasks = DBA::select('workerqueue', ['id'], $condition, ['limit' => $limit, 'order' => ['created']]);
776                 self::$db_duration += (microtime(true) - $stamp);
777                 while ($task = DBA::fetch($tasks)) {
778                         $ids[] = $task['id'];
779                 }
780                 DBA::close($tasks);
781
782                 Logger::info('Found:', ['id' => $ids, 'priority' => $priority]);
783                 return $ids;
784         }
785
786         /**
787          * @brief Returns the priority of the next workerqueue job
788          *
789          * @return string priority
790          * @throws \Exception
791          */
792         private static function nextPriority()
793         {
794                 $waiting = [];
795                 $priorities = [PRIORITY_CRITICAL, PRIORITY_HIGH, PRIORITY_MEDIUM, PRIORITY_LOW, PRIORITY_NEGLIGIBLE];
796                 foreach ($priorities as $priority) {
797                         $stamp = (float)microtime(true);
798                         if (DBA::exists('workerqueue', ["`priority` = ? AND `pid` = 0 AND NOT `done` AND `next_try` < ?", $priority, DateTimeFormat::utcNow()])) {
799                                 $waiting[$priority] = true;
800                         }
801                         self::$db_duration += (microtime(true) - $stamp);
802                 }
803
804                 if (!empty($waiting[PRIORITY_CRITICAL])) {
805                         return PRIORITY_CRITICAL;
806                 }
807
808                 $running = [];
809                 $running_total = 0;
810                 $stamp = (float)microtime(true);
811                 $processes = DBA::p("SELECT COUNT(DISTINCT(`process`.`pid`)) AS `running`, `priority` FROM `process`
812                         INNER JOIN `workerqueue` ON `workerqueue`.`pid` = `process`.`pid`
813                         WHERE NOT `done` GROUP BY `priority`");
814                 self::$db_duration += (microtime(true) - $stamp);
815                 while ($process = DBA::fetch($processes)) {
816                         $running[$process['priority']] = $process['running'];
817                         $running_total += $process['running'];
818                 }
819                 DBA::close($processes);
820
821                 foreach ($priorities as $priority) {
822                         if (!empty($waiting[$priority]) && empty($running[$priority])) {
823                                 Logger::info('No running worker found with priority {priority} - assigning it.', ['priority' => $priority]);
824                                 return $priority;
825                         }
826                 }
827
828                 $active = max(self::activeWorkers(), $running_total);
829                 $priorities = max(count($waiting), count($running));
830                 $exponent = 2;
831
832                 $total = 0;
833                 for ($i = 1; $i <= $priorities; ++$i) {
834                         $total += pow($i, $exponent);
835                 }
836
837                 $limit = [];
838                 for ($i = 1; $i <= $priorities; ++$i) {
839                         $limit[$priorities - $i] = max(1, round($active * (pow($i, $exponent) / $total)));
840                 }
841
842                 $i = 0;
843                 foreach ($running as $priority => $workers) {
844                         if ($workers < $limit[$i++]) {
845                                 Logger::info('Priority {priority} has got {workers} workers out of a limit of {limit}', ['priority' => $priority, 'workers' => $workers, 'limit' => $limit[$i - 1]]);
846                                 return $priority;
847                         }
848                 }
849
850                 if (!empty($waiting)) {
851                         $priority =  array_shift(array_keys($waiting));
852                         Logger::info('No underassigned priority found, now taking the highest priority.', ['priority' => $priority]);
853                         return $priority;
854                 }
855
856                 return false;
857         }
858
859         /**
860          * @brief Find and claim the next worker process for us
861          *
862          * @return boolean Have we found something?
863          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
864          */
865         private static function findWorkerProcesses()
866         {
867                 $mypid = getmypid();
868
869                 $ids = self::nextProcess();
870
871                 // If there is no result we check without priority limit
872                 if (empty($ids)) {
873                         $stamp = (float)microtime(true);
874                         $condition = ["`pid` = 0 AND NOT `done` AND `next_try` < ?", DateTimeFormat::utcNow()];
875                         $result = DBA::select('workerqueue', ['id'], $condition, ['limit' => 1, 'order' => ['priority', 'created']]);
876                         self::$db_duration += (microtime(true) - $stamp);
877
878                         while ($id = DBA::fetch($result)) {
879                                 $ids[] = $id["id"];
880                         }
881                         DBA::close($result);
882                 }
883
884                 if (!empty($ids)) {
885                         $stamp = (float)microtime(true);
886                         $condition = ['id' => $ids, 'done' => false, 'pid' => 0];
887                         DBA::update('workerqueue', ['executed' => DateTimeFormat::utcNow(), 'pid' => $mypid], $condition);
888                         self::$db_duration += (microtime(true) - $stamp);
889                         self::$db_duration_write += (microtime(true) - $stamp);
890                 }
891
892                 return !empty($ids);
893         }
894
895         /**
896          * @brief Returns the next worker process
897          *
898          * @return string SQL statement
899          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
900          */
901         public static function workerProcess()
902         {
903                 // There can already be jobs for us in the queue.
904                 $waiting = self::getWaitingJobForPID();
905                 if (!empty($waiting)) {
906                         return $waiting;
907                 }
908
909                 $stamp = (float)microtime(true);
910                 if (!Lock::acquire('worker_process')) {
911                         return false;
912                 }
913                 self::$lock_duration += (microtime(true) - $stamp);
914
915                 $found = self::findWorkerProcesses();
916
917                 Lock::release('worker_process');
918
919                 if ($found) {
920                         $stamp = (float)microtime(true);
921                         $r = DBA::select('workerqueue', [], ['pid' => getmypid(), 'done' => false]);
922                         self::$db_duration += (microtime(true) - $stamp);
923                         return DBA::toArray($r);
924                 }
925                 return false;
926         }
927
928         /**
929          * @brief Removes a workerqueue entry from the current process
930          * @return void
931          * @throws \Exception
932          */
933         public static function unclaimProcess()
934         {
935                 $mypid = getmypid();
936
937                 $stamp = (float)microtime(true);
938                 DBA::update('workerqueue', ['executed' => DBA::NULL_DATETIME, 'pid' => 0], ['pid' => $mypid, 'done' => false]);
939                 self::$db_duration += (microtime(true) - $stamp);
940                 self::$db_duration_write += (microtime(true) - $stamp);
941         }
942
943         /**
944          * @brief Call the front end worker
945          * @return void
946          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
947          */
948         public static function callWorker()
949         {
950                 if (!Config::get("system", "frontend_worker")) {
951                         return;
952                 }
953
954                 $url = System::baseUrl()."/worker";
955                 Network::fetchUrl($url, false, $redirects, 1);
956         }
957
958         /**
959          * @brief Call the front end worker if there aren't any active
960          * @return void
961          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
962          */
963         public static function executeIfIdle()
964         {
965                 if (!Config::get("system", "frontend_worker")) {
966                         return;
967                 }
968
969                 // Do we have "proc_open"? Then we can fork the worker
970                 if (function_exists("proc_open")) {
971                         // When was the last time that we called the worker?
972                         // Less than one minute? Then we quit
973                         if ((time() - Config::get("system", "worker_started")) < 60) {
974                                 return;
975                         }
976
977                         Config::set("system", "worker_started", time());
978
979                         // Do we have enough running workers? Then we quit here.
980                         if (self::tooMuchWorkers()) {
981                                 // Cleaning dead processes
982                                 self::killStaleWorkers();
983                                 Process::deleteInactive();
984
985                                 return;
986                         }
987
988                         self::runCron();
989
990                         Logger::log('Call worker', Logger::DEBUG);
991                         self::spawnWorker();
992                         return;
993                 }
994
995                 // We cannot execute background processes.
996                 // We now run the processes from the frontend.
997                 // This won't work with long running processes.
998                 self::runCron();
999
1000                 self::clearProcesses();
1001
1002                 $workers = self::activeWorkers();
1003
1004                 if ($workers == 0) {
1005                         self::callWorker();
1006                 }
1007         }
1008
1009         /**
1010          * @brief Removes long running worker processes
1011          * @return void
1012          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
1013          */
1014         public static function clearProcesses()
1015         {
1016                 $timeout = Config::get("system", "frontend_worker_timeout", 10);
1017
1018                 /// @todo We should clean up the corresponding workerqueue entries as well
1019                 $stamp = (float)microtime(true);
1020                 $condition = ["`created` < ? AND `command` = 'worker.php'",
1021                                 DateTimeFormat::utc("now - ".$timeout." minutes")];
1022                 DBA::delete('process', $condition);
1023                 self::$db_duration = (microtime(true) - $stamp);
1024                 self::$db_duration_write += (microtime(true) - $stamp);
1025         }
1026
1027         /**
1028          * @brief Runs the cron processes
1029          * @return void
1030          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
1031          */
1032         private static function runCron()
1033         {
1034                 Logger::log('Add cron entries', Logger::DEBUG);
1035
1036                 // Check for spooled items
1037                 self::add(['priority' => PRIORITY_HIGH, 'force_priority' => true], 'SpoolPost');
1038
1039                 // Run the cron job that calls all other jobs
1040                 self::add(['priority' => PRIORITY_MEDIUM, 'force_priority' => true], 'Cron');
1041
1042                 // Cleaning dead processes
1043                 self::killStaleWorkers();
1044         }
1045
1046         /**
1047          * @brief Spawns a new worker
1048          * @param bool $do_cron
1049          * @return void
1050          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
1051          */
1052         public static function spawnWorker($do_cron = false)
1053         {
1054                 $command = 'bin/worker.php';
1055
1056                 $args = ['no_cron' => !$do_cron];
1057
1058                 get_app()->proc_run($command, $args);
1059
1060                 // after spawning we have to remove the flag.
1061                 if (Config::get('system', 'worker_daemon_mode', false)) {
1062                         self::IPCSetJobState(false);
1063                 }
1064         }
1065
1066         /**
1067          * @brief Adds tasks to the worker queue
1068          *
1069          * @param (integer|array) priority or parameter array, strings are deprecated and are ignored
1070          *
1071          * next args are passed as $cmd command line
1072          * or: Worker::add(PRIORITY_HIGH, "Notifier", "drop", $drop_id);
1073          * or: Worker::add(array('priority' => PRIORITY_HIGH, 'dont_fork' => true), "CreateShadowEntry", $post_id);
1074          *
1075          * @return boolean "false" if proc_run couldn't be executed
1076          * @throws \Friendica\Network\HTTPException\InternalServerErrorException
1077          * @note $cmd and string args are surrounded with ""
1078          *
1079          * @hooks 'proc_run'
1080          *    array $arr
1081          *
1082          */
1083         public static function add($cmd)
1084         {
1085                 $args = func_get_args();
1086
1087                 if (!count($args)) {
1088                         return false;
1089                 }
1090
1091                 $arr = ['args' => $args, 'run_cmd' => true];
1092
1093                 Hook::callAll("proc_run", $arr);
1094                 if (!$arr['run_cmd'] || !count($args)) {
1095                         return true;
1096                 }
1097
1098                 $priority = PRIORITY_MEDIUM;
1099                 $dont_fork = Config::get("system", "worker_dont_fork", false);
1100                 $created = DateTimeFormat::utcNow();
1101                 $force_priority = false;
1102
1103                 $run_parameter = array_shift($args);
1104
1105                 if (is_int($run_parameter)) {
1106                         $priority = $run_parameter;
1107                 } elseif (is_array($run_parameter)) {
1108                         if (isset($run_parameter['priority'])) {
1109                                 $priority = $run_parameter['priority'];
1110                         }
1111                         if (isset($run_parameter['created'])) {
1112                                 $created = $run_parameter['created'];
1113                         }
1114                         if (isset($run_parameter['dont_fork'])) {
1115                                 $dont_fork = $run_parameter['dont_fork'];
1116                         }
1117                         if (isset($run_parameter['force_priority'])) {
1118                                 $force_priority = $run_parameter['force_priority'];
1119                         }
1120                 }
1121
1122                 $parameters = json_encode($args);
1123                 $found = DBA::exists('workerqueue', ['parameter' => $parameters, 'done' => false]);
1124
1125                 // Quit if there was a database error - a precaution for the update process to 3.5.3
1126                 if (DBA::errorNo() != 0) {
1127                         return false;
1128                 }
1129
1130                 if (!$found) {
1131                         DBA::insert('workerqueue', ['parameter' => $parameters, 'created' => $created, 'priority' => $priority]);
1132                 } elseif ($force_priority) {
1133                         DBA::update('workerqueue', ['priority' => $priority], ['parameter' => $parameters, 'done' => false, 'pid' => 0]);
1134                 }
1135
1136                 // Should we quit and wait for the worker to be called as a cronjob?
1137                 if ($dont_fork) {
1138                         return true;
1139                 }
1140
1141                 // If there is a lock then we don't have to check for too much worker
1142                 if (!Lock::acquire('worker', 0)) {
1143                         return true;
1144                 }
1145
1146                 // If there are already enough workers running, don't fork another one
1147                 $quit = self::tooMuchWorkers();
1148                 Lock::release('worker');
1149
1150                 if ($quit) {
1151                         return true;
1152                 }
1153
1154                 // We tell the daemon that a new job entry exists
1155                 if (Config::get('system', 'worker_daemon_mode', false)) {
1156                         // We don't have to set the IPC flag - this is done in "tooMuchWorkers"
1157                         return true;
1158                 }
1159
1160                 // Now call the worker to execute the jobs that we just added to the queue
1161                 self::spawnWorker();
1162
1163                 return true;
1164         }
1165
1166         /**
1167          * Defers the current worker entry
1168          */
1169         public static function defer()
1170         {
1171                 if (empty(BaseObject::getApp()->queue)) {
1172                         return;
1173                 }
1174
1175                 $queue = BaseObject::getApp()->queue;
1176
1177                 $retrial = $queue['retrial'];
1178                 $id = $queue['id'];
1179                 $priority = $queue['priority'];
1180
1181                 if ($retrial > 14) {
1182                         Logger::log('Id ' . $id . ' had been tried 14 times. We stop now.', Logger::DEBUG);
1183                         return;
1184                 }
1185
1186                 // Calculate the delay until the next trial
1187                 $delay = (($retrial + 3) ** 4) + (rand(1, 30) * ($retrial + 1));
1188                 $next = DateTimeFormat::utc('now + ' . $delay . ' seconds');
1189
1190                 if (($priority < PRIORITY_MEDIUM) && ($retrial > 2)) {
1191                         $priority = PRIORITY_MEDIUM;
1192                 } elseif (($priority < PRIORITY_LOW) && ($retrial > 5)) {
1193                         $priority = PRIORITY_LOW;
1194                 } elseif (($priority < PRIORITY_NEGLIGIBLE) && ($retrial > 7)) {
1195                         $priority = PRIORITY_NEGLIGIBLE;
1196                 }
1197
1198                 Logger::log('Defer execution ' . $retrial . ' of id ' . $id . ' to ' . $next . ' - priority old/new: ' . $queue['priority'] . '/' . $priority, Logger::DEBUG);
1199
1200                 $stamp = (float)microtime(true);
1201                 $fields = ['retrial' => $retrial + 1, 'next_try' => $next, 'executed' => DBA::NULL_DATETIME, 'pid' => 0, 'priority' => $priority];
1202                 DBA::update('workerqueue', $fields, ['id' => $id]);
1203                 self::$db_duration += (microtime(true) - $stamp);
1204                 self::$db_duration_write += (microtime(true) - $stamp);
1205         }
1206
1207         /**
1208          * Log active processes into the "process" table
1209          *
1210          * @brief Log active processes into the "process" table
1211          */
1212         public static function startProcess()
1213         {
1214                 $trace = debug_backtrace(DEBUG_BACKTRACE_IGNORE_ARGS, 1);
1215
1216                 $command = basename($trace[0]['file']);
1217
1218                 Process::deleteInactive();
1219
1220                 Process::insert($command);
1221         }
1222
1223         /**
1224          * Remove the active process from the "process" table
1225          *
1226          * @brief Remove the active process from the "process" table
1227          * @return bool
1228          * @throws \Exception
1229          */
1230         public static function endProcess()
1231         {
1232                 return Process::deleteByPid();
1233         }
1234
1235         /**
1236          * Set the flag if some job is waiting
1237          *
1238          * @brief Set the flag if some job is waiting
1239          * @param boolean $jobs Is there a waiting job?
1240          * @throws \Exception
1241          */
1242         public static function IPCSetJobState($jobs)
1243         {
1244                 $stamp = (float)microtime(true);
1245                 DBA::update('worker-ipc', ['jobs' => $jobs], ['key' => 1], true);
1246                 self::$db_duration += (microtime(true) - $stamp);
1247                 self::$db_duration_write += (microtime(true) - $stamp);
1248         }
1249
1250         /**
1251          * Checks if some worker job waits to be executed
1252          *
1253          * @brief Checks if some worker job waits to be executed
1254          * @return bool
1255          * @throws \Exception
1256          */
1257         public static function IPCJobsExists()
1258         {
1259                 $stamp = (float)microtime(true);
1260                 $row = DBA::selectFirst('worker-ipc', ['jobs'], ['key' => 1]);
1261                 self::$db_duration += (microtime(true) - $stamp);
1262
1263                 // When we don't have a row, no job is running
1264                 if (!DBA::isResult($row)) {
1265                         return false;
1266                 }
1267
1268                 return (bool)$row['jobs'];
1269         }
1270 }