TimingsHandler.php

<?php
 
/*
 *
 *  ____            _        _   __  __ _                  __  __ ____
 * |  _ \ ___   ___| | _____| |_|  \/  (_)_ __   ___      |  \/  |  _ \
 * | |_) / _ \ / __| |/ / _ \ __| |\/| | | '_ \ / _ \_____| |\/| | |_) |
 * |  __/ (_) | (__|   <  __/ |_| |  | | | | | |  __/_____| |  | |  __/
 * |_|   \___/ \___|_|\_\___|\__|_|  |_|_|_| |_|\___|     |_|  |_|_|
 *
 * This program is free software: you can redistribute it and/or modify
 * it under the terms of the GNU Lesser General Public License as published by
 * the Free Software Foundation, either version 3 of the License, or
 * (at your option) any later version.
 *
 * @author PocketMine Team
 * @link http://www.pocketmine.net/
 *
 *
 */
 
declare(strict_types=1);
 
namespace pocketmine\timings;
 
use pmmp\thread\Thread as NativeThread;
use pocketmine\errorhandler\ErrorToExceptionHandler;
use pocketmine\promise\Promise;
use pocketmine\promise\PromiseResolver;
use pocketmine\Server;
use pocketmine\utils\AssumptionFailedError;
use pocketmine\utils\ObjectSet;
use pocketmine\utils\Utils;
use Symfony\Component\Filesystem\Path;
use function array_merge;
use function array_push;
use function date;
use function fclose;
use function fopen;
use function fwrite;
use function hrtime;
use function implode;
use function is_dir;
use function mkdir;
use function spl_object_id;
use const PHP_EOL;
 
class TimingsHandler{
    private const FORMAT_VERSION = 3; //thread timings collection
 
    private static bool $enabled = false;
    private static int $timingStart = 0;
 
    private static ?ObjectSet $toggleCallbacks = null;
    private static ?ObjectSet $reloadCallbacks = null;
    private static ?ObjectSet $collectCallbacks = null;
 
    private static function lazyGetSet(?ObjectSet &$where) : ObjectSet{
        //workaround for phpstan bug - allows us to ignore 1 error instead of 6 without suppressing other errors
        return $where ??= new ObjectSet();
    }
 
    public static function getToggleCallbacks() : ObjectSet{ return self::lazyGetSet(self::$toggleCallbacks); }
 
    public static function getReloadCallbacks() : ObjectSet{ return self::lazyGetSet(self::$reloadCallbacks); }
 
    public static function getCollectCallbacks() : ObjectSet{ return self::lazyGetSet(self::$collectCallbacks); }
 
    public static function printCurrentThreadRecords() : array{
        $threadId = NativeThread::getCurrentThread()?->getThreadId();
        $groups = [];
 
        foreach(TimingsRecord::getAll() as $timings){
            $time = $timings->getTotalTime();
            $count = $timings->getCount();
            if($count === 0){
                //this should never happen - a timings record shouldn't exist if it hasn't been used
                continue;
            }
 
            $avg = $time / $count;
 
            $group = $timings->getGroup() . ($threadId !== null ? " ThreadId: $threadId" : "");
            $groups[$group][] = implode(" ", [
                $timings->getName(),
                "Time: $time",
                "Count: $count",
                "Avg: $avg",
                "Violations: " . $timings->getViolations(),
                "RecordId: " . $timings->getId(),
                "ParentRecordId: " . ($timings->getParentId() ?? "none"),
                "TimerId: " . $timings->getTimerId(),
                "Ticks: " . $timings->getTicksActive(),
                "Peak: " . $timings->getPeakTime(),
            ]);
        }
        $result = [];
 
        foreach(Utils::stringifyKeys($groups) as $groupName => $lines){
            $result[] = $groupName;
            foreach($lines as $line){
                $result[] = "    $line";
            }
        }
 
        return $result;
    }
 
    private static function printFooter() : array{
        $result = [];
 
        $result[] = "# Version " . Server::getInstance()->getVersion();
        $result[] = "# " . Server::getInstance()->getName() . " " . Server::getInstance()->getPocketMineVersion();
 
        $result[] = "# FormatVersion " . self::FORMAT_VERSION;
 
        $sampleTime = hrtime(true) - self::$timingStart;
        $result[] = "Sample time $sampleTime (" . ($sampleTime / 1000000000) . "s)";
 
        return $result;
    }
 
