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

@@ -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<int, TimingsRecord>
+	 */
+	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 = [];
 	}
 }

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;
+	}
 }