From ab21fcdd675697d73d274eea14419641c8ae34f0 Mon Sep 17 00:00:00 2001
From: "Dylan K. Taylor" <dktapps@pmmp.io>
Date: Mon, 16 Jan 2023 19:26:32 +0000
Subject: [PATCH] Server: fixed load statistics not including Snooze processing
 time this has been a bug ever since Snooze was first introduced. The load
 statistic, similarly to timings, did not account for time spent processing
 notifications between ticks. The problem is that this is often where a
 significant amoutn of the load actually comes from, because Snooze is most
 often activated due to incoming packets.

This change fixes the problem by including the time spent processing notifications since the previous tick in the current tick's usage metric.
---
 src/Server.php                                | 12 ++++++-----
 ...ler.php => TimeTrackingSleeperHandler.php} | 21 +++++++++++++++++--
 2 files changed, 26 insertions(+), 7 deletions(-)
 rename src/{timings/TimingsAwareSleeperHandler.php => TimeTrackingSleeperHandler.php} (62%)

diff --git a/src/Server.php b/src/Server.php
index b20ec0a35..ddc1bb07d 100644
--- a/src/Server.php
+++ b/src/Server.php
@@ -90,7 +90,7 @@ use pocketmine\scheduler\AsyncPool;
 use pocketmine\snooze\SleeperHandler;
 use pocketmine\stats\SendUsageTask;
 use pocketmine\timings\Timings;
-use pocketmine\timings\TimingsAwareSleeperHandler;
+use pocketmine\TimeTrackingSleeperHandler;
 use pocketmine\timings\TimingsHandler;
 use pocketmine\updater\UpdateChecker;
 use pocketmine\utils\AssumptionFailedError;
@@ -187,7 +187,7 @@ class Server{
 
 	private static ?Server $instance = null;
 
-	private SleeperHandler $tickSleeper;
+	private TimeTrackingSleeperHandler $tickSleeper;
 
 	private BanList $banByName;
 
@@ -783,7 +783,7 @@ class Server{
 		$this->startTime = microtime(true);
 
 		Timings::init();
-		$this->tickSleeper = new TimingsAwareSleeperHandler(Timings::$serverInterrupts);
+		$this->tickSleeper = new TimeTrackingSleeperHandler(Timings::$serverInterrupts);
 
 		$this->signalHandler = new SignalHandler(function() : void{
 			$this->logger->info("Received signal interrupt, stopping the server");
@@ -1866,14 +1866,16 @@ class Server{
 		Timings::$serverTick->stopTiming();
 
 		$now = microtime(true);
-		$this->currentTPS = min(20, 1 / max(0.001, $now - $tickTime));
-		$this->currentUse = min(1, ($now - $tickTime) / 0.05);
+		$totalTickTimeSeconds = $now - $tickTime + ($this->tickSleeper->getNotificationProcessingTime() / 1_000_000_000);
+		$this->currentTPS = min(20, 1 / max(0.001, $totalTickTimeSeconds));
+		$this->currentUse = min(1, $totalTickTimeSeconds / 0.05);
 
 		TimingsHandler::tick($this->currentTPS <= $this->profilingTickRate);
 
 		$idx = $this->tickCounter % 20;
 		$this->tickAverage[$idx] = $this->currentTPS;
 		$this->useAverage[$idx] = $this->currentUse;
+		$this->tickSleeper->resetNotificationProcessingTime();
 
 		if(($this->nextTick - $tickTime) < -1){
 			$this->nextTick = $tickTime;
diff --git a/src/timings/TimingsAwareSleeperHandler.php b/src/TimeTrackingSleeperHandler.php
similarity index 62%
rename from src/timings/TimingsAwareSleeperHandler.php
rename to src/TimeTrackingSleeperHandler.php
index 80a1a0c57..970d85ce0 100644
--- a/src/timings/TimingsAwareSleeperHandler.php
+++ b/src/TimeTrackingSleeperHandler.php
@@ -21,14 +21,19 @@
 
 declare(strict_types=1);
 
-namespace pocketmine\timings;
+namespace pocketmine;
 
 use pocketmine\snooze\SleeperHandler;
+use pocketmine\timings\TimingsHandler;
+use function hrtime;
 
 /**
  * Custom Snooze sleeper handler which captures notification processing time.
+ * @internal
  */
-final class TimingsAwareSleeperHandler extends SleeperHandler{
+final class TimeTrackingSleeperHandler extends SleeperHandler{
+
+	private int $notificationProcessingTimeNs = 0;
 
 	public function __construct(
 		private TimingsHandler $timings
@@ -36,11 +41,23 @@ final class TimingsAwareSleeperHandler extends SleeperHandler{
 		parent::__construct();
 	}
 
+	/**
+	 * Returns the time in nanoseconds spent processing notifications since the last reset.
+	 */
+	public function getNotificationProcessingTime() : int{ return $this->notificationProcessingTimeNs; }
+
+	/**
+	 * Resets the notification processing time tracker to zero.
+	 */
+	public function resetNotificationProcessingTime() : void{ $this->notificationProcessingTimeNs = 0; }
+
 	public function processNotifications() : void{
+		$startTime = hrtime(true);
 		$this->timings->startTiming();
 		try{
 			parent::processNotifications();
 		}finally{
+			$this->notificationProcessingTimeNs += hrtime(true) - $startTime;
 			$this->timings->stopTiming();
 		}
 	}