From b14aad3292abe926334eb4b28c63f2e82ef597ae Mon Sep 17 00:00:00 2001 From: Denis Smetannikov Date: Sun, 3 Sep 2023 02:11:37 +0300 Subject: [PATCH] Fixes in profiling output (#20) --- README.md | 6 +- demo/Commands/DemoOutput.php | 2 + src/OutputMods/AbstractOutputMode.php | 2 +- src/OutputMods/Logstash.php | 7 +- src/OutputMods/Text.php | 101 +++++++++++++++++++------- tests/CliOutputLogstashTest.php | 7 +- 6 files changed, 90 insertions(+), 35 deletions(-) diff --git a/README.md b/README.md index 7751572..4f685af 100644 --- a/README.md +++ b/README.md @@ -519,7 +519,7 @@ $this->_(CliRender::list([ ### Simple log ```bash -./my-app output --timestamp >> /path/to/crontab/logs/`date +\%Y-\%m-\%d`.log 2>&1 +./my-app output --timestamp >> /path/to/crontab/logs/$(date +%Y-%m-%d).log 2>&1 ``` ![logs-simple](.github/assets/logs-simple.png) @@ -531,7 +531,7 @@ $this->_(CliRender::list([ Just add the `--output-mode=cron` flag and save the output to a file. Especially, this is very handy for saving logs for Crontab. ```bash -./my-app output --output-mode=cron >> /path/to/crontab/logs/`date +\%Y-\%m-\%d`.log 2>&1 +./my-app output --output-mode=cron >> /path/to/crontab/logs/$(date +%Y-%m-%d).log 2>&1 ``` ![logs-cron](.github/assets/logs-cron.png) @@ -543,7 +543,7 @@ Just add the `--output-mode=cron` flag and save the output to a file. Especially Just add the `--output-mode=logstash` flag and save the output to a file. Especially, this is very handy for saving logs for ELK Stack. ```bash -./my-app output --output-mode=logstash >> /path/to/logstash/logs/`date +\%Y-\%m-\%d`.log 2>&1 +./my-app output --output-mode=logstash >> /path/to/logstash/logs/$(date +%Y-%m-%d).log 2>&1 ``` ![logs-logstash-exception](.github/assets/logs-logstash-exception.png) diff --git a/demo/Commands/DemoOutput.php b/demo/Commands/DemoOutput.php index 88aa5e8..b19c9f8 100644 --- a/demo/Commands/DemoOutput.php +++ b/demo/Commands/DemoOutput.php @@ -57,6 +57,8 @@ protected function executeAction(): int // `cli($text)` is global alias for `$this->_();` + // \sleep(1); + // Info output // ./my-app examples:output -v cli("Verbose message #1 {$code('OutLvl::V')} (-v)", OutLvl::V); diff --git a/src/OutputMods/AbstractOutputMode.php b/src/OutputMods/AbstractOutputMode.php index 6083e15..45bb993 100644 --- a/src/OutputMods/AbstractOutputMode.php +++ b/src/OutputMods/AbstractOutputMode.php @@ -236,8 +236,8 @@ public static function getInstance(): self */ protected function getProfileInfo(): array { - $currentTime = \microtime(true); $currentMemory = \memory_get_usage(false); + $currentTime = \microtime(true); $startTime = $_SERVER['REQUEST_TIME_FLOAT'] ?? 0.0; diff --git a/src/OutputMods/Logstash.php b/src/OutputMods/Logstash.php index d9aef49..da5f7d7 100644 --- a/src/OutputMods/Logstash.php +++ b/src/OutputMods/Logstash.php @@ -55,9 +55,10 @@ public function onExecBefore(): void { $this->_('Command Start: ' . (string)$this->input->getFirstArgument(), OutLvl::INFO, [ 'service' => [ - 'name' => $this->application->getName(), - 'version' => $this->application->getVersion(), - 'type' => 'php', + 'name' => $this->application->getName(), + 'version' => $this->application->getVersion(), + 'type' => 'php', + 'php_version' => \PHP_VERSION, ], 'process' => [ 'pid' => \getmypid(), diff --git a/src/OutputMods/Text.php b/src/OutputMods/Text.php index accd959..643ff98 100644 --- a/src/OutputMods/Text.php +++ b/src/OutputMods/Text.php @@ -142,46 +142,97 @@ protected function printMessage( $profilePrefix .= "[{$timestamp}] "; } - if ($this->isDisplayProfiling()) { - $profile = $this->getProfileInfo(); - $memoryDiff = FS::format($profile['memory_usage_diff']); - $totalTime = \number_format($profile['time_diff_ms'] / 1000, 3); - $curMemory = \str_pad($memoryDiff, 10, ' ', \STR_PAD_LEFT); - - $profilePrefix .= "[+{$totalTime}s/{$curMemory}] "; - } - - $vNormal = OutputInterface::VERBOSITY_NORMAL; + $executePrint = false; + $printCallback = null; + $vNormal = OutputInterface::VERBOSITY_NORMAL; if ($verboseLevel === OutLvl::DEFAULT) { - $this->getOutput()->writeln($profilePrefix . $message, $vNormal); + $executePrint = $this->showMessage($vNormal); + $printCallback = function (string $profilePrefix) use ($message, $vNormal): void { + $this->getOutput()->writeln($profilePrefix . $message, $vNormal); + }; } elseif ($verboseLevel === OutLvl::V) { - $this->getOutput()->writeln($profilePrefix . $message, OutputInterface::VERBOSITY_VERBOSE); + $executePrint = $this->showMessage(OutputInterface::VERBOSITY_VERBOSE); + $printCallback = function (string $profilePrefix) use ($message): void { + $this->getOutput()->writeln($profilePrefix . $message, OutputInterface::VERBOSITY_VERBOSE); + }; } elseif ($verboseLevel === OutLvl::VV) { - $this->getOutput()->writeln($profilePrefix . $message, OutputInterface::VERBOSITY_VERY_VERBOSE); + $executePrint = $this->showMessage(OutputInterface::VERBOSITY_VERY_VERBOSE); + $printCallback = function (string $profilePrefix) use ($message): void { + $this->getOutput()->writeln($profilePrefix . $message, OutputInterface::VERBOSITY_VERY_VERBOSE); + }; } elseif ($verboseLevel === OutLvl::VVV) { - $this->getOutput()->writeln($profilePrefix . $message, OutputInterface::VERBOSITY_DEBUG); + $executePrint = $this->showMessage(OutputInterface::VERBOSITY_DEBUG); + $printCallback = function (string $profilePrefix) use ($message): void { + $this->getOutput()->writeln($profilePrefix . $message, OutputInterface::VERBOSITY_DEBUG); + }; } elseif ($verboseLevel === OutLvl::Q) { - $this->getOutput()->writeln($profilePrefix . $message, OutputInterface::VERBOSITY_QUIET); // Show ALWAYS! + $executePrint = $this->showMessage(OutputInterface::VERBOSITY_QUIET); + $printCallback = function (string $profilePrefix) use ($message): void { + $this->getOutput()->writeln( + $profilePrefix . $message, + OutputInterface::VERBOSITY_QUIET, + ); // Show ALWAYS! + }; } elseif ($verboseLevel === OutLvl::LEGACY) { - $this->_('Legacy Output: ' . $message); + $this->_("Legacy Output: {$message}"); } elseif ($verboseLevel === OutLvl::DEBUG) { - $this->_('Debug: ' . $message, OutLvl::VVV); + $this->_("Debug: {$message}", OutLvl::VVV); } elseif ($verboseLevel === OutLvl::WARNING) { - $this->_('Warning: ' . $message, OutLvl::VV); + $this->_("Warning: {$message}", OutLvl::VV); } elseif ($verboseLevel === OutLvl::INFO) { - $this->_('Info: ' . $message, OutLvl::V); + $this->_("Info: {$message}", OutLvl::V); } elseif ($verboseLevel === OutLvl::E) { - $this->markOutputHasErrors(true); - $this->getErrOutput()->writeln($profilePrefix . $message, $vNormal); + $executePrint = $this->showMessage($vNormal); + $printCallback = function (string $profilePrefix) use ($message, $vNormal): void { + $this->markOutputHasErrors(true); + $this->getErrOutput()->writeln($profilePrefix . $message, $vNormal); + }; } elseif ($verboseLevel === OutLvl::ERROR) { - $this->markOutputHasErrors(true); - $this->getErrOutput()->writeln($profilePrefix . 'Error: ' . $message, $vNormal); + $executePrint = $this->showMessage($vNormal); + $printCallback = function (string $profilePrefix) use ($message, $vNormal): void { + $this->markOutputHasErrors(true); + $this->getErrOutput()->writeln("{$profilePrefix}Error: {$message}", $vNormal); + }; } elseif ($verboseLevel === OutLvl::EXCEPTION) { - $this->markOutputHasErrors(true); - $this->getErrOutput()->writeln($profilePrefix . 'Muted Exception: ' . $message, $vNormal); + $executePrint = $this->showMessage($vNormal); + $printCallback = function (string $profilePrefix) use ($message, $vNormal): void { + $this->markOutputHasErrors(true); + $this->getErrOutput()->writeln( + "{$profilePrefix}Muted Exception: {$message}", + $vNormal, + ); + }; } else { throw new Exception("Undefined verbose level: \"{$verboseLevel}\""); } + + if ($executePrint && $printCallback !== null) { + if ($this->isDisplayProfiling()) { + $profile = $this->getProfileInfo(); + $memoryDiff = FS::format($profile['memory_usage_diff']); + $totalTime = \number_format($profile['time_diff_ms'] / 1000, 3); + $curMemory = \str_pad($memoryDiff, 10, ' ', \STR_PAD_LEFT); + $profilePrefix .= "[+{$totalTime}s/{$curMemory}] "; + } + $printCallback($profilePrefix); + } + } + + private function showMessage(int $selectedVerbosity): bool + { + $verbosities = OutputInterface::VERBOSITY_QUIET + | OutputInterface::VERBOSITY_NORMAL + | OutputInterface::VERBOSITY_VERBOSE + | OutputInterface::VERBOSITY_VERY_VERBOSE + | OutputInterface::VERBOSITY_DEBUG; + + $verbosity = ($verbosities & $selectedVerbosity) > 0 + ? $verbosities & $selectedVerbosity + : OutputInterface::VERBOSITY_NORMAL; + + $curVerbose = $this->getOutput()->getVerbosity(); + + return $verbosity <= $curVerbose; } } diff --git a/tests/CliOutputLogstashTest.php b/tests/CliOutputLogstashTest.php index 1c33277..80b1248 100644 --- a/tests/CliOutputLogstashTest.php +++ b/tests/CliOutputLogstashTest.php @@ -85,9 +85,10 @@ public function testFormatOfMessageVerboseFisrt(): void 'time_diff_ms' => 'double', ], 'service' => [ - 'name' => 'string', - 'version' => 'string', - 'type' => 'string', + 'name' => 'string', + 'version' => 'string', + 'type' => 'string', + 'php_version' => 'string', ], 'process' => [ 'pid' => 'integer',