Implemented global, tasks 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/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\Timings;
 use pocketmine\event\TimingsHandler;
 use pocketmine\inventory\CraftingManager;
 use pocketmine\inventory\InventoryType;
@@ -1476,6 +1477,7 @@ class Server{
 		$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));
@@ -1599,10 +1601,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();
 	}
 
 	/**
@@ -1623,7 +1630,6 @@ class Server{
 		}else{
 			$sender->sendMessage("Unknown command. Type \"help\" for help.");
 		}
-
 		return false;
 	}
 
@@ -1935,13 +1941,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(){
@@ -1999,11 +2007,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){
@@ -2020,6 +2032,8 @@ class Server{
 			$this->nextTick = 0.05 * (0.05 / max(0.05, $this->tickMeasure)) + $time;
 			$this->inTick = false;
 
+			Timings::$serverTickTimer->stopTiming();
+
 			return true;
 		}
 

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/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);
 	}
 
 	/**
@@ -386,6 +391,8 @@ class Level implements ChunkManager, Metadatable{
 	 */
 	public function doTick($currentTick){
 
+		$this->timings->doTick->startTiming();
+
 		if(($currentTick % 200) === 0){
 			$this->checkTime();
 		}
@@ -450,9 +457,7 @@ class Level implements ChunkManager, Metadatable{
 
 		$this->processChunkRequest();
 
-		if($this->nextSave < microtime(true)){
-			$this->save(false);
-		}
+		$this->timings->doTick->stopTiming();
 	}
 
 	private function tickChunks(){
@@ -1677,6 +1682,8 @@ class Level implements ChunkManager, Metadatable{
 	}
 
 	public function doChunkGarbageCollection(){
+		$this->timings->doChunkGC->startTiming();
+
 		$X = null;
 		$Z = null;
 
@@ -1703,6 +1710,8 @@ class Level implements ChunkManager, Metadatable{
 			}
 		}
 
+
+		$this->timings->doChunkGC->stopTiming();
 	}
 
 

src/pocketmine/resources/pocketmine.yml

@@ -4,7 +4,6 @@
 
 settings:
  shutdown-message: "Server closed"
- plugin-profiling: false
  query-plugins: true
  deprecated-verbose: true
  enable-profiling: false

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(!($task instanceof PluginTask) ? "Scheduler" : null, $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);
+	}
 }