Added base timings

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;

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

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

src/pocketmine/command/defaults/TimingsCommand.php

@@ -0,0 +1,141 @@
+<?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/
+ *
+ *
+*/
+
+namespace pocketmine\command\defaults;
+
+use pocketmine\command\CommandSender;
+use pocketmine\event\HandlerList;
+use pocketmine\event\TimingsHandler;
+use pocketmine\Player;
+use pocketmine\plugin\TimedRegisteredListener;
+use pocketmine\utils\TextFormat;
+use pocketmine\utils\Utils;
+
+class TimingsCommand extends VanillaCommand{
+
+	public static $timingStart = 0;
+
+	public function __construct($name){
+		parent::__construct(
+			$name,
+			"Records timings to see performance of the server.",
+			"/timings <reset|report|on|off|paste>"
+		);
+		$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;
+	}
+}

src/pocketmine/event/TimingsHandler.php

@@ -0,0 +1,151 @@
+<?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/
+ *
+ *
+*/
+
+namespace pocketmine\event;
+
+use pocketmine\command\defaults\TimingsCommand;
+use pocketmine\entity\Living;
+use pocketmine\plugin\PluginManager;
+use pocketmine\Server;
+
+class TimingsHandler{
+
+	/** @var TimingsHandler[] */
+	private static $HANDLERS = [];
+
+	private $name;
+	/** @var TimingsHandler */
+	private $parent = null;
+
+	private $count = 0;
+	private $start = 0;
+	private $timingDepth = 0;
+	private $totalTime = 0;
+	private $curTickTotal = 0;
+	private $violations = 0;
+
+	/**
+	 * @param string         $name
+	 * @param TimingsHandler $parent
+	 */
+	public function __construct($name, $parent = null){
+		$this->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)]);
+	}
+
+}

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);
 

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

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

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();
 	}
 
 	/**

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