From 40573120b929e43fde957f413efb15e952e036da Mon Sep 17 00:00:00 2001
From: Michael <heluecht@pirati.ca>
Date: Wed, 27 Feb 2019 06:36:19 +0000
Subject: [PATCH 1/9] Enhanced logging, stopping worker after cron lifetime

---
 src/Core/Worker.php | 35 +++++++++++++++++++++--------------
 1 file changed, 21 insertions(+), 14 deletions(-)

diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index 160277c74..9691514d0 100644
--- 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,15 +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.
 		*/
-		$dbtotal = number_format(self::$db_duration - (self::$db_duration_count + self::$db_duration_write + self::$db_duration_stat), 4);
-		$dbcount = number_format(self::$db_duration_count, 4);
-		$dbstat  = number_format(self::$db_duration_stat, 4);
-		$dbwrite = number_format(self::$db_duration_write, 4);
-		$dblock  = number_format(self::$lock_duration, 4);
-		$rest    = number_format(max(0, $up_duration - (self::$db_duration + self::$lock_duration)), 4);
-		$exec    = number_format($duration, 4);
+		$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:', ['total' => $dbtotal, 'count' => $dbcount, 'stat' => $dbstat, 'write' => $dbwrite, 'block' => $dblock, 'rest' => $rest, 'exec' => $exec]);
+		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;
@@ -427,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);

From 528636c9f42379fa156bb337ec05897299bf033b Mon Sep 17 00:00:00 2001
From: Michael <heluecht@pirati.ca>
Date: Wed, 27 Feb 2019 06:55:04 +0000
Subject: [PATCH 2/9] Using constants is nicer

---
 src/Core/Worker.php | 19 +++++++++++++------
 1 file changed, 13 insertions(+), 6 deletions(-)

diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index b0b9fc2cf..7e40a26c4 100644
--- a/src/Core/Worker.php
+++ b/src/Core/Worker.php
@@ -22,6 +22,11 @@ use Friendica\Util\Network;
  */
 class Worker
 {
+	const STATE_STARTUP    = 1;
+	const STATE_SHORT_LOOP = 2;
+	const STATE_REFETCH    = 3;
+	const STATE_LONG_LOOP  = 4;
+
 	private static $up_start;
 	private static $db_duration = 0;
 	private static $db_duration_count = 0;
@@ -29,7 +34,7 @@ class Worker
 	private static $db_duration_stat = 0;
 	private static $lock_duration = 0;
 	private static $last_update;
-	private static $mode = 0;
+	private static $state;
 
 	/**
 	 * @brief Processes the tasks that are in the workerqueue table
@@ -93,7 +98,7 @@ class Worker
 		}
 
 		$starttime = time();
-		self::$mode = 1;
+		self::$state = self::STATE_STARTUP;
 
 		// We fetch the next queue entry that is about to be executed
 		while ($r = self::workerProcess()) {
@@ -111,11 +116,13 @@ class Worker
 				if (!self::getWaitingJobForPID() && Lock::acquire('worker_process', 0)) {
 					self::findWorkerProcesses();
 					Lock::release('worker_process');
-					self::$mode = 3;
+					self::$state = self::STATE_REFETCH;
 				}
 			}
 
-			self::$mode = 4;
+			if (self::$state != self::STATE_REFETCH) {
+				self::$state = self::STATE_LONG_LOOP;
+			}
 
 			// Quit the worker once every cron interval
 			if (time() > ($starttime + Config::get('system', 'cron_interval'))) {
@@ -408,7 +415,7 @@ class Worker
 		$rest    = round(max(0, $up_duration - (self::$db_duration + self::$lock_duration)), 2);
 		$exec    = round($duration, 2);
 
-		$logger->info('Performance log.', ['mode' => self::$mode, 'count' => $dbcount, 'stat' => $dbstat, 'write' => $dbwrite, 'lock' => $dblock, 'total' => $dbtotal, 'rest' => $rest, 'exec' => $exec]);
+		$logger->info('Performance log.', ['state' => self::$state, 'count' => $dbcount, 'stat' => $dbstat, 'write' => $dbwrite, 'lock' => $dblock, 'total' => $dbtotal, 'rest' => $rest, 'exec' => $exec]);
 
 		self::$up_start = microtime(true);
 		self::$db_duration = 0;
@@ -416,7 +423,7 @@ class Worker
 		self::$db_duration_stat = 0;
 		self::$db_duration_write = 0;
 		self::$lock_duration = 0;
-		self::$mode = 2;
+		self::$state = self::STATE_SHORT_LOOP;
 
 		if ($duration > 3600) {
 			$logger->info('Longer than 1 hour.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);

From e1cc7262de44a1323048a7e5f03335bdf0120c5e Mon Sep 17 00:00:00 2001
From: Michael <heluecht@pirati.ca>
Date: Wed, 27 Feb 2019 07:04:21 +0000
Subject: [PATCH 3/9] Respawing when quitting

---
 src/Core/Worker.php | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index 7e40a26c4..362d41811 100644
--- a/src/Core/Worker.php
+++ b/src/Core/Worker.php
@@ -126,7 +126,8 @@ class Worker
 
 			// Quit the worker once every cron interval
 			if (time() > ($starttime + Config::get('system', 'cron_interval'))) {
-				Logger::log('Process lifetime reached, quitting.', Logger::DEBUG);
+				Logger::log('Process lifetime reached, respawning.', Logger::DEBUG);
+				self::spawnWorker();
 				return;
 			}
 

From 11e39da6ccd4ff86be95de6af9e6f84ca67996d9 Mon Sep 17 00:00:00 2001
From: Michael <heluecht@pirati.ca>
Date: Wed, 27 Feb 2019 07:08:44 +0000
Subject: [PATCH 4/9] And moving the block back to the old place

---
 src/Core/Worker.php | 14 +++++++-------
 1 file changed, 7 insertions(+), 7 deletions(-)

diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index 362d41811..1aa339170 100644
--- a/src/Core/Worker.php
+++ b/src/Core/Worker.php
@@ -124,13 +124,6 @@ class Worker
 				self::$state = self::STATE_LONG_LOOP;
 			}
 
-			// Quit the worker once every cron interval
-			if (time() > ($starttime + Config::get('system', 'cron_interval'))) {
-				Logger::log('Process lifetime reached, respawning.', Logger::DEBUG);
-				self::spawnWorker();
-				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
@@ -148,6 +141,13 @@ class Worker
 				}
 				Lock::release('worker');
 			}
+
+			// Quit the worker once every cron interval
+			if (time() > ($starttime + Config::get('system', 'cron_interval'))) {
+				Logger::log('Process lifetime reached, respawning.', Logger::DEBUG);
+				self::spawnWorker();
+				return;
+			}
 		}
 
 		// Cleaning up. Possibly not needed, but it doesn't harm anything.

From 0ee1ea5f29e92bd1a472e575163d087228f17500 Mon Sep 17 00:00:00 2001
From: Michael <heluecht@pirati.ca>
Date: Wed, 27 Feb 2019 08:41:45 +0000
Subject: [PATCH 5/9] The log text is now shorter

---
 src/Core/Worker.php | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index 1aa339170..3c1f08fda 100644
--- a/src/Core/Worker.php
+++ b/src/Core/Worker.php
@@ -416,7 +416,7 @@ class Worker
 		$rest    = round(max(0, $up_duration - (self::$db_duration + self::$lock_duration)), 2);
 		$exec    = round($duration, 2);
 
-		$logger->info('Performance log.', ['state' => self::$state, 'count' => $dbcount, 'stat' => $dbstat, 'write' => $dbwrite, 'lock' => $dblock, 'total' => $dbtotal, 'rest' => $rest, 'exec' => $exec]);
+		$logger->info('Performance:', ['state' => self::$state, 'count' => $dbcount, 'stat' => $dbstat, 'write' => $dbwrite, 'lock' => $dblock, 'total' => $dbtotal, 'rest' => $rest, 'exec' => $exec]);
 
 		self::$up_start = microtime(true);
 		self::$db_duration = 0;

From 5e440aa0350075b5ba915c81bb2818ab38fe6469 Mon Sep 17 00:00:00 2001
From: Michael <heluecht@pirati.ca>
Date: Wed, 27 Feb 2019 08:55:25 +0000
Subject: [PATCH 6/9] The cron interval is minutes - so we have to convert it
 into seconds

---
 src/Core/Worker.php | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index 3c1f08fda..984fca595 100644
--- a/src/Core/Worker.php
+++ b/src/Core/Worker.php
@@ -143,7 +143,7 @@ class Worker
 			}
 
 			// Quit the worker once every cron interval
-			if (time() > ($starttime + Config::get('system', 'cron_interval'))) {
+			if (time() > ($starttime + (Config::get('system', 'cron_interval') * 60))) {
 				Logger::log('Process lifetime reached, respawning.', Logger::DEBUG);
 				self::spawnWorker();
 				return;

From 78960d4bde695ac00ccf7f365a956c91c49ad345 Mon Sep 17 00:00:00 2001
From: Michael <heluecht@pirati.ca>
Date: Wed, 27 Feb 2019 09:11:37 +0000
Subject: [PATCH 7/9] Removed unneeded spaces

---
 src/Core/Worker.php | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index 984fca595..bee87b3ae 100644
--- a/src/Core/Worker.php
+++ b/src/Core/Worker.php
@@ -427,16 +427,16 @@ class Worker
 		self::$state = self::STATE_SHORT_LOOP;
 
 		if ($duration > 3600) {
-			$logger->info('Longer than 1 hour.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
+			$logger->info('Longer than 1 hour.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]);
 		} elseif ($duration > 600) {
-			$logger->info('Longer than 10 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
+			$logger->info('Longer than 10 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]);
 		} elseif ($duration > 300) {
-			$logger->info('Longer than 5 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
+			$logger->info('Longer than 5 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]);
 		} elseif ($duration > 120) {
-			$logger->info('Longer than 2 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   round($duration/60, 3)]);
+			$logger->info('Longer than 2 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]);
 		}
 
-		$workerLogger->info('Process done. ', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' =>   number_format($duration, 4)]);
+		$workerLogger->info('Process done.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => number_format($duration, 4)]);
 
 		$a->getProfiler()->saveLog($a->getLogger(), "ID " . $queue["id"] . ": " . $funcname);
 

From 505a34d40e24295a60499d40b890683360b160d6 Mon Sep 17 00:00:00 2001
From: Michael <heluecht@pirati.ca>
Date: Wed, 27 Feb 2019 09:12:40 +0000
Subject: [PATCH 8/9] Log the time as decimal

---
 src/Core/Worker.php | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index bee87b3ae..111cd85f5 100644
--- a/src/Core/Worker.php
+++ b/src/Core/Worker.php
@@ -436,7 +436,7 @@ class Worker
 			$logger->info('Longer than 2 minutes.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration/60, 3)]);
 		}
 
-		$workerLogger->info('Process done.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => number_format($duration, 4)]);
+		$workerLogger->info('Process done.', ['priority' => $queue["priority"], 'id' => $queue["id"], 'duration' => round($duration, 3)]);
 
 		$a->getProfiler()->saveLog($a->getLogger(), "ID " . $queue["id"] . ": " . $funcname);
 

From c3b12b63c8729a1cb844e40b490dc2d1168e9aac Mon Sep 17 00:00:00 2001
From: Michael <heluecht@pirati.ca>
Date: Wed, 27 Feb 2019 09:49:26 +0000
Subject: [PATCH 9/9] Added some description, changed logger call

---
 src/Core/Worker.php | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)

diff --git a/src/Core/Worker.php b/src/Core/Worker.php
index 111cd85f5..ea8f6d242 100644
--- a/src/Core/Worker.php
+++ b/src/Core/Worker.php
@@ -22,10 +22,10 @@ use Friendica\Util\Network;
  */
 class Worker
 {
-	const STATE_STARTUP    = 1;
-	const STATE_SHORT_LOOP = 2;
-	const STATE_REFETCH    = 3;
-	const STATE_LONG_LOOP  = 4;
+	const STATE_STARTUP    = 1; // Worker is in startup. This takes most time.
+	const STATE_SHORT_LOOP = 2; // Worker is processing preassigned jobs, thus saving much time.
+	const STATE_REFETCH    = 3; // Worker had refetched jobs in the execution loop.
+	const STATE_LONG_LOOP  = 4; // Worker is processing the whole - long - loop.
 
 	private static $up_start;
 	private static $db_duration = 0;
@@ -144,7 +144,7 @@ class Worker
 
 			// Quit the worker once every cron interval
 			if (time() > ($starttime + (Config::get('system', 'cron_interval') * 60))) {
-				Logger::log('Process lifetime reached, respawning.', Logger::DEBUG);
+				Logger::info('Process lifetime reached, respawning.');
 				self::spawnWorker();
 				return;
 			}