From 0c47455b2456cf2216b33eb2ea7a6ebd8ecdcf8a Mon Sep 17 00:00:00 2001 From: "Dylan K. Taylor" Date: Thu, 30 Mar 2023 18:12:06 +0100 Subject: [PATCH 1/6] Timings: ensure that Average Players count is shown properly when custom player classes are used --- src/timings/Timings.php | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/src/timings/Timings.php b/src/timings/Timings.php index 668860132..e4f253874 100644 --- a/src/timings/Timings.php +++ b/src/timings/Timings.php @@ -27,6 +27,7 @@ use pocketmine\block\tile\Tile; use pocketmine\entity\Entity; use pocketmine\network\mcpe\protocol\ClientboundPacket; use pocketmine\network\mcpe\protocol\ServerboundPacket; +use pocketmine\player\Player; use pocketmine\scheduler\TaskHandler; abstract class Timings{ @@ -236,8 +237,14 @@ abstract class Timings{ } public static function getEntityTimings(Entity $entity) : TimingsHandler{ - $entityType = (new \ReflectionClass($entity))->getShortName(); + $reflect = new \ReflectionClass($entity); + $entityType = $reflect->getShortName(); if(!isset(self::$entityTypeTimingMap[$entityType])){ + //the timings viewer calculates average player count by looking at this timer, so we need to ensure it has + //a name it can identify. However, we also want to make it obvious if this is a custom Player class. + if($entity instanceof Player && $reflect->getName() !== Player::class){ + $entityType = "Player (" . $reflect->getName() . ")"; + } self::$entityTypeTimingMap[$entityType] = new TimingsHandler(self::INCLUDED_BY_OTHER_TIMINGS_PREFIX . "Entity Tick - " . $entityType, self::$tickEntity); } From 5ac0d7ae11d1302ab15757c295594f8ed17b800b Mon Sep 17 00:00:00 2001 From: "Dylan K. Taylor" Date: Fri, 31 Mar 2023 17:08:59 +0100 Subject: [PATCH 2/6] TimingsRecord: fixed incorrect violations calculation closes #5665 --- src/timings/TimingsRecord.php | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/timings/TimingsRecord.php b/src/timings/TimingsRecord.php index 8ee752ae2..532d2eaee 100644 --- a/src/timings/TimingsRecord.php +++ b/src/timings/TimingsRecord.php @@ -24,7 +24,7 @@ declare(strict_types=1); namespace pocketmine\timings; use pocketmine\Server; -use function round; +use function floor; use function spl_object_id; /** @@ -56,7 +56,7 @@ final class TimingsRecord{ if($measure){ foreach(self::$records as $record){ if($record->curTickTotal > Server::TARGET_NANOSECONDS_PER_TICK){ - $record->violations += (int) round($record->curTickTotal / Server::TARGET_NANOSECONDS_PER_TICK); + $record->violations += (int) floor($record->curTickTotal / Server::TARGET_NANOSECONDS_PER_TICK); } $record->curTickTotal = 0; $record->curCount = 0; From a862cf5144fbac028b95c7c44fa54fce1ad4f9a4 Mon Sep 17 00:00:00 2001 From: "Dylan K. Taylor" Date: Fri, 31 Mar 2023 17:27:11 +0100 Subject: [PATCH 3/6] Workaround ItemStackRequest offhand incorrect slot bug closes #5667 this appears to be a client bug specific to ItemStackRequest. --- src/network/mcpe/handler/ItemStackRequestExecutor.php | 7 ++++++- src/network/mcpe/handler/ItemStackResponseBuilder.php | 4 ++++ 2 files changed, 10 insertions(+), 1 deletion(-) diff --git a/src/network/mcpe/handler/ItemStackRequestExecutor.php b/src/network/mcpe/handler/ItemStackRequestExecutor.php index bdc2937a5..840a23cc1 100644 --- a/src/network/mcpe/handler/ItemStackRequestExecutor.php +++ b/src/network/mcpe/handler/ItemStackRequestExecutor.php @@ -113,7 +113,12 @@ class ItemStackRequestExecutor{ */ protected function getBuilderInventoryAndSlot(ItemStackRequestSlotInfo $info) : array{ $windowId = ItemStackContainerIdTranslator::translate($info->getContainerId(), $this->inventoryManager->getCurrentWindowId()); - $windowAndSlot = $this->inventoryManager->locateWindowAndSlot($windowId, $info->getSlotId()); + $slotId = $info->getSlotId(); + if($info->getContainerId() === ContainerUIIds::OFFHAND && $slotId === 1){ + //TODO: HACK! The client sends an incorrect slot ID for the offhand as of 1.19.70 + $slotId = 0; + } + $windowAndSlot = $this->inventoryManager->locateWindowAndSlot($windowId, $slotId); if($windowAndSlot === null){ throw new ItemStackRequestProcessException("No open inventory matches container UI ID: " . $info->getContainerId() . ", slot ID: " . $info->getSlotId()); } diff --git a/src/network/mcpe/handler/ItemStackResponseBuilder.php b/src/network/mcpe/handler/ItemStackResponseBuilder.php index 68a549f21..2a55c2d95 100644 --- a/src/network/mcpe/handler/ItemStackResponseBuilder.php +++ b/src/network/mcpe/handler/ItemStackResponseBuilder.php @@ -53,6 +53,10 @@ final class ItemStackResponseBuilder{ * @phpstan-return array{Inventory, int} */ private function getInventoryAndSlot(int $containerInterfaceId, int $slotId) : ?array{ + if($containerInterfaceId === ContainerUIIds::OFFHAND && $slotId === 1){ + //TODO: HACK! The client sends an incorrect slot ID for the offhand as of 1.19.70 + $slotId = 0; + } $windowId = ItemStackContainerIdTranslator::translate($containerInterfaceId, $this->inventoryManager->getCurrentWindowId()); $windowAndSlot = $this->inventoryManager->locateWindowAndSlot($windowId, $slotId); if($windowAndSlot === null){ From a2ff9649d5f9a14a2bb6e9ab7bab4ea731d225a3 Mon Sep 17 00:00:00 2001 From: "Dylan K. Taylor" Date: Fri, 31 Mar 2023 19:44:06 +0100 Subject: [PATCH 4/6] Timings: do not shorten event handler timing names this doesn't work very well in tree view timings --- src/timings/Timings.php | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/src/timings/Timings.php b/src/timings/Timings.php index c420f796f..dcabc3657 100644 --- a/src/timings/Timings.php +++ b/src/timings/Timings.php @@ -304,12 +304,7 @@ abstract class Timings{ public static function getEventTimings(Event $event) : TimingsHandler{ $eventClass = get_class($event); if(!isset(self::$events[$eventClass])){ - if(str_starts_with($eventClass, "pocketmine\\event\\")){ - $name = (new \ReflectionClass($event))->getShortName(); - }else{ - $name = $eventClass; - } - self::$events[$eventClass] = new TimingsHandler($name, group: "Events"); + self::$events[$eventClass] = new TimingsHandler($eventClass, group: "Events"); } return self::$events[$eventClass]; From 4a770e5801c86cbfeb50c34a6713b2c101bacef6 Mon Sep 17 00:00:00 2001 From: "Dylan K. Taylor" Date: Fri, 31 Mar 2023 20:32:42 +0100 Subject: [PATCH 5/6] CS --- src/timings/Timings.php | 1 - 1 file changed, 1 deletion(-) diff --git a/src/timings/Timings.php b/src/timings/Timings.php index dcabc3657..8104ed192 100644 --- a/src/timings/Timings.php +++ b/src/timings/Timings.php @@ -30,7 +30,6 @@ use pocketmine\network\mcpe\protocol\ClientboundPacket; use pocketmine\network\mcpe\protocol\ServerboundPacket; use pocketmine\scheduler\TaskHandler; use function get_class; -use function str_starts_with; abstract class Timings{ public const INCLUDED_BY_OTHER_TIMINGS_PREFIX = "** "; From 02e11b5a60f799bd9e4a793a5194c0b403814613 Mon Sep 17 00:00:00 2001 From: Dylan T Date: Fri, 31 Mar 2023 21:26:58 +0100 Subject: [PATCH 6/6] Timings tree (#5587) Split timings into tree reports this will allow the timings site to display timings as a tree, instead of as a list as is done now, which will enable more precise identification of performance issues. An example of this can be seen here: https://timings.pmmp.io/?id=302629 The format changes are fully backwards compatible, as the timings site aggregates timings from timers with the same names, and doesn't limit how much extra data can appear at the end of a line. --- src/timings/TimingsHandler.php | 52 +++++++++++++++++++++++++++------- src/timings/TimingsRecord.php | 27 +++++++++++++++++- 2 files changed, 68 insertions(+), 11 deletions(-) diff --git a/src/timings/TimingsHandler.php b/src/timings/TimingsHandler.php index 3cf65c203..231325c3e 100644 --- a/src/timings/TimingsHandler.php +++ b/src/timings/TimingsHandler.php @@ -28,6 +28,8 @@ use pocketmine\Server; use pocketmine\utils\Utils; use function count; use function hrtime; +use function implode; +use function spl_object_id; class TimingsHandler{ private static bool $enabled = false; @@ -48,7 +50,16 @@ class TimingsHandler{ $avg = $time / $count; $group = $timings->getGroup(); - $groups[$group][] = $timings->getName() . " Time: $time Count: " . $count . " Avg: $avg Violations: " . $timings->getViolations(); + $groups[$group][] = implode(" ", [ + $timings->getName(), + "Time: $time", + "Count: $count", + "Avg: $avg", + "Violations: " . $timings->getViolations(), + "RecordId: " . $timings->getId(), + "ParentRecordId: " . ($timings->getParentId() ?? "none"), + "TimerId: " . $timings->getTimerId() + ]); } $result = []; @@ -107,9 +118,15 @@ class TimingsHandler{ } } - private ?TimingsRecord $record = null; + private ?TimingsRecord $rootRecord = null; private int $timingDepth = 0; + /** + * @var TimingsRecord[] + * @phpstan-var array + */ + private array $recordsByParent = []; + public function __construct( private string $name, private ?TimingsHandler $parent = null, @@ -128,13 +145,24 @@ class TimingsHandler{ private function internalStartTiming(int $now) : void{ if(++$this->timingDepth === 1){ - if($this->record === null){ - $this->record = new TimingsRecord($this); - } - $this->record->startTiming($now); if($this->parent !== null){ $this->parent->internalStartTiming($now); } + + $current = TimingsRecord::getCurrentRecord(); + if($current !== null){ + $record = $this->recordsByParent[spl_object_id($current)] ?? null; + if($record === null){ + $record = new TimingsRecord($this, $current); + $this->recordsByParent[spl_object_id($current)] = $record; + } + }else{ + if($this->rootRecord === null){ + $this->rootRecord = new TimingsRecord($this, null); + } + $record = $this->rootRecord; + } + $record->startTiming($now); } } @@ -155,9 +183,12 @@ class TimingsHandler{ return; } - if($this->record !== null){ - //this might be null if a timings reset occurred while the timer was running - $this->record->stopTiming($now); + $record = TimingsRecord::getCurrentRecord(); + if($record !== null){ + if($record->getTimerId() !== spl_object_id($this)){ + throw new \LogicException("Timer \"" . $record->getName() . "\" should have been stopped before stopping timer \"" . $this->name . "\""); + } + $record->stopTiming($now); } if($this->parent !== null){ $this->parent->internalStopTiming($now); @@ -184,6 +215,7 @@ class TimingsHandler{ * @internal */ public function destroyCycles() : void{ - $this->record = null; + $this->rootRecord = null; + $this->recordsByParent = []; } } diff --git a/src/timings/TimingsRecord.php b/src/timings/TimingsRecord.php index 8449a7e8d..891f41b3f 100644 --- a/src/timings/TimingsRecord.php +++ b/src/timings/TimingsRecord.php @@ -24,6 +24,7 @@ declare(strict_types=1); namespace pocketmine\timings; use pocketmine\Server; +use pocketmine\utils\AssumptionFailedError; use function round; use function spl_object_id; @@ -39,11 +40,14 @@ final class TimingsRecord{ */ private static array $records = []; + private static ?self $currentRecord = null; + public static function clearRecords() : void{ foreach(self::$records as $record){ $record->handler->destroyCycles(); } self::$records = []; + self::$currentRecord = null; } /** @@ -81,11 +85,18 @@ final class TimingsRecord{ public function __construct( //I'm not the biggest fan of this cycle, but it seems to be the most effective way to avoid leaking anything. - private TimingsHandler $handler + private TimingsHandler $handler, + private ?TimingsRecord $parentRecord ){ self::$records[spl_object_id($this)] = $this; } + public function getId() : int{ return spl_object_id($this); } + + public function getParentId() : ?int{ return $this->parentRecord?->getId(); } + + public function getTimerId() : int{ return spl_object_id($this->handler); } + public function getName() : string{ return $this->handler->getName(); } public function getGroup() : string{ return $this->handler->getGroup(); } @@ -104,12 +115,22 @@ final class TimingsRecord{ public function startTiming(int $now) : void{ $this->start = $now; + self::$currentRecord = $this; } public function stopTiming(int $now) : void{ if($this->start == 0){ return; } + if(self::$currentRecord !== $this){ + if(self::$currentRecord === null){ + //timings may have been stopped while this timer was running + return; + } + + throw new AssumptionFailedError("stopTiming() called on a non-current timer"); + } + self::$currentRecord = $this->parentRecord; $diff = $now - $this->start; $this->totalTime += $diff; $this->curTickTotal += $diff; @@ -117,4 +138,8 @@ final class TimingsRecord{ ++$this->count; $this->start = 0; } + + public static function getCurrentRecord() : ?self{ + return self::$currentRecord; + } }