Async task timings

composer.json

@@ -41,7 +41,7 @@
       "pocketmine/callback-validator": "^1.0.2",
       "pocketmine/color": "^0.3.0",
       "pocketmine/errorhandler": "^0.7.0",
-      "pocketmine/locale-data": "~2.21.0",
+      "pocketmine/locale-data": "~2.22.0",
       "pocketmine/log": "^0.4.0",
       "pocketmine/math": "~1.0.0",
       "pocketmine/nbt": "~1.0.0",

src/Server.php

@@ -89,6 +89,8 @@
 use pocketmine\promise\PromiseResolver;
 use pocketmine\resourcepacks\ResourcePackManager;
 use pocketmine\scheduler\AsyncPool;
+use pocketmine\scheduler\TimingsCollectionTask;
+use pocketmine\scheduler\TimingsControlTask;
 use pocketmine\snooze\SleeperHandler;
 use pocketmine\stats\SendUsageTask;
 use pocketmine\thread\log\AttachableThreadSafeLogger;
@@ -891,7 +893,36 @@ public function __construct(
 				$poolSize = max(1, (int) $poolSize);
 			}
 
+			TimingsHandler::setEnabled($this->configGroup->getPropertyBool(Yml::SETTINGS_ENABLE_PROFILING, false));
+			$this->profilingTickRate = $this->configGroup->getPropertyInt(Yml::SETTINGS_PROFILE_REPORT_TRIGGER, self::TARGET_TICKS_PER_SECOND);
+
 			$this->asyncPool = new AsyncPool($poolSize, max(-1, $this->configGroup->getPropertyInt(Yml::MEMORY_ASYNC_WORKER_HARD_LIMIT, 256)), $this->autoloader, $this->logger, $this->tickSleeper);
+			$this->asyncPool->addWorkerStartHook(function(int $i) : void{
+				if(TimingsHandler::isEnabled()){
+					$this->asyncPool->submitTaskToWorker(TimingsControlTask::setEnabled(true), $i);
+				}
+			});
+			TimingsHandler::getToggleCallbacks()->add(function(bool $enable) : void{
+				foreach($this->asyncPool->getRunningWorkers() as $workerId){
+					$this->asyncPool->submitTaskToWorker(TimingsControlTask::setEnabled($enable), $workerId);
+				}
+			});
+			TimingsHandler::getReloadCallbacks()->add(function() : void{
+				foreach($this->asyncPool->getRunningWorkers() as $workerId){
+					$this->asyncPool->submitTaskToWorker(TimingsControlTask::reload(), $workerId);
+				}
+			});
+			TimingsHandler::getCollectCallbacks()->add(function() : array{
+				$promises = [];
+				foreach($this->asyncPool->getRunningWorkers() as $workerId){
+					$resolver = new PromiseResolver();
+					$this->asyncPool->submitTaskToWorker(new TimingsCollectionTask($resolver), $workerId);
+
+					$promises[] = $resolver->getPromise();
+				}
+
+				return $promises;
+			});
 
 			$netCompressionThreshold = -1;
 			if($this->configGroup->getPropertyInt(Yml::NETWORK_BATCH_THRESHOLD, 256) >= 0){
@@ -965,9 +996,6 @@ public function __construct(
 			)));
 			$this->logger->info($this->language->translate(KnownTranslationFactory::pocketmine_server_license($this->getName())));
 
-			TimingsHandler::setEnabled($this->configGroup->getPropertyBool(Yml::SETTINGS_ENABLE_PROFILING, false));
-			$this->profilingTickRate = $this->configGroup->getPropertyInt(Yml::SETTINGS_PROFILE_REPORT_TRIGGER, self::TARGET_TICKS_PER_SECOND);
-
 			DefaultPermissions::registerCorePermissions();
 
 			$this->commandMap = new SimpleCommandMap($this);

src/command/defaults/TimingsCommand.php

@@ -26,28 +26,28 @@
 use pocketmine\command\Command;
 use pocketmine\command\CommandSender;
 use pocketmine\command\utils\InvalidCommandSyntaxException;
+use pocketmine\errorhandler\ErrorToExceptionHandler;
 use pocketmine\lang\KnownTranslationFactory;
 use pocketmine\permission\DefaultPermissionNames;
 use pocketmine\player\Player;
 use pocketmine\scheduler\BulkCurlTask;
 use pocketmine\scheduler\BulkCurlTaskOperation;
 use pocketmine\timings\TimingsHandler;
+use pocketmine\utils\AssumptionFailedError;
 use pocketmine\utils\InternetException;
 use pocketmine\utils\InternetRequestResult;
-use pocketmine\utils\Utils;
 use pocketmine\YmlServerProperties;
 use Symfony\Component\Filesystem\Path;
 use function count;
 use function fclose;
 use function file_exists;
 use function fopen;
-use function fseek;
 use function fwrite;
 use function http_build_query;
+use function implode;
 use function is_array;
 use function json_decode;
 use function mkdir;
