diff --git a/src/pocketmine/Server.php b/src/pocketmine/Server.php index 6c045bde5..d3f207202 100644 --- a/src/pocketmine/Server.php +++ b/src/pocketmine/Server.php @@ -36,6 +36,7 @@ use pocketmine\event\HandlerList; use pocketmine\event\level\LevelInitEvent; use pocketmine\event\level\LevelLoadEvent; use pocketmine\event\server\ServerCommandEvent; +use pocketmine\event\TimingsHandler; use pocketmine\inventory\CraftingManager; use pocketmine\inventory\InventoryType; use pocketmine\inventory\Recipe; @@ -1354,7 +1355,7 @@ class Server{ $this->filePath = $filePath; $this->dataPath = $dataPath; $this->pluginPath = $pluginPath; - @mkdir($this->dataPath . "worlds/", 0777); + @mkdir($this->dataPath . "worlds/", 0777, true); @mkdir($this->dataPath . "players/", 0777); @mkdir($this->pluginPath, 0777); @@ -1474,8 +1475,10 @@ class Server{ Item::init(); $this->craftingManager = new CraftingManager(); + PluginManager::$pluginParentTimer = new TimingsHandler("** Plugins"); $this->pluginManager = new PluginManager($this, $this->commandMap); $this->pluginManager->subscribeToPermission(Server::BROADCAST_CHANNEL_ADMINISTRATIVE, $this->consoleSender); + $this->pluginManager->setUseTimings($this->getProperty("settings.enable-profiling", false)); $this->pluginManager->registerInterface("pocketmine\\plugin\\PharPluginLoader"); $this->pluginManager->loadPlugins($this->pluginPath); @@ -1664,6 +1667,7 @@ class Server{ $this->pluginManager->loadPlugins($this->pluginPath); $this->enablePlugins(PluginLoadOrder::STARTUP); $this->enablePlugins(PluginLoadOrder::POSTWORLD); + TimingsHandler::reload(); } /** @@ -2009,6 +2013,8 @@ class Server{ } } + TimingsHandler::tick(); + $this->tickMeasure = (($time = microtime(true)) - $this->tickTime); $this->tickTime = $time; $this->nextTick = 0.05 * (0.05 / max(0.05, $this->tickMeasure)) + $time; diff --git a/src/pocketmine/command/Command.php b/src/pocketmine/command/Command.php index d2a65b670..898820f85 100644 --- a/src/pocketmine/command/Command.php +++ b/src/pocketmine/command/Command.php @@ -24,6 +24,7 @@ */ namespace pocketmine\command; +use pocketmine\event\TimingsHandler; use pocketmine\Server; use pocketmine\utils\TextFormat; @@ -62,6 +63,9 @@ abstract class Command{ /** @var string */ private $permissionMessage = null; + /** @var TimingsHandler */ + public $timings; + /** * @param string $name * @param string $description @@ -76,6 +80,7 @@ abstract class Command{ $this->usageMessage = $usageMessage === null ? "/" . $name : $usageMessage; $this->aliases = $aliases; $this->activeAliases = (array) $aliases; + $this->timings = new TimingsHandler("** Command: ". $name); } /** @@ -156,8 +161,8 @@ abstract class Command{ public function setLabel($name){ $this->nextLabel = $name; if(!$this->isRegistered()){ + $this->timings = new TimingsHandler("** Command: ". $name); $this->label = $name; - return true; } diff --git a/src/pocketmine/command/SimpleCommandMap.php b/src/pocketmine/command/SimpleCommandMap.php index efb51a7f6..2847b52cb 100644 --- a/src/pocketmine/command/SimpleCommandMap.php +++ b/src/pocketmine/command/SimpleCommandMap.php @@ -51,6 +51,7 @@ use pocketmine\command\defaults\StopCommand; use pocketmine\command\defaults\TeleportCommand; use pocketmine\command\defaults\TellCommand; use pocketmine\command\defaults\TimeCommand; +use pocketmine\command\defaults\TimingsCommand; use pocketmine\command\defaults\VanillaCommand; use pocketmine\command\defaults\VersionCommand; use pocketmine\command\defaults\WhitelistCommand; @@ -102,6 +103,7 @@ class SimpleCommandMap implements CommandMap{ $this->register("pocketmine", new SetWorldSpawnCommand("setworldspawn")); $this->register("pocketmine", new TeleportCommand("tp")); $this->register("pocketmine", new TimeCommand("time")); + $this->register("pocketmine", new TimingsCommand("timings")); $this->register("pocketmine", new ReloadCommand("reload")); if($this->server->getProperty("debug.commands", false) === true){ @@ -175,7 +177,9 @@ class SimpleCommandMap implements CommandMap{ return false; } + $target->timings->startTiming(); $target->execute($sender, $sentCommandLabel, $args); + $target->timings->stopTiming(); return true; } diff --git a/src/pocketmine/command/defaults/TimingsCommand.php b/src/pocketmine/command/defaults/TimingsCommand.php new file mode 100644 index 000000000..59a21135a --- /dev/null +++ b/src/pocketmine/command/defaults/TimingsCommand.php @@ -0,0 +1,141 @@ +" + ); + $this->setPermission("pocketmine.command.timings"); + } + + public function execute(CommandSender $sender, $currentAlias, array $args){ + if(!$this->testPermission($sender)){ + return true; + } + + if(count($args) !== 1){ + $sender->sendMessage(TextFormat::RED . "Usage: " . $this->usageMessage); + return true; + } + + $mode = strtolower($args[0]); + + if($mode === "on"){ + $sender->getServer()->getPluginManager()->setUseTimings(true); + TimingsHandler::reload(); + $sender->sendMessage("Enabled Timings & Reset"); + return true; + }elseif($mode === "off"){ + $sender->getServer()->getPluginManager()->setUseTimings(false); + $sender->sendMessage("Disabled Timings"); + } + + if(!$sender->getServer()->getPluginManager()->useTimings()){ + $sender->sendMessage("Please enable timings by typing /timings on"); + return true; + } + + $paste = $mode === "paste"; + + if($mode === "reset"){ + TimingsHandler::reload(); + $sender->sendMessage("Timings reset"); + /*foreach(HandlerList::getHandlerLists() as $handlerList){ + foreach($handlerList->getRegisteredListeners() as $listener){ + if($listener instanceof TimedRegisteredListener){ + $listener->reset(); + } + } + }*/ + }elseif($mode === "merged" or $mode === "report" or $paste){ + + $sampleTime = microtime(true) - self::$timingStart; + $index = 0; + $timingFolder = $sender->getServer()->getDataPath() . "timings/"; + @mkdir($timingFolder, 0777); + $timings = $timingFolder . "timings.txt"; + while(file_exists($timings)){ + $timings = $timingFolder . "timings" . (++$index) . ".txt"; + } + + $fileTimings = $paste ? fopen("php://temp", "r+b") : fopen($timings, "a+b"); + + TimingsHandler::printTimings($fileTimings); + + fwrite($fileTimings, "Sample time ". round($sampleTime * 1000000000) ." (". $sampleTime ."s)" . PHP_EOL); + + if($paste){ + fseek($fileTimings, 0); + $data = [ + "public" => false, + "description" => "PocketMine-MP Timings", + "files" => [ + "timings.txt" => [ + "content" => stream_get_contents($fileTimings) + ] + ] + ]; + + $ch = curl_init("https://api.github.com/gists"); + curl_setopt($ch, CURLOPT_POST, 1); + curl_setopt($ch, CURLOPT_SSL_VERIFYPEER, false); + curl_setopt($ch, CURLOPT_SSL_VERIFYHOST, 2); + curl_setopt($ch, CURLOPT_FORBID_REUSE, 1); + curl_setopt($ch, CURLOPT_FRESH_CONNECT, 1); + curl_setopt($ch, CURLOPT_POSTFIELDS, json_encode($data, JSON_UNESCAPED_SLASHES)); + curl_setopt($ch, CURLOPT_AUTOREFERER, true); + curl_setopt($ch, CURLOPT_FOLLOWLOCATION, true); + curl_setopt($ch, CURLOPT_HTTPHEADER, ["Content-Type: application/json", "User-Agent: PocketMine-MP ".$sender->getServer()->getPocketMineVersion()]); + curl_setopt($ch, CURLOPT_RETURNTRANSFER, true); + $ret = curl_exec($ch); + $data = json_decode($ret); + curl_close($ch); + if($data === false or $data === null or !isset($data->html_url)){ + $sender->sendMessage("An error happened while pasting the report"); + return true; + } + $timings = $data->html_url; + } + + fclose($fileTimings); + $sender->sendMessage("Timings written to ". $timings); + $sender->sendMessage("Paste contents of file into form at http://aikar.co/timings.php to read results."); + } + + return true; + } +} \ No newline at end of file diff --git a/src/pocketmine/event/TimingsHandler.php b/src/pocketmine/event/TimingsHandler.php new file mode 100644 index 000000000..38a02e0e0 --- /dev/null +++ b/src/pocketmine/event/TimingsHandler.php @@ -0,0 +1,151 @@ +name = $name; + if($parent instanceof TimingsHandler){ + $this->parent = $parent; + } + + self::$HANDLERS[spl_object_hash($this)] = $this; + } + + public static function printTimings($fp){ + fwrite($fp, "Minecraft" . PHP_EOL); + + foreach(self::$HANDLERS as $timings){ + $time = $timings->totalTime; + $count = $timings->count; + if($count === 0){ + continue; + } + + $avg = $time / $count; + + fwrite($fp, " " . $timings->name ." Time: ". round($time * 1000000000) ." Count: ". $count ." Avg: ". round($avg * 1000000000) ." Violations: ". $timings->violations . PHP_EOL); + } + + fwrite($fp, "# Version " . Server::getInstance()->getVersion() . PHP_EOL); + fwrite($fp, "# PocketMine-MP " . Server::getInstance()->getPocketMineVersion() . PHP_EOL); + + $entities = 0; + $livingEntities = 0; + foreach(Server::getInstance()->getLevels() as $level){ + $entities += count($level->getEntities()); + foreach($level->getEntities() as $e){ + if($e instanceof Living){ + ++$livingEntities; + } + } + } + + fwrite($fp, "# Entities ". $entities . PHP_EOL); + fwrite($fp, "# LivingEntities ". $livingEntities . PHP_EOL); + } + + public static function reload(){ + if(Server::getInstance()->getPluginManager()->useTimings()){ + foreach(self::$HANDLERS as $timings){ + $timings->reset(); + } + TimingsCommand::$timingStart = microtime(true); + } + } + + public static function tick(){ + if(PluginManager::$useTimings){ + foreach(self::$HANDLERS as $timings){ + if($timings->curTickTotal > 0.05){ + $timings->violations += ceil($timings->curTickTotal / 0.05); + } + $timings->curTickTotal = 0; + $timings->timingDepth = 0; + } + } + } + + public function startTiming(){ + if(PluginManager::$useTimings and ++$this->timingDepth === 1){ + $this->start = microtime(true); + if($this->parent instanceof TimingsHandler and ++$this->parent->timingDepth === 1){ + $this->parent->start = $this->start; + } + } + } + + public function stopTiming(){ + if(PluginManager::$useTimings){ + if(--$this->timingDepth !== 0 or $this->start === 0){ + return; + } + + $diff = microtime(true) - $this->start; + $this->totalTime += $diff; + $this->curTickTotal += $diff; + $this->count++; + $this->start = 0; + if($this->parent instanceof TimingsHandler){ + $this->parent->stopTiming(); + } + } + } + + public function reset(){ + $this->count = 0; + $this->violations = 0; + $this->curTickTotal = 0; + $this->totalTime = 0; + $this->start = 0; + $this->timingDepth = 0; + } + + public function remove(){ + unset(self::$HANDLERS[spl_object_hash($this)]); + } + +} \ No newline at end of file diff --git a/src/pocketmine/permission/DefaultPermissions.php b/src/pocketmine/permission/DefaultPermissions.php index c9b7ad036..45fda6efe 100644 --- a/src/pocketmine/permission/DefaultPermissions.php +++ b/src/pocketmine/permission/DefaultPermissions.php @@ -107,6 +107,7 @@ abstract class DefaultPermissions{ self::registerPermission(new Permission(self::ROOT . ".command.defaultgamemode", "Allows the user to change the default gamemode", Permission::DEFAULT_OP), $commands); self::registerPermission(new Permission(self::ROOT . ".command.seed", "Allows the user to view the seed of the world", Permission::DEFAULT_OP), $commands); self::registerPermission(new Permission(self::ROOT . ".command.status", "Allows the user to view the server performance", Permission::DEFAULT_OP), $commands); + self::registerPermission(new Permission(self::ROOT . ".command.timings", "Allows the user to records timings for all plugin events", Permission::DEFAULT_OP), $commands); self::registerPermission(new Permission(self::ROOT . ".command.spawnpoint", "Allows the user to change player's spawnpoint", Permission::DEFAULT_OP), $commands); self::registerPermission(new Permission(self::ROOT . ".command.setworldspawn", "Allows the user to change the world spawn", Permission::DEFAULT_OP), $commands); diff --git a/src/pocketmine/plugin/MethodEventExecutor.php b/src/pocketmine/plugin/MethodEventExecutor.php index a735f2954..43137db8e 100644 --- a/src/pocketmine/plugin/MethodEventExecutor.php +++ b/src/pocketmine/plugin/MethodEventExecutor.php @@ -35,4 +35,8 @@ class MethodEventExecutor implements EventExecutor{ public function execute(Listener $listener, Event $event){ call_user_func(array($listener, $this->method), $event); } + + public function getMethod(){ + return $this->method; + } } \ No newline at end of file diff --git a/src/pocketmine/plugin/PluginManager.php b/src/pocketmine/plugin/PluginManager.php index 3d55c638f..91f36c073 100644 --- a/src/pocketmine/plugin/PluginManager.php +++ b/src/pocketmine/plugin/PluginManager.php @@ -21,12 +21,14 @@ namespace pocketmine\plugin; +use pocketmine\command\defaults\TimingsCommand; use pocketmine\command\PluginCommand; use pocketmine\command\SimpleCommandMap; use pocketmine\event\Event; use pocketmine\event\EventPriority; use pocketmine\event\HandlerList; use pocketmine\event\Listener; +use pocketmine\event\TimingsHandler; use pocketmine\permission\Permissible; use pocketmine\permission\Permission; use pocketmine\Server; @@ -82,6 +84,11 @@ class PluginManager{ */ protected $fileAssociations = []; + /** @var TimingsHandler */ + public static $pluginParentTimer; + + public static $useTimings = false; + /** * @param Server $server * @param SimpleCommandMap $commandMap @@ -306,8 +313,10 @@ class PluginManager{ } } + TimingsCommand::$timingStart = microtime(true); return $loadedPlugins; }else{ + TimingsCommand::$timingStart = microtime(true); return []; } } @@ -699,7 +708,9 @@ class PluginManager{ throw new \Exception("Plugin attempted to register " . $event . " while not enabled"); } - $this->getEventListeners($event)->register(new RegisteredListener($listener, $executor, $priority, $plugin, $ignoreCancelled)); + $timings = new TimingsHandler("Plugin: ".$plugin->getDescription()->getName()." Event: ".get_class($listener)."::".($executor instanceof MethodEventExecutor ? $executor->getMethod() : "???")."(".(new \ReflectionClass($event))->getShortName().")", self::$pluginParentTimer); + + $this->getEventListeners($event)->register(new RegisteredListener($listener, $executor, $priority, $plugin, $ignoreCancelled, $timings)); } /** @@ -715,4 +726,18 @@ class PluginManager{ return $event::$handlerList; } + /** + * @return bool + */ + public function useTimings(){ + return self::$useTimings; + } + + /** + * @param bool $use + */ + public function setUseTimings($use){ + self::$useTimings = (bool) $use; + } + } diff --git a/src/pocketmine/plugin/RegisteredListener.php b/src/pocketmine/plugin/RegisteredListener.php index b24e01e5e..e613ee7c7 100644 --- a/src/pocketmine/plugin/RegisteredListener.php +++ b/src/pocketmine/plugin/RegisteredListener.php @@ -24,6 +24,7 @@ namespace pocketmine\plugin; use pocketmine\event\Cancellable; use pocketmine\event\Event; use pocketmine\event\Listener; +use pocketmine\event\TimingsHandler; class RegisteredListener{ @@ -42,19 +43,26 @@ class RegisteredListener{ /** @var bool */ private $ignoreCancelled; + /** @var TimingsHandler */ + private $timings; + + + /** - * @param Listener $listener - * @param EventExecutor $executor - * @param int $priority - * @param Plugin $plugin - * @param boolean $ignoreCancelled + * @param Listener $listener + * @param EventExecutor $executor + * @param int $priority + * @param Plugin $plugin + * @param boolean $ignoreCancelled + * @param TimingsHandler $timings */ - public function __construct(Listener $listener, EventExecutor $executor, $priority, Plugin $plugin, $ignoreCancelled){ + public function __construct(Listener $listener, EventExecutor $executor, $priority, Plugin $plugin, $ignoreCancelled, TimingsHandler $timings){ $this->listener = $listener; $this->priority = $priority; $this->plugin = $plugin; $this->executor = $executor; $this->ignoreCancelled = $ignoreCancelled; + $this->timings = $timings; } /** @@ -85,7 +93,13 @@ class RegisteredListener{ if($event instanceof Cancellable and $event->isCancelled() and $this->isIgnoringCancelled()){ return; } + $this->timings->startTiming(); $this->executor->execute($this->listener, $event); + $this->timings->stopTiming(); + } + + public function __destruct(){ + $this->timings->remove(); } /** diff --git a/src/pocketmine/resources/pocketmine.yml b/src/pocketmine/resources/pocketmine.yml index a932e6269..77957cea1 100644 --- a/src/pocketmine/resources/pocketmine.yml +++ b/src/pocketmine/resources/pocketmine.yml @@ -7,6 +7,7 @@ settings: plugin-profiling: false query-plugins: true deprecated-verbose: true + enable-profiling: false advanced-cache: false upnp-forwarding: false send-usage: true