Added timings for AsyncTask completion handlers, progress updates and error handlers (#5798)

closes #5749

src/scheduler/AsyncPool.php

@@ -27,6 +27,7 @@ use pmmp\thread\Thread as NativeThread;
 use pocketmine\snooze\SleeperHandler;
 use pocketmine\thread\log\ThreadSafeLogger;
 use pocketmine\thread\ThreadSafeClassLoader;
+use pocketmine\timings\Timings;
 use pocketmine\utils\Utils;
 use function array_keys;
 use function array_map;
@@ -231,7 +232,9 @@ class AsyncPool{
 
 				if($task->isCrashed()){
 					$this->logger->critical("Could not execute asynchronous task " . (new \ReflectionClass($task))->getShortName() . ": Task crashed");
-					$task->onError();
+					Timings::getAsyncTaskErrorTimings($task)->time(function() use ($task) : void{
+						$task->onError();
+					});
 				}elseif(!$task->hasCancelledRun()){
 					/*
 					 * It's possible for a task to submit a progress update and then finish before the progress
@@ -242,11 +245,13 @@ class AsyncPool{
 					 * lost. Thus, it's necessary to do one last check here to make sure all progress updates have
 					 * been consumed before completing.
 					 */
-					$task->checkProgressUpdates();
+					$this->checkTaskProgressUpdates($task);
-					$task->onCompletion();
+					Timings::getAsyncTaskCompletionTimings($task)->time(function() use ($task) : void{
+						$task->onCompletion();
+					});
 				}
 			}else{
-				$task->checkProgressUpdates();
+				$this->checkTaskProgressUpdates($task);
 				$more = true;
 				break; //current task is still running, skip to next worker
 			}
@@ -294,4 +299,10 @@ class AsyncPool{
 		}
 		$this->workers = [];
 	}
+
+	private function checkTaskProgressUpdates(AsyncTask $task) : void{
+		Timings::getAsyncTaskProgressUpdateTimings($task)->time(function() use ($task) : void{
+			$task->checkProgressUpdates();
+		});
+	}
 }

src/timings/Timings.php

@@ -29,6 +29,7 @@ use pocketmine\event\Event;
 use pocketmine\network\mcpe\protocol\ClientboundPacket;
 use pocketmine\network\mcpe\protocol\ServerboundPacket;
 use pocketmine\player\Player;
+use pocketmine\scheduler\AsyncTask;
 use pocketmine\scheduler\TaskHandler;
 use function get_class;
 use function str_starts_with;
@@ -115,6 +116,17 @@ abstract class Timings{
 	/** @var TimingsHandler[][] */
 	private static array $eventHandlers = [];
 
+	private static TimingsHandler $asyncTaskProgressUpdateParent;
+	private static TimingsHandler $asyncTaskCompletionParent;
+	private static TimingsHandler $asyncTaskErrorParent;
+
+	/** @var TimingsHandler[] */
+	private static array $asyncTaskProgressUpdate = [];
+	/** @var TimingsHandler[] */
+	private static array $asyncTaskCompletion = [];
+	/** @var TimingsHandler[] */
+	private static array $asyncTaskError = [];
+
 	public static function init() : void{
 		if(self::$initialized){
 			return;
@@ -168,7 +180,11 @@ abstract class Timings{
 		self::$itemEntityBaseTick = new TimingsHandler("Entity Base Tick - ItemEntity", group: self::GROUP_BREAKDOWN);
 
 		self::$schedulerSync = new TimingsHandler("Scheduler - Sync Tasks", group: self::GROUP_BREAKDOWN);
+
 		self::$schedulerAsync = new TimingsHandler("Scheduler - Async Tasks", group: self::GROUP_BREAKDOWN);
+		self::$asyncTaskProgressUpdateParent = new TimingsHandler("Async Tasks - Progress Updates", self::$schedulerAsync, group: self::GROUP_BREAKDOWN);
+		self::$asyncTaskCompletionParent = new TimingsHandler("Async Tasks - Completion Handlers", self::$schedulerAsync, group: self::GROUP_BREAKDOWN);
+		self::$asyncTaskErrorParent = new TimingsHandler("Async Tasks - Error Handlers", self::$schedulerAsync, group: self::GROUP_BREAKDOWN);
 
 		self::$playerCommand = new TimingsHandler("Player Command", group: self::GROUP_BREAKDOWN);
 		self::$craftingDataCacheRebuild = new TimingsHandler("Build CraftingDataPacket Cache", group: self::GROUP_BREAKDOWN);
@@ -299,4 +315,46 @@ abstract class Timings{
 
 		return self::$eventHandlers[$event][$handlerName];
 	}
+
+	public static function getAsyncTaskProgressUpdateTimings(AsyncTask $task, string $group = self::GROUP_BREAKDOWN) : TimingsHandler{
+		$taskClass = $task::class;
+		if(!isset(self::$asyncTaskProgressUpdate[$taskClass])){
+			self::init();
+			self::$asyncTaskProgressUpdate[$taskClass] = new TimingsHandler(
+				"AsyncTask - " . self::shortenCoreClassName($taskClass, "pocketmine\\") . " - Progress Updates",
+				self::$asyncTaskProgressUpdateParent,
+				$group
+			);
+		}
+
+		return self::$asyncTaskProgressUpdate[$taskClass];
+	}
+
+	public static function getAsyncTaskCompletionTimings(AsyncTask $task, string $group = self::GROUP_BREAKDOWN) : TimingsHandler{
+		$taskClass = $task::class;
+		if(!isset(self::$asyncTaskCompletion[$taskClass])){
+			self::init();
+			self::$asyncTaskCompletion[$taskClass] = new TimingsHandler(
+				"AsyncTask - " . self::shortenCoreClassName($taskClass, "pocketmine\\") . " - Completion Handler",
+				self::$asyncTaskCompletionParent,
+				$group
+			);
+		}
+
+		return self::$asyncTaskCompletion[$taskClass];
+	}
+
+	public static function getAsyncTaskErrorTimings(AsyncTask $task, string $group = self::GROUP_BREAKDOWN) : TimingsHandler{
+		$taskClass = $task::class;
+		if(!isset(self::$asyncTaskError[$taskClass])){
+			self::init();
+			self::$asyncTaskError[$taskClass] = new TimingsHandler(
+				"AsyncTask - " . self::shortenCoreClassName($taskClass, "pocketmine\\") . " - Error Handler",
+				self::$asyncTaskErrorParent,
+				$group
+			);
+		}
+
+		return self::$asyncTaskError[$taskClass];
+	}
 }