Merge pull request #1634 from PocketMine/timings

Implemented Timings

src/pocketmine/Player.php

@@ -47,6 +47,7 @@ use pocketmine\event\player\PlayerQuitEvent;
 use pocketmine\event\player\PlayerRespawnEvent;
 use pocketmine\event\server\DataPacketReceiveEvent;
 use pocketmine\event\server\DataPacketSendEvent;
+use pocketmine\event\Timings;
 use pocketmine\inventory\BaseTransaction;
 use pocketmine\inventory\BigShapelessRecipe;
 use pocketmine\inventory\CraftingTransactionGroup;
@@ -1845,7 +1846,9 @@ class Player extends Human implements CommandSender, InventoryHolder, IPlayer{
 						break;
 					}
 					if(substr($ev->getMessage(), 0, 1) === "/"){ //Command
+						Timings::$playerCommandTimer->startTiming();
 						$this->server->dispatchCommand($ev->getPlayer(), substr($ev->getMessage(), 1));
+						Timings::$playerCommandTimer->stopTiming();
 					}else{
 						$this->server->getPluginManager()->callEvent($ev = new PlayerChatEvent($this, $ev->getMessage()));
 						if(!$ev->isCancelled()){

src/pocketmine/PocketMine.php

@@ -74,7 +74,7 @@ namespace pocketmine {
 	use raklib\RakLib;
 
 	const VERSION = "Alpha_1.4dev";
-	const API_VERSION = "1.0.0";
+	const API_VERSION = "1.1.0";
 	const CODENAME = "絶好(Zekkou)ケーキ(Cake)";
 	const MINECRAFT_VERSION = "v0.9.0 alpha";
 	const PHP_VERSION = "5.5";
@@ -135,7 +135,7 @@ namespace pocketmine {
 		}
 	}
 
-	gc_enable();
+	gc_disable();
 	error_reporting(E_ALL | E_STRICT);
 	ini_set("allow_url_fopen", 1);
 	ini_set("display_errors", 1);

src/pocketmine/Server.php

@@ -36,6 +36,8 @@ use pocketmine\event\HandlerList;
 use pocketmine\event\level\LevelInitEvent;
 use pocketmine\event\level\LevelLoadEvent;
 use pocketmine\event\server\ServerCommandEvent;
+use pocketmine\event\Timings;
+use pocketmine\event\TimingsHandler;
 use pocketmine\inventory\CraftingManager;
 use pocketmine\inventory\InventoryType;
 use pocketmine\inventory\Recipe;
@@ -71,6 +73,7 @@ use pocketmine\plugin\Plugin;
 use pocketmine\plugin\PluginLoadOrder;
 use pocketmine\plugin\PluginManager;
 use pocketmine\scheduler\CallbackTask;
+use pocketmine\scheduler\PHPGarbageCollectionTask;
 use pocketmine\scheduler\SendUsageTask;
 use pocketmine\scheduler\ServerScheduler;
 use pocketmine\tile\Tile;
@@ -1354,7 +1357,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 +1477,11 @@ class Server{
 		Item::init();
 		$this->craftingManager = new CraftingManager();
 
+		PluginManager::$pluginParentTimer = new TimingsHandler("** Plugins");
+		Timings::init();
 		$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);
 
@@ -1516,9 +1522,11 @@ class Server{
 		}
 
 		if($this->getProperty("chunk-gc.period-in-ticks", 600) > 0){
-			$this->scheduler->scheduleDelayedRepeatingTask(new CallbackTask(array($this, "doLevelGC")), $this->getProperty("chunk-gc.period-in-ticks", 600), $this->getProperty("chunk-gc.period-in-ticks", 600));
+			$this->scheduler->scheduleDelayedRepeatingTask(new CallbackTask([$this, "doLevelGC"]), $this->getProperty("chunk-gc.period-in-ticks", 600), $this->getProperty("chunk-gc.period-in-ticks", 600));
 		}
 
+		$this->scheduler->scheduleRepeatingTask(new PHPGarbageCollectionTask(), 100);
+
 		$this->enablePlugins(PluginLoadOrder::POSTWORLD);
 
 	}
@@ -1596,10 +1604,15 @@ class Server{
 	}
 
 	public function checkConsole(){
+		Timings::$serverCommandTimer->startTiming();
 		if(($line = $this->console->getLine()) !== null){
 			$this->pluginManager->callEvent($ev = new ServerCommandEvent($this->consoleSender, $line));
+			if($ev->isCancelled()){
+				return;
+			}
 			$this->dispatchCommand($this->consoleSender, $ev->getCommand());
 		}
+		Timings::$serverCommandTimer->stopTiming();
 	}
 
 	/**
@@ -1620,7 +1633,6 @@ class Server{
 		}else{
 			$sender->sendMessage("Unknown command. Type \"help\" for help.");
 		}
-
 		return false;
 	}
 
@@ -1664,6 +1676,7 @@ class Server{
 		$this->pluginManager->loadPlugins($this->pluginPath);
 		$this->enablePlugins(PluginLoadOrder::STARTUP);
 		$this->enablePlugins(PluginLoadOrder::POSTWORLD);
+		TimingsHandler::reload();
 	}
 
 	/**
@@ -1743,35 +1756,10 @@ class Server{
 
 		$this->logger->info("Done (" . round(microtime(true) - \pocketmine\START_TIME, 3) . 's)! For help, type "help" or "?"');
 
-		//if(Utils::getOS() === "win"){ //Workaround less usleep() waste
-		//	$this->tickProcessorWindows();
-		//}else{
-			$this->tickProcessor();
-		//}
+		$this->tickProcessor();
 		$this->forceShutdown();
 	}
 
-	/*private function tickProcessorWindows(){
-		$lastLoop = 0;
-		while($this->isRunning){
-			foreach($this->interfaces as $interface){
-				if($interface->process()){
-					$lastLoop = 0;
-				}
-			}
-			$this->generationManager->handlePackets();
-
-			if(($ticks = $this->tick()) !== true){
-				++$lastLoop;
-				if($lastLoop > 8){
-					usleep(1000);
-				}
-			}else{
-				$lastLoop = 0;
-			}
-		}
-	}*/
-
 	public function checkTicks(){
 		if($this->getTicksPerSecond() < 12){
 			$this->logger->warning("Can't keep up! Is the server overloaded?");
@@ -1875,13 +1863,17 @@ class Server{
 
 	private function tickProcessor(){
 		$lastLoop = 0;
+		$connectionTimer = Timings::$connectionTimer;
 		while($this->isRunning){
 
+			$connectionTimer->startTiming();
 			foreach($this->interfaces as $interface){
 				if($interface->process()){
 					$lastLoop = 0;
 				}
 			}
+			$connectionTimer->stopTiming();
+
 			$this->generationManager->handlePackets();
 
 			++$lastLoop;
@@ -1903,22 +1895,29 @@ class Server{
 	}
 
 	private function checkTickUpdates($currentTick){
+
+		//TODO: move this to each Level
+
 		//Update entities that need update
 		if(count(Entity::$needUpdate) > 0){
+			Timings::$tickEntityTimer->startTiming();
 			foreach(Entity::$needUpdate as $id => $entity){
 				if($entity->onUpdate() === false){
 					unset(Entity::$needUpdate[$id]);
 				}
 			}
+			Timings::$tickEntityTimer->stopTiming();
 		}
 
 		//Update tiles that need update
 		if(count(Tile::$needUpdate) > 0){
+			Timings::$tickTileEntityTimer->startTiming();
 			foreach(Tile::$needUpdate as $id => $tile){
 				if($tile->onUpdate() === false){
 					unset(Tile::$needUpdate[$id]);
 				}
 			}
+			Timings::$tickTileEntityTimer->stopTiming();
 		}
 
 		//TODO: Add level blocks
@@ -1931,13 +1930,15 @@ class Server{
 
 	public function doAutoSave(){
 
-		/*foreach($this->getOnlinePlayers() as $player){
+		Timings::$worldSaveTimer->startTiming();
+		foreach($this->getOnlinePlayers() as $player){
 			$player->save();
-		}*/
+		}
 
 		foreach($this->getLevels() as $level){
-			$level->save();
+			$level->save(false);
 		}
+		Timings::$worldSaveTimer->stopTiming();
 	}
 
 	public function doLevelGC(){
@@ -1995,11 +1996,15 @@ class Server{
 				return false;
 			}
 
+			Timings::$serverTickTimer->startTiming();
+
 			$this->inTick = true; //Fix race conditions
 			++$this->tickCounter;
 
 			$this->checkConsole();
+			Timings::$schedulerTimer->startTiming();
 			$this->scheduler->mainThreadHeartbeat($this->tickCounter);
+			Timings::$schedulerTimer->stopTiming();
 			$this->checkTickUpdates($this->tickCounter);
 
 			if(($this->tickCounter & 0b1111) === 0){
@@ -2009,11 +2014,15 @@ 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;
 			$this->inTick = false;
 
+			Timings::$serverTickTimer->stopTiming();
+
 			return true;
 		}
 

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/entity/Entity.php

@@ -33,6 +33,7 @@ use pocketmine\event\entity\EntityMotionEvent;
 use pocketmine\event\entity\EntityMoveEvent;
 use pocketmine\event\entity\EntitySpawnEvent;
 use pocketmine\event\entity\EntityTeleportEvent;
+use pocketmine\event\Timings;
 use pocketmine\level\format\Chunk;
 use pocketmine\level\Level;
 use pocketmine\level\Position;
@@ -669,6 +670,8 @@ abstract class Entity extends Position implements Metadatable{
 			return;
 		}
 
+		Timings::$entityMoveTimer->startTiming();
+
 		$ox = $this->x;
 		$oy = $this->y;
 		$oz = $this->z;
@@ -832,6 +835,7 @@ abstract class Entity extends Position implements Metadatable{
 
 		//TODO: vehicle collision events (first we need to spawn them!)
 
+		Timings::$entityMoveTimer->stopTiming();
 
 	}
 

src/pocketmine/entity/Living.php

@@ -26,6 +26,7 @@ use pocketmine\event\entity\EntityDamageByEntityEvent;
 use pocketmine\event\entity\EntityDamageEvent;
 use pocketmine\event\entity\EntityDeathEvent;
 use pocketmine\event\entity\EntityRegainHealthEvent;
+use pocketmine\event\Timings;
 use pocketmine\math\Vector3;
 use pocketmine\nbt\tag\Short;
 use pocketmine\network\protocol\EntityEventPacket;
@@ -114,6 +115,12 @@ abstract class Living extends Entity implements Damageable{
 		}
 	}
 
+	public function entityBaseTick(){
+		Timings::$timerEntityBaseTick->startTiming();
+		parent::entityBaseTick();
+		Timings::$timerEntityBaseTick->stopTiming();
+	}
+
 	/**
 	 * @return Item[]
 	 */

src/pocketmine/event/LevelTimings.php

@@ -0,0 +1,103 @@
+<?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\level\Level;
+
+class LevelTimings{
+
+	/** @var TimingsHandler */
+	public $mobSpawn;
+	/** @var TimingsHandler */
+	public $doChunkUnload;
+	/** @var TimingsHandler */
+	public $doPortalForcer;
+	/** @var TimingsHandler */
+	public $doTickPending;
+	/** @var TimingsHandler */
+	public $doTickTiles;
+	/** @var TimingsHandler */
+	public $doVillages;
+	/** @var TimingsHandler */
+	public $doChunkMap;
+	/** @var TimingsHandler */
+	public $doChunkGC;
+	/** @var TimingsHandler */
+	public $doSounds;
+	/** @var TimingsHandler */
+	public $entityTick;
+	/** @var TimingsHandler */
+	public $tileEntityTick;
+	/** @var TimingsHandler */
+	public $tileEntityPending;
+	/** @var TimingsHandler */
+	public $tracker;
+	/** @var TimingsHandler */
+	public $doTick;
+	/** @var TimingsHandler */
+	public $tickEntities;
+
+	/** @var TimingsHandler */
+	public $syncChunkLoadTimer;
+	/** @var TimingsHandler */
+	public $syncChunkLoadDataTimer;
+	/** @var TimingsHandler */
+	public $syncChunkLoadStructuresTimer;
+	/** @var TimingsHandler */
+	public $syncChunkLoadEntitiesTimer;
+	/** @var TimingsHandler */
+	public $syncChunkLoadTileEntitiesTimer;
+	/** @var TimingsHandler */
+	public $syncChunkLoadTileTicksTimer;
+	/** @var TimingsHandler */
+	public $syncChunkLoadPostTimer;
+
+	public function __construct(Level $level){
+		$name = $level->getFolderName() . " - ";
+
+		$this->mobSpawn = new TimingsHandler("** ". $name ."mobSpawn");
+		$this->doChunkUnload = new TimingsHandler("** ". $name ."doChunkUnload");
+		$this->doTickPending = new TimingsHandler("** ". $name ."doTickPending");
+		$this->doTickTiles = new TimingsHandler("** ". $name ."doTickTiles");
+		$this->doVillages = new TimingsHandler("** ". $name ."doVillages");
+		$this->doChunkMap = new TimingsHandler("** ". $name ."doChunkMap");
+		$this->doSounds = new TimingsHandler("** ". $name ."doSounds");
+		$this->doChunkGC = new TimingsHandler("** ". $name ."doChunkGC");
+		$this->doPortalForcer = new TimingsHandler("** ". $name ."doPortalForcer");
+		$this->entityTick = new TimingsHandler("** ". $name ."entityTick");
+		$this->tileEntityTick = new TimingsHandler("** ". $name ."tileEntityTick");
+		$this->tileEntityPending = new TimingsHandler("** ". $name ."tileEntityPending");
+
+		$this->syncChunkLoadTimer = new TimingsHandler("** ". $name ."syncChunkLoad");
+		$this->syncChunkLoadDataTimer = new TimingsHandler("** ". $name ."syncChunkLoad - Data");
+		$this->syncChunkLoadStructuresTimer = new TimingsHandler("** ". $name ."syncChunkLoad - Structures");
+		$this->syncChunkLoadEntitiesTimer = new TimingsHandler("** ". $name ."syncChunkLoad - Entities");
+		$this->syncChunkLoadTileEntitiesTimer = new TimingsHandler("** ". $name ."syncChunkLoad - TileEntities");
+		$this->syncChunkLoadTileTicksTimer = new TimingsHandler("** ". $name ."syncChunkLoad - TileTicks");
+		$this->syncChunkLoadPostTimer = new TimingsHandler("** ". $name ."syncChunkLoad - Post");
+
+		$this->tracker = new TimingsHandler($name ."tracker");
+		$this->doTick = new TimingsHandler($name ."doTick");
+		$this->tickEntities = new TimingsHandler($name ."tickEntities");
+	}
+
+}

src/pocketmine/event/Timings.php

@@ -0,0 +1,182 @@
+<?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\entity\Entity;
+use pocketmine\plugin\PluginManager;
+use pocketmine\scheduler\PluginTask;
+use pocketmine\scheduler\TaskHandler;
+use pocketmine\tile\Tile;
+
+abstract class Timings{
+
+	/** @var TimingsHandler */
+	public static $serverTickTimer;
+	/** @var TimingsHandler */
+	public static $playerListTimer;
+	/** @var TimingsHandler */
+	public static $connectionTimer;
+	/** @var TimingsHandler */
+	public static $tickablesTimer;
+	/** @var TimingsHandler */
+	public static $schedulerTimer;
+	/** @var TimingsHandler */
+	public static $chunkIOTickTimer;
+	/** @var TimingsHandler */
+	public static $timeUpdateTimer;
+	/** @var TimingsHandler */
+	public static $serverCommandTimer;
+	/** @var TimingsHandler */
+	public static $worldSaveTimer;
+
+	/** @var TimingsHandler */
+	public static $entityMoveTimer;
+	/** @var TimingsHandler */
+	public static $tickEntityTimer;
+	/** @var TimingsHandler */
+	public static $activatedEntityTimer;
+	/** @var TimingsHandler */
+	public static $tickTileEntityTimer;
+
+	/** @var TimingsHandler */
+	public static $timerEntityBaseTick;
+	/** @var TimingsHandler */
+	public static $timerEntityAI;
+	/** @var TimingsHandler */
+	public static $timerEntityAICollision;
+	/** @var TimingsHandler */
+	public static $timerEntityAIMove;
+	/** @var TimingsHandler */
+	public static $timerEntityTickRest;
+
+	/** @var TimingsHandler */
+	public static $processQueueTimer;
+	/** @var TimingsHandler */
+	public static $schedulerSyncTimer;
+
+	/** @var TimingsHandler */
+	public static $playerCommandTimer;
+
+	/** @var TimingsHandler[] */
+	public static $entityTypeTimingMap = [];
+	/** @var TimingsHandler[] */
+	public static $tileEntityTypeTimingMap = [];
+	/** @var TimingsHandler[] */
+	public static $pluginTaskTimingMap = [];
+
+	public static function init(){
+		if(self::$serverTickTimer instanceof TimingsHandler){
+			return;
+		}
+
+		self::$serverTickTimer = new TimingsHandler("** Full Server Tick");
+		self::$playerListTimer = new TimingsHandler("Player List");
+		self::$connectionTimer = new TimingsHandler("Connection Handler");
+		self::$tickablesTimer = new TimingsHandler("Tickables");
+		self::$schedulerTimer = new TimingsHandler("Scheduler");
+		self::$chunkIOTickTimer = new TimingsHandler("ChunkIOTick");
+		self::$timeUpdateTimer = new TimingsHandler("Time Update");
+		self::$serverCommandTimer = new TimingsHandler("Server Command");
+		self::$worldSaveTimer = new TimingsHandler("World Save");
+
+		self::$entityMoveTimer = new TimingsHandler("** entityMove");
+		self::$tickEntityTimer = new TimingsHandler("** tickEntity");
+		self::$activatedEntityTimer = new TimingsHandler("** activatedTickEntity");
+		self::$tickTileEntityTimer = new TimingsHandler("** tickTileEntity");
+
+		self::$timerEntityBaseTick = new TimingsHandler("** livingEntityBaseTick");
+		self::$timerEntityAI = new TimingsHandler("** livingEntityAI");
+		self::$timerEntityAICollision = new TimingsHandler("** livingEntityAICollision");
+		self::$timerEntityAIMove = new TimingsHandler("** livingEntityAIMove");
+		self::$timerEntityTickRest = new TimingsHandler("** livingEntityTickRest");
+
+		self::$processQueueTimer = new TimingsHandler("processQueue");
+		self::$schedulerSyncTimer = new TimingsHandler("** Scheduler - Sync Tasks", PluginManager::$pluginParentTimer);
+
+		self::$playerCommandTimer = new TimingsHandler("** playerCommand");
+
+	}
+
+	/**
+	 * @param TaskHandler $task
+	 * @param             $period
+	 *
+	 * @return TimingsHandler
+	 */
+	public static function getPluginTaskTimings(TaskHandler $task, $period){
+		$ftask = $task->getTask();
+		if($ftask instanceof PluginTask and $ftask->getOwner() !== null){
+			$plugin = $ftask->getOwner()->getDescription()->getName();
+		}elseif($task->timingName !== null){
+			$plugin = "Scheduler";
+		}else{
+			$plugin = "Unknown";
+		}
+
+		$taskname = $task->getTaskName();
+
+		$name = "Task: ". $plugin." Runnable: ". $taskname;
+
+		if($period > 0){
+			$name .= "(interval:".$period.")";
+		}else{
+			$name .= "(Single)";
+		}
+
+		if(!isset(self::$pluginTaskTimingMap[$name])){
+			self::$pluginTaskTimingMap[$name] = new TimingsHandler($name, self::$schedulerSyncTimer);
+		}
+
+		return self::$pluginTaskTimingMap[$name];
+	}
+
+	/**
+	 * @param Entity $entity
+	 *
+	 * @return TimingsHandler
+	 */
+	public static function getEntityTimings(Entity $entity){
+		$entityType = (new \ReflectionClass($entity))->getShortName();
+		if(!isset(self::$entityTypeTimingMap[$entityType])){
+			self::$entityTypeTimingMap[$entityType] = new TimingsHandler("** tickEntity - ". $entityType, self::$activatedEntityTimer);
+		}
+
+		return self::$entityTypeTimingMap[$entityType];
+	}
+
+	/**
+	 * @param Tile $tile
+	 *
+	 * @return TimingsHandler
+	 */
+	public static function getTileEntityTimings(Tile $tile){
+		$tileType = (new \ReflectionClass($tile))->getShortName();
+		if(!isset(self::$tileEntityTypeTimingMap[$tileType])){
+			self::$tileEntityTypeTimingMap[$tileType] = new TimingsHandler("** tickTileEntity - ". $tileType, self::$tickTileEntityTimer);
+		}
+
+		return self::$tileEntityTypeTimingMap[$tileType];
+	}
+
+}

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/level/Level.php

@@ -33,6 +33,7 @@ use pocketmine\event\block\BlockPlaceEvent;
 use pocketmine\event\level\LevelSaveEvent;
 use pocketmine\event\level\LevelUnloadEvent;
 use pocketmine\event\level\SpawnChangeEvent;
+use pocketmine\event\LevelTimings;
 use pocketmine\event\player\PlayerInteractEvent;
 use pocketmine\item\Item;
 use pocketmine\level\format\Chunk;
@@ -157,6 +158,9 @@ class Level implements ChunkManager, Metadatable{
 		Block::BEETROOT_BLOCK,
 	];
 
+	/** @var LevelTimings */
+	public $timings;
+
 	/**
 	 * Returns the chunk unique hash/key
 	 *
@@ -208,6 +212,7 @@ class Level implements ChunkManager, Metadatable{
 		$this->chunksPerTick = (int) $this->server->getProperty("chunk-ticking.per-tick", 128);
 		$this->chunkTickList = [];
 		$this->clearChunksOnTick = (bool) $this->server->getProperty("chunk-ticking.clear-tick-list", true);
+		$this->timings = new LevelTimings($this);
 	}
 
 	/**
@@ -336,7 +341,7 @@ class Level implements ChunkManager, Metadatable{
 	 */
 	public function freeAllChunks(Player $player){
 		foreach($this->usedChunks as $i => $c){
-			unset($this->usedChunks[$i][spl_object_hash($player)]);
+			unset($this->usedChunks[$i][$player->getID()]);
 		}
 	}
 
@@ -349,7 +354,7 @@ class Level implements ChunkManager, Metadatable{
 	 * @param Player $player
 	 */
 	public function freeChunk($X, $Z, Player $player){
-		unset($this->usedChunks[Level::chunkHash($X, $Z)][$player->getID()]);
+		unset($this->usedChunks[$index = Level::chunkHash($X, $Z)][$player->getID()]);
 		$this->unloadChunkRequest($X, $Z, true);
 	}
 
@@ -386,6 +391,8 @@ class Level implements ChunkManager, Metadatable{
 	 */
 	public function doTick($currentTick){
 
+		$this->timings->doTick->startTiming();
+
 		if(($currentTick % 200) === 0){
 			$this->checkTime();
 		}
@@ -440,19 +447,21 @@ class Level implements ChunkManager, Metadatable{
 		$X = null;
 		$Z = null;
 
-		//Do chunk updates
+		//Do block updates
+		$this->timings->doTickPending->startTiming();
 		while($this->updateQueue->count() > 0 and $this->updateQueue->current()["priority"] <= $currentTick){
 			$block = $this->getBlock($this->updateQueue->extract()["data"]);
 			$block->onUpdate(self::BLOCK_UPDATE_SCHEDULED);
 		}
+		$this->timings->doTickPending->stopTiming();
 
+		$this->timings->doTickTiles->startTiming();
 		$this->tickChunks();
+		$this->timings->doTickTiles->stopTiming();
 
 		$this->processChunkRequest();
 
-		if($this->nextSave < microtime(true)){
-			$this->save(false);
-		}
+		$this->timings->doTick->stopTiming();
 	}
 
 	private function tickChunks(){
@@ -1481,7 +1490,9 @@ class Level implements ChunkManager, Metadatable{
 		if($chunk instanceof Chunk){
 			return true;
 		}else{
+			$this->timings->syncChunkLoadTimer->startTiming();
 			$this->provider->loadChunk($x, $z);
+			$this->timings->syncChunkLoadTimer->stopTiming();
 
 			return $this->provider->getChunk($x, $z) instanceof Chunk;
 		}
@@ -1509,10 +1520,14 @@ class Level implements ChunkManager, Metadatable{
 		if($safe === true and $this->isChunkInUse($x, $z)){
 			return false;
 		}
+		$this->timings->doChunkUnload->startTiming();
 
 		$this->provider->unloadChunk($x, $z, $safe);
+		unset($this->usedChunks[Level::chunkHash($x, $z)]);
 		Cache::remove("world:" . $this->getID() . ":$x:$z");
 
+		$this->timings->doChunkUnload->stopTiming();
+
 		return true;
 	}
 
@@ -1668,7 +1683,7 @@ class Level implements ChunkManager, Metadatable{
 	}
 
 	public function regenerateChunk($x, $z){
-		$this->unloadChunk($x, $z);
+		$this->unloadChunk($x, $z, false);
 
 		$this->cancelUnloadChunkRequest($x, $z);
 
@@ -1677,6 +1692,8 @@ class Level implements ChunkManager, Metadatable{
 	}
 
 	public function doChunkGarbageCollection(){
+		$this->timings->doChunkGC->startTiming();
+
 		$X = null;
 		$Z = null;
 
@@ -1698,11 +1715,17 @@ class Level implements ChunkManager, Metadatable{
 			if(count($c) === 0){
 				Level::getXZ($i, $X, $Z);
 				if(!$this->isSpawnChunk($X, $Z)){
+					if($this->getAutoSave()){
+						$this->provider->saveChunk($X, $Z);
+					}
+
 					$this->unloadChunk($X, $Z, true);
 				}
 			}
 		}
 
+
+		$this->timings->doChunkGC->stopTiming();
 	}
 
 

src/pocketmine/level/format/anvil/Anvil.php

@@ -117,7 +117,10 @@ class Anvil extends BaseLevelProvider{
 		$regionX = $regionZ = null;
 		self::getRegionIndex($chunkX, $chunkZ, $regionX, $regionZ);
 		$this->loadRegion($regionX, $regionZ);
+
+		$this->level->timings->syncChunkLoadDataTimer->startTiming();
 		$chunk = $this->getRegion($regionX, $regionZ)->readChunk($chunkX - $regionX * 32, $chunkZ - $regionZ * 32, $create); //generate empty chunk if not loaded
+		$this->level->timings->syncChunkLoadDataTimer->stopTiming();
 
 		if($chunk instanceof Chunk){
 			$this->chunks[$index] = $chunk;
@@ -127,8 +130,8 @@ class Anvil extends BaseLevelProvider{
 	}
 
 	public function unloadChunk($x, $z, $safe = true){
+		$chunk = $this->getChunk($x, $z, false);
 		if($safe === true and $this->isChunkLoaded($x, $z)){
-			$chunk = $this->getChunk($x, $z);
 			foreach($chunk->getEntities() as $entity){
 				if($entity instanceof Player){
 					return false;
@@ -136,7 +139,17 @@ class Anvil extends BaseLevelProvider{
 			}
 		}
 
-		unset($this->chunks[Level::chunkHash($x, $z)]);
+		foreach($chunk->getEntities() as $entity){
+			$entity->close();
+		}
+
+		foreach($chunk->getTiles() as $tile){
+			$tile->close();
+		}
+
+		$this->chunks[$index = Level::chunkHash($x, $z)] = null;
+
+		unset($this->chunks[$index]);
 
 		return true;
 	}

src/pocketmine/level/format/anvil/RegionLoader.php

@@ -116,13 +116,14 @@ class RegionLoader{
 			$this->writeLocationIndex($index);
 		}elseif($compression !== self::COMPRESSION_ZLIB and $compression !== self::COMPRESSION_GZIP){
 			trigger_error("Invalid compression type", E_USER_WARNING);
-
 			return false;
 		}
 
 		$nbt = new NBT(NBT::BIG_ENDIAN);
 		$nbt->readCompressed(fread($this->filePointer, $length - 1), $compression);
 		$chunk = $nbt->getData();
+
+
 		if(!isset($chunk->Level) or !($chunk->Level instanceof Compound)){
 			return false;
 		}

src/pocketmine/level/format/generic/BaseChunk.php

@@ -98,6 +98,7 @@ abstract class BaseChunk implements Chunk{
 			$this->biomeColors = array_fill(0, 256, Binary::readInt("\x00\x85\xb2\x4a"));
 		}
 
+		$this->getLevel()->getLevel()->timings->syncChunkLoadEntitiesTimer->startTiming();
 		foreach($entities as $nbt){
 			if($nbt instanceof Compound){
 				if(!isset($nbt->id)){
@@ -115,8 +116,9 @@ abstract class BaseChunk implements Chunk{
 				}
 			}
 		}
+		$this->getLevel()->getLevel()->timings->syncChunkLoadEntitiesTimer->stopTiming();
 
-
+		$this->getLevel()->getLevel()->timings->syncChunkLoadTileEntitiesTimer->startTiming();
 		foreach($tiles as $nbt){
 			if($nbt instanceof Compound){
 				if(!isset($nbt->id)){
@@ -135,6 +137,7 @@ abstract class BaseChunk implements Chunk{
 				}
 			}
 		}
+		$this->getLevel()->getLevel()->timings->syncChunkLoadTileEntitiesTimer->stopTiming();
 	}
 
 	public function getX(){

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

@@ -4,9 +4,9 @@
 
 settings:
  shutdown-message: "Server closed"
- plugin-profiling: false
  query-plugins: true
  deprecated-verbose: true
+ enable-profiling: false
  advanced-cache: false
  upnp-forwarding: false
  send-usage: true

src/pocketmine/scheduler/PHPGarbageCollectionTask.php

@@ -0,0 +1,30 @@
+<?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
+
+ *
+ *
+*/
+
+namespace pocketmine\scheduler;
+
+class PHPGarbageCollectionTask extends Task{
+
+	public function onRun($currentTicks){
+		gc_collect_cycles();
+	}
+
+}

src/pocketmine/scheduler/ServerScheduler.php

@@ -178,7 +178,7 @@ class ServerScheduler{
 			$period = 1;
 		}
 
-		return $this->handle(new TaskHandler($task, $this->nextId(), $delay, $period));
+		return $this->handle(new TaskHandler(get_class($task), $task, $this->nextId(), $delay, $period));
 	}
 
 	private function handle(TaskHandler $handler){
@@ -201,12 +201,15 @@ class ServerScheduler{
 	public function mainThreadHeartbeat($currentTick){
 		$this->currentTick = $currentTick;
 		while($this->isReady($this->currentTick)){
+			/** @var TaskHandler $task */
 			$task = $this->queue->extract();
 			if($task->isCancelled()){
 				unset($this->tasks[$task->getTaskId()]);
 				continue;
 			}else{
+				$task->timings->startTiming();
 				$task->run($this->currentTick);
+				$task->timings->stopTiming();
 			}
 			if($task->isRepeating()){
 				$task->setNextRun($this->currentTick + $task->getPeriod());

src/pocketmine/scheduler/TaskHandler.php

@@ -21,6 +21,8 @@
 
 namespace pocketmine\scheduler;
 
+use pocketmine\event\Timings;
+
 class TaskHandler{
 
 	/** @var Task */
@@ -41,17 +43,25 @@ class TaskHandler{
 	/** @var bool */
 	protected $cancelled = false;
 
+	/** @var \pocketmine\event\TimingsHandler */
+	public $timings;
+
+	public $timingName = null;
+
 	/**
-	 * @param Task $task
-	 * @param int  $taskId
-	 * @param int  $delay
-	 * @param int  $period
+	 * @param string $timingName
+	 * @param Task   $task
+	 * @param int    $taskId
+	 * @param int    $delay
+	 * @param int    $period
 	 */
-	public function __construct(Task $task, $taskId, $delay = -1, $period = -1){
+	public function __construct($timingName, Task $task, $taskId, $delay = -1, $period = -1){
 		$this->task = $task;
 		$this->taskId = $taskId;
 		$this->delay = $delay;
 		$this->period = $period;
+		$this->timingName = $timingName === null ? "Unknown" : $timingName;
+		$this->timings = Timings::getPluginTaskTimings($this, $period);
 	}
 
 	/**
@@ -127,6 +137,7 @@ class TaskHandler{
 	public function remove(){
 		$this->cancelled = true;
 		$this->task->setHandler(null);
+		$this->timings->remove();
 	}
 
 	/**
@@ -135,4 +146,14 @@ class TaskHandler{
 	public function run($currentTick){
 		$this->task->onRun($currentTick);
 	}
+
+	/**
+	 * @return string
+	 */
+	public function getTaskName(){
+		if($this->timingName !== null){
+			return $this->timingName;
+		}
+		return get_class($this->task);
+	}
 }

src/pocketmine/tile/Tile.php

@@ -25,6 +25,7 @@
  */
 namespace pocketmine\tile;
 
+use pocketmine\event\Timings;
 use pocketmine\level\format\Chunk;
 use pocketmine\level\Position;
 use pocketmine\nbt\tag\Compound;
@@ -57,6 +58,9 @@ abstract class Tile extends Position{
 	protected $lastUpdate;
 	protected $server;
 
+	/** @var \pocketmine\event\TimingsHandler */
+	public $tickTimer;
+
 	public function __construct(Chunk $chunk, Compound $nbt){
 		$this->server = $chunk->getLevel()->getLevel()->getServer();
 		$this->chunk = $chunk;
@@ -72,6 +76,7 @@ abstract class Tile extends Position{
 
 		$this->chunk->addTile($this);
 		$this->getLevel()->addTile($this);
+		$this->tickTimer = Timings::getTileEntityTimings($this);
 	}
 
 	public function getID(){