-use function stream_get_contents;
 use function strtolower;
 use const CURLOPT_AUTOREFERER;
 use const CURLOPT_FOLLOWLOCATION;
@@ -101,82 +101,91 @@ public function execute(CommandSender $sender, string $commandLabel, array $args
 			TimingsHandler::reload();
 			Command::broadcastCommandMessage($sender, KnownTranslationFactory::pocketmine_command_timings_reset());
 		}elseif($mode === "merged" || $mode === "report" || $paste){
-			$timings = "";
-			if($paste){
-				$fileTimings = Utils::assumeNotFalse(fopen("php://temp", "r+b"), "Opening php://temp should never fail");
-			}else{
-				$index = 0;
-				$timingFolder = Path::join($sender->getServer()->getDataPath(), "timings");
-
-				if(!file_exists($timingFolder)){
-					mkdir($timingFolder, 0777);
-				}
-				$timings = Path::join($timingFolder, "timings.txt");
-				while(file_exists($timings)){
-					$timings = Path::join($timingFolder, "timings" . (++$index) . ".txt");
-				}
-
-				$fileTimings = fopen($timings, "a+b");
-			}
-			$lines = TimingsHandler::printTimings();
-			foreach($lines as $line){
-				fwrite($fileTimings, $line . PHP_EOL);
-			}
-
-			if($paste){
-				fseek($fileTimings, 0);
-				$data = [
-					"browser" => $agent = $sender->getServer()->getName() . " " . $sender->getServer()->getPocketMineVersion(),
-					"data" => $content = stream_get_contents($fileTimings)
-				];
-				fclose($fileTimings);
-
-				$host = $sender->getServer()->getConfigGroup()->getPropertyString(YmlServerProperties::TIMINGS_HOST, "timings.pmmp.io");
-
-				$sender->getServer()->getAsyncPool()->submitTask(new BulkCurlTask(
-					[new BulkCurlTaskOperation(
-						"https://$host?upload=true",
-						10,
-						[],
-						[
-							CURLOPT_HTTPHEADER => [
-								"User-Agent: $agent",
-								"Content-Type: application/x-www-form-urlencoded"
-							],
-							CURLOPT_POST => true,
-							CURLOPT_POSTFIELDS => http_build_query($data),
-							CURLOPT_AUTOREFERER => false,
-							CURLOPT_FOLLOWLOCATION => false
-						]
-					)],
-					function(array $results) use ($sender, $host) : void{
-						/** @phpstan-var array<InternetRequestResult|InternetException> $results */
-						if($sender instanceof Player && !$sender->isOnline()){ // TODO replace with a more generic API method for checking availability of CommandSender
-							return;
-						}
-						$result = $results[0];
-						if($result instanceof InternetException){
-							$sender->getServer()->getLogger()->logException($result);
-							return;
-						}
-						$response = json_decode($result->getBody(), true);
-						if(is_array($response) && isset($response["id"])){
-							Command::broadcastCommandMessage($sender, KnownTranslationFactory::pocketmine_command_timings_timingsRead(
-								"https://" . $host . "/?id=" . $response["id"]));
-						}else{
-							$sender->getServer()->getLogger()->debug("Invalid response from timings server (" . $result->getCode() . "): " . $result->getBody());
-							Command::broadcastCommandMessage($sender, KnownTranslationFactory::pocketmine_command_timings_pasteError());
-						}
-					}
-				));
-			}else{
-				fclose($fileTimings);
-				Command::broadcastCommandMessage($sender, KnownTranslationFactory::pocketmine_command_timings_timingsWrite($timings));
-			}
+			$timingsPromise = TimingsHandler::requestPrintTimings();
+			Command::broadcastCommandMessage($sender, KnownTranslationFactory::pocketmine_command_timings_collect());
+			$timingsPromise->onCompletion(
+				fn(array $lines) => $paste ? $this->uploadReport($lines, $sender) : $this->createReportFile($lines, $sender),
+				fn() => throw new AssumptionFailedError("This promise is not expected to be rejected")
+			);
 		}else{
 			throw new InvalidCommandSyntaxException();
 		}
 
 		return true;
 	}
