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.
This commit is contained in:
Dylan K. Taylor 2023-01-16 19:26:32 +00:00
parent b03df4f1e6
commit ab21fcdd67
No known key found for this signature in database
GPG Key ID: 8927471A91CAFD3D
2 changed files with 26 additions and 7 deletions

View File

@ -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;

View File

@ -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();
}
}