Report debug stats for cost accounting every 10 seconds

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",

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",
+                "url": "https://api.github.com/repos/pmmp/BinaryUtils/zipball/8cfa34c9d5aae11886a4142c172cff05f1e87ee2",
-                "reference": "ccfc1899b859d45814ea3592e20ebec4cb731c84",
+                "reference": "8cfa34c9d5aae11886a4142c172cff05f1e87ee2",
                 "shasum": ""
             },
             "require": {
@@ -320,9 +320,9 @@
             },
             "require-dev": {
                 "phpstan/extension-installer": "^1.0",
-                "phpstan/phpstan": "~1.10.3",
+                "phpstan/phpstan": "2.1.0",
-                "phpstan/phpstan-phpunit": "^1.0",
+                "phpstan/phpstan-phpunit": "^2.0",
-                "phpstan/phpstan-strict-rules": "^1.0.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": {

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<string, int>
+	 */
+	private array $packetCostsMin = [];
+	/**
+	 * @var int[]
+	 * @phpstan-var array<string, int>
+	 */
+	private array $packetCostsMax = [];
+	/**
+	 * @var int[]
+	 * @phpstan-var array<string, int>
+	 */
+	private array $packetCostsTotal = [];
+	/**
+	 * @var int[]
+	 * @phpstan-var array<string, int>
+	 */
+	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<string, int|float|array<string, int|float>>
+	 */
+	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;
 }