Enhanced logging, stopping worker after cron lifetime

[friendica.git] / src / Core / Worker.php

diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index afc8b5ab3a7a16c074a2c92b7d2db55124605a82..9691514d040836cb941dd012dbfe38c343ca09ab 100644 (file)
--- a/src/Core/Worker.php
+++ b/src/Core/Worker.php
@@ -28,6 +28,7 @@ class Worker
        private static $db_duration_stat = 0;
        private static $lock_duration = 0;
        private static $last_update;
+       private static $mode = 0;
 
        /**
         * @brief Processes the tasks that are in the workerqueue table
@@ -91,6 +92,7 @@ class Worker
                }
 
                $starttime = time();
+               self::$mode = 1;
 
                // We fetch the next queue entry that is about to be executed
                while ($r = self::workerProcess()) {
@@ -108,9 +110,18 @@ class Worker
                                if (!self::getWaitingJobForPID() && Lock::acquire('worker_process', 0)) {
                                        self::findWorkerProcesses();
                                        Lock::release('worker_process');
+                                       self::$mode = 3;
                                }
                        }
 
+                       self::$mode = 4;
+
+                       // Quit the worker once every cron interval
+                       if (time() > ($starttime + Config::get('system', 'cron_interval'))) {
+                               Logger::log('Process lifetime reached, quitting.', Logger::DEBUG);
+                               return;
+                       }
+
                        // To avoid the quitting of multiple workers only one worker at a time will execute the check
                        if (Lock::acquire('worker', 0)) {
                                // Count active workers and compare them with a maximum value that depends on the load
@@ -128,12 +139,6 @@ class Worker
                                }
                                Lock::release('worker');
                        }
-
-                       // Quit the worker once every 5 minutes
-                       if (time() > ($starttime + 300)) {
-                               Logger::log('Process lifetime reached, quitting.', Logger::DEBUG);
-                               return;
-                       }
                }
 
                // Cleaning up. Possibly not needed, but it doesn't harm anything.
@@ -411,16 +416,16 @@ class Worker
                 * The execution time is the productive time.
                 * By changing parameters like the maximum number of workers we can check the effectivness.
                */
-               Logger::log(
-                       'DB: '.number_format(self::$db_duration - (self::$db_duration_count + self::$db_duration_write + self::$db_duration_stat), 4).
-                       ' - DB-Count: '.number_format(self::$db_duration_count, 4).
-                       ' - DB-Stat: '.number_format(self::$db_duration_stat, 4).
-                       ' - DB-Write: '.number_format(self::$db_duration_write, 4).
-                       ' - Lock: '.number_format(self::$lock_duration, 4).
-                       ' - Rest: '.number_format(max(0, $up_duration - (self::$db_duration + self::$lock_duration)), 4).
-                       ' - Execution: '.number_format($duration, 4),
-                       Logger::DEBUG
-               );
+               $dbtotal = round(self::$db_duration, 2);
+               $dbread  = round(self::$db_duration - (self::$db_duration_count + self::$db_duration_write + self::$db_duration_stat), 2);
+               $dbcount = round(self::$db_duration_count, 2);
+               $dbstat  = round(self::$db_duration_stat, 2);
+               $dbwrite = round(self::$db_duration_write, 2);
+               $dblock  = round(self::$lock_duration, 2);
+               $rest    = round(max(0, $up_duration - (self::$db_duration + self::$lock_duration)), 2);
+               $exec    = round($duration, 2);
+
+               Logger::info('Performance:', ['mode' => self::$mode, 'count' => $dbcount, 'stat' => $dbstat, 'write' => $dbwrite, 'lock' => $dblock, 'total' => $dbtotal, 'rest' => $rest, 'exec' => $exec]);
 
                self::$up_start = microtime(true);
                self::$db_duration = 0;
@@ -428,6 +433,7 @@ class Worker
                self::$db_duration_stat = 0;
                self::$db_duration_write = 0;
                self::$lock_duration = 0;
+               self::$mode = 2;
 
                if ($duration > 3600) {
                        Logger::log("Prio ".$queue["priority"].": ".$queue["parameter"]." - longer than 1 hour (".round($duration/60, 3).")", Logger::DEBUG);
@@ -848,7 +854,7 @@ class Worker
        {
                $priority = self::nextPriority();
                if (empty($priority)) {
-                       Logger::log('No tasks found', Logger::DEBUG);
+                       Logger::info('No tasks found');
                        return [];
                }
 
@@ -868,7 +874,7 @@ class Worker
                }
                DBA::close($tasks);
 
-               Logger::log('Found task(s) ' . implode(', ', $ids) . ' with priority ' .$priority, Logger::DEBUG);
+               Logger::info('Found:', ['id' => $ids, 'priority' => $priority]);
                return $ids;
        }
 
@@ -909,7 +915,7 @@ class Worker
 
                foreach ($priorities as $priority) {
                        if (!empty($waiting[$priority]) && empty($running[$priority])) {
-                               Logger::log('No running worker found with priority ' . $priority . ' - assigning it.', Logger::DEBUG);
+                               Logger::info('No running worker found with priority {priority} - assigning it.', ['priority' => $priority]);
                                return $priority;
                        }
                }
@@ -931,14 +937,14 @@ class Worker
                $i = 0;
                foreach ($running as $priority => $workers) {
                        if ($workers < $limit[$i++]) {
-                               Logger::log('Priority ' . $priority . ' has got ' . $workers . ' workers out of a limit of ' . $limit[$i - 1], Logger::DEBUG);
+                               Logger::info('Priority {priority} has got {workers} workers out of a limit of {limit}', ['priority' => $priority, 'workers' => $workers, 'limit' => $limit[$i - 1]]);
                                return $priority;
                        }
                }
 
                if (!empty($waiting)) {
                        $priority =  array_shift(array_keys($waiting));
-                       Logger::log('No underassigned priority found, now taking the highest priority (' . $priority . ').', Logger::DEBUG);
+                       Logger::info('No underassigned priority found, now taking the highest priority.', ['priority' => $priority]);
                        return $priority;
                }