+
+	/**
+	 * @param string[] $lines
+	 * @phpstan-param list<string> $lines
+	 */
+	private function createReportFile(array $lines, CommandSender $sender) : void{
+		$index = 0;
+		$timingFolder = Path::join($sender->getServer()->getDataPath(), "timings");
+
+		if(!file_exists($timingFolder)){
+			mkdir($timingFolder, 0777);
+		}
+		$timings = Path::join($timingFolder, "timings.txt");
+		while(file_exists($timings)){
+			$timings = Path::join($timingFolder, "timings" . (++$index) . ".txt");
+		}
+
+		$fileTimings = ErrorToExceptionHandler::trapAndRemoveFalse(fn() => fopen($timings, "a+b"));
+		foreach($lines as $line){
+			fwrite($fileTimings, $line . PHP_EOL);
+		}
+		fclose($fileTimings);
+
+		Command::broadcastCommandMessage($sender, KnownTranslationFactory::pocketmine_command_timings_timingsWrite($timings));
+	}
+
+	/**
+	 * @param string[] $lines
+	 * @phpstan-param list<string> $lines
+	 */
+	private function uploadReport(array $lines, CommandSender $sender) : void{
+		$data = [
+			"browser" => $agent = $sender->getServer()->getName() . " " . $sender->getServer()->getPocketMineVersion(),
+			"data" => implode("\n", $lines)
+		];
+
+		$host = $sender->getServer()->getConfigGroup()->getPropertyString(YmlServerProperties::TIMINGS_HOST, "timings.pmmp.io");
+
+		$sender->getServer()->getAsyncPool()->submitTask(new BulkCurlTask(
+			[new BulkCurlTaskOperation(
+				"https://$host?upload=true",
+				10,
+				[],
+				[
+					CURLOPT_HTTPHEADER => [
+						"User-Agent: $agent",
+						"Content-Type: application/x-www-form-urlencoded"
+					],
+					CURLOPT_POST => true,
+					CURLOPT_POSTFIELDS => http_build_query($data),
+					CURLOPT_AUTOREFERER => false,
+					CURLOPT_FOLLOWLOCATION => false
+				]
+			)],
+			function(array $results) use ($sender, $host) : void{
+				/** @phpstan-var array<InternetRequestResult|InternetException> $results */
+				if($sender instanceof Player && !$sender->isOnline()){ // TODO replace with a more generic API method for checking availability of CommandSender
+					return;
+				}
+				$result = $results[0];
+				if($result instanceof InternetException){
+					$sender->getServer()->getLogger()->logException($result);
+					return;
+				}
+				$response = json_decode($result->getBody(), true);
+				if(is_array($response) && isset($response["id"])){
+					Command::broadcastCommandMessage($sender, KnownTranslationFactory::pocketmine_command_timings_timingsRead(
+						"https://" . $host . "/?id=" . $response["id"]));
+				}else{
+					$sender->getServer()->getLogger()->debug("Invalid response from timings server (" . $result->getCode() . "): " . $result->getBody());
+					Command::broadcastCommandMessage($sender, KnownTranslationFactory::pocketmine_command_timings_pasteError());
+				}
+			}
+		));
+	}
 }

src/lang/KnownTranslationFactory.php

@@ -1441,6 +1441,10 @@ public static function pocketmine_command_timings_alreadyEnabled() : Translatabl
 		return new Translatable(KnownTranslationKeys::POCKETMINE_COMMAND_TIMINGS_ALREADYENABLED, []);
 	}
 
+	public static function pocketmine_command_timings_collect() : Translatable{
+		return new Translatable(KnownTranslationKeys::POCKETMINE_COMMAND_TIMINGS_COLLECT, []);
+	}
+
 	public static function pocketmine_command_timings_description() : Translatable{
 		return new Translatable(KnownTranslationKeys::POCKETMINE_COMMAND_TIMINGS_DESCRIPTION, []);
 	}

src/lang/KnownTranslationKeys.php

@@ -315,6 +315,7 @@ final class KnownTranslationKeys{
 	public const POCKETMINE_COMMAND_TIME_DESCRIPTION = "pocketmine.command.time.description";
 	public const POCKETMINE_COMMAND_TIME_USAGE = "pocketmine.command.time.usage";
 	public const POCKETMINE_COMMAND_TIMINGS_ALREADYENABLED = "pocketmine.command.timings.alreadyEnabled";
+	public const POCKETMINE_COMMAND_TIMINGS_COLLECT = "pocketmine.command.timings.collect";
 	public const POCKETMINE_COMMAND_TIMINGS_DESCRIPTION = "pocketmine.command.timings.description";
 	public const POCKETMINE_COMMAND_TIMINGS_DISABLE = "pocketmine.command.timings.disable";
 	public const POCKETMINE_COMMAND_TIMINGS_ENABLE = "pocketmine.command.timings.enable";

src/scheduler/AsyncTask.php

@@ -27,6 +27,7 @@
 use pmmp\thread\ThreadSafe;
 use pmmp\thread\ThreadSafeArray;
 use pocketmine\thread\NonThreadSafeValue;
+use pocketmine\timings\Timings;
 use function array_key_exists;
 use function igbinary_serialize;
 use function igbinary_unserialize;
@@ -78,7 +79,14 @@ abstract class AsyncTask extends Runnable{
 	public function run() : void{
 		$this->result = null;
 
-		$this->onRun();
+		$timings = Timings::getAsyncTaskRunTimings($this);
+		$timings->startTiming();
+
+		try{
+			$this->onRun();
+		}finally{
+			$timings->stopTiming();
+		}
 
 		$this->finished = true;
 		AsyncWorker::getNotifier()->wakeupSleeper();