Skip to content

Commit

Permalink
Fixes in profiling output (#20)
Browse files Browse the repository at this point in the history
  • Loading branch information
@SmetDenis
SmetDenis committed Sep 2, 2023
1 parent 10f743b commit b14aad3
Show file tree
Hide file tree
Showing 6 changed files with 90 additions and 35 deletions.
6 changes: 3 additions & 3 deletions README.md
View file
Expand Up @@ -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)
Expand All @@ -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)
Expand All @@ -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)
Expand Down
2 changes: 2 additions & 0 deletions demo/Commands/DemoOutput.php
View file
Expand Up @@ -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);
Expand Down
2 changes: 1 addition & 1 deletion src/OutputMods/AbstractOutputMode.php
View file
Expand Up @@ -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;

Expand Down
7 changes: 4 additions & 3 deletions src/OutputMods/Logstash.php
View file
Expand Up @@ -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(),
Expand Down
101 changes: 76 additions & 25 deletions src/OutputMods/Text.php
View file
Expand Up @@ -142,46 +142,97 @@ protected function printMessage(
$profilePrefix .= "<green>[</green>{$timestamp}<green>]</green> ";
}

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 .= "<green>[</green>+{$totalTime}s<green>/</green>{$curMemory}<green>]</green> ";
}

$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->_('<yellow>Legacy Output:</yellow> ' . $message);
$this->_("<yellow>Legacy Output:</yellow> {$message}");
} elseif ($verboseLevel === OutLvl::DEBUG) {
$this->_('<magenta>Debug:</magenta> ' . $message, OutLvl::VVV);
$this->_("<magenta>Debug:</magenta> {$message}", OutLvl::VVV);
} elseif ($verboseLevel === OutLvl::WARNING) {
$this->_('<yellow>Warning:</yellow> ' . $message, OutLvl::VV);
$this->_("<yellow>Warning:</yellow> {$message}", OutLvl::VV);
} elseif ($verboseLevel === OutLvl::INFO) {
$this->_('<blue>Info:</blue> ' . $message, OutLvl::V);
$this->_("<blue>Info:</blue> {$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 . '<red-bg>Error:</red-bg> ' . $message, $vNormal);
$executePrint = $this->showMessage($vNormal);
$printCallback = function (string $profilePrefix) use ($message, $vNormal): void {
$this->markOutputHasErrors(true);
$this->getErrOutput()->writeln("{$profilePrefix}<red-bg>Error:</red-bg> {$message}", $vNormal);
};
} elseif ($verboseLevel === OutLvl::EXCEPTION) {
$this->markOutputHasErrors(true);
$this->getErrOutput()->writeln($profilePrefix . '<red-bg>Muted Exception:</red-bg> ' . $message, $vNormal);
$executePrint = $this->showMessage($vNormal);
$printCallback = function (string $profilePrefix) use ($message, $vNormal): void {
$this->markOutputHasErrors(true);
$this->getErrOutput()->writeln(
"{$profilePrefix}<red-bg>Muted Exception:</red-bg> {$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 .= "<green>[</green>+{$totalTime}s<green>/</green>{$curMemory}<green>]</green> ";
}
$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;
}
}
7 changes: 4 additions & 3 deletions tests/CliOutputLogstashTest.php
View file
Expand Up @@ -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',
Expand Down

0 comments on commit b14aad3

Please sign in to comment.