    public static function requestPrintTimings() : Promise{
        $thisThreadRecords = self::printCurrentThreadRecords();
 
        $otherThreadRecordPromises = [];
        if(self::$collectCallbacks !== null){
            foreach(self::$collectCallbacks as $callback){
                $callbackPromises = $callback();
                array_push($otherThreadRecordPromises, ...$callbackPromises);
            }
        }
 
        $resolver = new PromiseResolver();
        Promise::all($otherThreadRecordPromises)->onCompletion(
            function(array $promisedRecords) use ($resolver, $thisThreadRecords) : void{
                $resolver->resolve([...$thisThreadRecords, ...array_merge(...$promisedRecords), ...self::printFooter()]);
            },
            function() : void{
                throw new \AssertionError("This promise is not expected to be rejected");
            }
        );
 
        return $resolver->getPromise();
    }
 
    public static function isEnabled() : bool{
        return self::$enabled;
    }
 
    public static function setEnabled(bool $enable = true) : void{
        if($enable === self::$enabled){
            return;
        }
        self::$enabled = $enable;
        self::internalReload();
        if(self::$toggleCallbacks !== null){
            foreach(self::$toggleCallbacks as $callback){
                $callback($enable);
            }
        }
    }
 
    public static function getStartTime() : float{
        return self::$timingStart;
    }
 
    private static function internalReload() : void{
        TimingsRecord::reset();
        if(self::$enabled){
            self::$timingStart = hrtime(true);
        }
    }
 
    public static function reload() : void{
        self::internalReload();
        if(self::$reloadCallbacks !== null){
            foreach(self::$reloadCallbacks as $callback){
                $callback();
            }
        }
    }
 
    public static function tick(bool $measure = true) : void{
        if(self::$enabled){
            TimingsRecord::tick($measure);
        }
    }
 
    private ?TimingsRecord $rootRecord = null;
    private int $timingDepth = 0;
 
    private array $recordsByParent = [];
 
    public function __construct(
        private string $name,
        private ?TimingsHandler $parent = null,
        private string $group = Timings::GROUP_MINECRAFT
    ){}
 
    public function getName() : string{ return $this->name; }
 
    public function getGroup() : string{ return $this->group; }
 
    public function startTiming() : void{
        if(self::$enabled){
            $this->internalStartTiming(hrtime(true));
        }
    }
 
    private function internalStartTiming(int $now) : void{
        if(++$this->timingDepth === 1){
            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);
        }
    }
 
    public function stopTiming() : void{
        if(self::$enabled){
            $this->internalStopTiming(hrtime(true));
        }
    }
 
    private function internalStopTiming(int $now) : void{
        if($this->timingDepth === 0){
            //TODO: it would be nice to bail here, but since we'd have to track timing depth across resets
            //and enable/disable, it would have a performance impact. Therefore, considering the limited
            //usefulness of bailing here anyway, we don't currently bother.
            return;
        }
        if(--$this->timingDepth !== 0){
            return;
        }
 
        $record = TimingsRecord::getCurrentRecord();
        $timerId = spl_object_id($this);
        for(; $record !== null && $record->getTimerId() !== $timerId; $record = TimingsRecord::getCurrentRecord()){
            \GlobalLogger::get()->error("Timer \"" . $record->getName() . "\" should have been stopped before stopping timer \"" . $this->name . "\"");
            $record->stopTiming($now);
        }
        $record?->stopTiming($now);
        if($this->parent !== null){
            $this->parent->internalStopTiming($now);
        }
    }
 
    public function time(\Closure $closure){
        $this->startTiming();
        try{
            return $closure();
        }finally{
            $this->stopTiming();
        }
    }
 
    public function reset() : void{
        $this->rootRecord = null;
        $this->recordsByParent = [];
        $this->timingDepth = 0;
    }
 
    public static function createReportFile(string $directory, ?string $fileName = null) : Promise{
        $timingsPromise = self::requestPrintTimings();
 
        $resolver = new PromiseResolver();
 
        $timingsPromise->onCompletion(
            function(array $lines) use ($fileName, $directory, $resolver) : void{
                if($fileName === null){
                    $date = date('Y-m-d_H.i.s_T');
                    $fileName = "timings_{$date}";
                }
                if(!@mkdir($directory, 0777, true) && !is_dir($directory)){
                    $resolver->reject();
                    return;
                }
                $timingsFile = Path::join($directory, $fileName . ".txt");
                try{
                    $handle = ErrorToExceptionHandler::trapAndRemoveFalse(fn() => fopen($timingsFile, "x+b"));
                }catch(\ErrorException){
                    //TODO: it'd be better if we could report this to the promise callback
                    $resolver->reject();
                    return;
                }
                foreach($lines as $line){
                    fwrite($handle, $line . PHP_EOL);
                }
                fclose($handle);
 
                $resolver->resolve($timingsFile);
            },
            fn() => throw new AssumptionFailedError("This promise is not expected to be rejected")
        );
 
        return $resolver->getPromise();
    }
}