From 41789bc67aaf45f5295941aef952240d69af6269 Mon Sep 17 00:00:00 2001 From: "Dylan K. Taylor" Date: Tue, 11 Mar 2025 12:41:59 +0000 Subject: [PATCH] Report debug stats for cost accounting every 10 seconds --- composer.json | 2 +- composer.lock | 33 +++++++++----- src/network/mcpe/NetworkSession.php | 69 +++++++++++++++++++++++++++++ 3 files changed, 91 insertions(+), 13 deletions(-) diff --git a/composer.json b/composer.json index 10454c560..cca1fc5e6 100644 --- a/composer.json +++ b/composer.json @@ -37,7 +37,7 @@ "pocketmine/bedrock-data": "~4.0.0+bedrock-1.21.60", "pocketmine/bedrock-item-upgrade-schema": "~1.14.0+bedrock-1.21.50", "pocketmine/bedrock-protocol": "~36.0.0+bedrock-1.21.60", - "pocketmine/binaryutils": "^0.2.1", + "pocketmine/binaryutils": "dev-experimental/read-ops-accounting as 0.2.6", "pocketmine/callback-validator": "^1.0.2", "pocketmine/color": "^0.3.0", "pocketmine/errorhandler": "^0.7.0", diff --git a/composer.lock b/composer.lock index e224887d6..dcbeeb2c8 100644 --- a/composer.lock +++ b/composer.lock @@ -4,7 +4,7 @@ "Read more about it at https://getcomposer.org/doc/01-basic-usage.md#installing-dependencies", "This file is @generated automatically" ], - "content-hash": "bef9decc40d9f5bd82e1de2d151bd99f", + "content-hash": "415cb668882a32039066467bb308421f", "packages": [ { "name": "adhocore/json-comment", @@ -302,16 +302,16 @@ }, { "name": "pocketmine/binaryutils", - "version": "0.2.6", + "version": "dev-experimental/read-ops-accounting", "source": { "type": "git", "url": "https://github.com/pmmp/BinaryUtils.git", - "reference": "ccfc1899b859d45814ea3592e20ebec4cb731c84" + "reference": "8cfa34c9d5aae11886a4142c172cff05f1e87ee2" }, "dist": { "type": "zip", - "url": "https://api.github.com/repos/pmmp/BinaryUtils/zipball/ccfc1899b859d45814ea3592e20ebec4cb731c84", - "reference": "ccfc1899b859d45814ea3592e20ebec4cb731c84", + "url": "https://api.github.com/repos/pmmp/BinaryUtils/zipball/8cfa34c9d5aae11886a4142c172cff05f1e87ee2", + "reference": "8cfa34c9d5aae11886a4142c172cff05f1e87ee2", "shasum": "" }, "require": { @@ -320,9 +320,9 @@ }, "require-dev": { "phpstan/extension-installer": "^1.0", - "phpstan/phpstan": "~1.10.3", - "phpstan/phpstan-phpunit": "^1.0", - "phpstan/phpstan-strict-rules": "^1.0.0", + "phpstan/phpstan": "2.1.0", + "phpstan/phpstan-phpunit": "^2.0", + "phpstan/phpstan-strict-rules": "^2.0.0", "phpunit/phpunit": "^9.5 || ^10.0 || ^11.0" }, "type": "library", @@ -338,9 +338,9 @@ "description": "Classes and methods for conveniently handling binary data", "support": { "issues": "https://github.com/pmmp/BinaryUtils/issues", - "source": "https://github.com/pmmp/BinaryUtils/tree/0.2.6" + "source": "https://github.com/pmmp/BinaryUtils/tree/experimental/read-ops-accounting" }, - "time": "2024-03-04T15:04:17+00:00" + "time": "2025-03-11T11:50:46+00:00" }, { "name": "pocketmine/callback-validator", @@ -2930,9 +2930,18 @@ "time": "2024-03-03T12:36:25+00:00" } ], - "aliases": [], + "aliases": [ + { + "package": "pocketmine/binaryutils", + "version": "dev-experimental/read-ops-accounting", + "alias": "0.2.6", + "alias_normalized": "0.2.6.0" + } + ], "minimum-stability": "stable", - "stability-flags": [], + "stability-flags": { + "pocketmine/binaryutils": 20 + }, "prefer-stable": false, "prefer-lowest": false, "platform": { diff --git a/src/network/mcpe/NetworkSession.php b/src/network/mcpe/NetworkSession.php index 8c457ed40..c08550b85 100644 --- a/src/network/mcpe/NetworkSession.php +++ b/src/network/mcpe/NetworkSession.php @@ -113,6 +113,7 @@ use pocketmine\utils\BinaryDataException; use pocketmine\utils\BinaryStream; use pocketmine\utils\ObjectSet; use pocketmine\utils\TextFormat; +use pocketmine\utils\Utils; use pocketmine\world\format\io\GlobalItemDataHandlers; use pocketmine\world\Position; use pocketmine\world\World; @@ -122,10 +123,12 @@ use function base64_encode; use function bin2hex; use function count; use function get_class; +use function hrtime; use function implode; use function in_array; use function is_string; use function json_encode; +use function microtime; use function ord; use function random_bytes; use function str_split; @@ -135,7 +138,9 @@ use function strtolower; use function substr; use function time; use function ucfirst; +use const JSON_PRETTY_PRINT; use const JSON_THROW_ON_ERROR; +use const PHP_INT_MAX; class NetworkSession{ private const INCOMING_PACKET_BATCH_PER_TICK = 2; //usually max 1 per tick, but transactions arrive separately @@ -194,6 +199,29 @@ class NetworkSession{ */ private ObjectSet $disposeHooks; + /** + * @var int[] + * @phpstan-var array + */ + private array $packetCostsMin = []; + /** + * @var int[] + * @phpstan-var array + */ + private array $packetCostsMax = []; + /** + * @var int[] + * @phpstan-var array + */ + private array $packetCostsTotal = []; + /** + * @var int[] + * @phpstan-var array + */ + private array $packetCounts = []; + private int $decodeCostTotal = 0; + private int $sessionStartHrtime; + public function __construct( private Server $server, private NetworkSessionManager $manager, @@ -223,6 +251,8 @@ class NetworkSession{ $this->manager->add($this); $this->logger->info($this->server->getLanguage()->translate(KnownTranslationFactory::pocketmine_network_session_open())); + + $this->sessionStartHrtime = hrtime(true); } private function getLogPrefix() : string{ @@ -450,7 +480,17 @@ class NetworkSession{ try{ $stream = PacketSerializer::decoder($buffer, 0); try{ + $stream->setReadOpsLimit(PHP_INT_MAX); //just for stats collection $packet->decode($stream); + + $readOps = $stream->getReadOps(); + + $this->decodeCostTotal += $readOps; + $key = $packet->getName(); + $this->packetCostsTotal[$key] = ($this->packetCostsTotal[$key] ?? 0) + $readOps; + $this->packetCostsMin[$key] = min($this->packetCostsMin[$key] ?? PHP_INT_MAX, $readOps); + $this->packetCostsMax[$key] = max($this->packetCostsMax[$key] ?? 0, $readOps); + $this->packetCounts[$key] = ($this->packetCounts[$key] ?? 0) + 1; }catch(PacketDecodeException $e){ throw PacketHandlingException::wrap($e); } @@ -483,6 +523,27 @@ class NetworkSession{ } } + /** + * @return int[]|float[] + * @phpstan-return array> + */ + public function dumpDecodeCostStats() : array{ + $sessionTime = ((hrtime(true) - $this->sessionStartHrtime) / 1_000_000_000); + $packetDecodeAverages = []; + $packetCostsPerSecondAverages = []; + foreach(Utils::stringifyKeys($this->packetCostsTotal) as $packet => $total){ + $packetDecodeAverages[$packet] = $total / $this->packetCounts[$packet]; + $packetCostsPerSecondAverages[$packet] = $total / $sessionTime; + } + return [ + "decodeCostAvgPerSecond" => $this->decodeCostTotal / $sessionTime, + "decodeCostAvgPerPacketPerSecond" => $packetCostsPerSecondAverages, + "decodeCostAvgPerPacket" => $packetDecodeAverages, + "decodeCostMinPerPacket" => $this->packetCostsMin, + "decodeCostMaxPerPacket" => $this->packetCostsMax + ]; + } + public function handleAckReceipt(int $receiptId) : void{ if(!$this->connected){ return; @@ -1346,5 +1407,13 @@ class NetworkSession{ } $this->flushSendBuffer(); + + $now = microtime(true); + if($now - $this->lastStatsReportTime > 10){ + $this->logger->debug("Decode cost stats: " . json_encode($this->dumpDecodeCostStats(), JSON_PRETTY_PRINT | JSON_THROW_ON_ERROR)); + $this->lastStatsReportTime = $now; + } } + + private float $lastStatsReportTime = 0; }