From aa11937ab244af26d8593460d533515513db0fc8 Mon Sep 17 00:00:00 2001 From: Clemens Schwaighofer Date: Thu, 2 Jun 2022 16:30:22 +0900 Subject: [PATCH] Update Running time for better high resolution timer Instead of ending with the second hr timer call, we print out difference to the last one. Add new method to print out from start time difference and add a reset method --- 4dev/tests/CoreLibsDebugRunningTimeTest.php | 62 ++++++++- www/admin/class_test.runningtime.php | 11 +- www/lib/CoreLibs/Debug/RunningTime.php | 134 +++++++++++++------- 3 files changed, 158 insertions(+), 49 deletions(-) diff --git a/4dev/tests/CoreLibsDebugRunningTimeTest.php b/4dev/tests/CoreLibsDebugRunningTimeTest.php index 95a27a57..20375635 100644 --- a/4dev/tests/CoreLibsDebugRunningTimeTest.php +++ b/4dev/tests/CoreLibsDebugRunningTimeTest.php @@ -15,6 +15,8 @@ final class CoreLibsDebugRunningTimeTest extends TestCase { public function hrRunningTimeProvider(): array { + // 0: return time difference + // 1: return time on first run in regex return [ 'default time' => [ 0 => null, @@ -69,21 +71,73 @@ final class CoreLibsDebugRunningTimeTest extends TestCase */ public function testHrRunningTime(?string $out_time, string $expected): void { + // reset for each run + \CoreLibs\Debug\RunningTime::hrRunningTimeReset(); $start = \CoreLibs\Debug\RunningTime::hrRunningTime(); $this->assertEquals( 0, - $start + $start, + 'assert first run 0' ); time_nanosleep(1, 500); if ($out_time === null) { - $end = \CoreLibs\Debug\RunningTime::hrRunningTime(); + $second = \CoreLibs\Debug\RunningTime::hrRunningTime(); } else { - $end = \CoreLibs\Debug\RunningTime::hrRunningTime($out_time); + $second = \CoreLibs\Debug\RunningTime::hrRunningTime($out_time); } // print "E: " . $end . "\n"; $this->assertMatchesRegularExpression( $expected, - (string)$end + (string)$second, + 'assert second run regex' + ); + if ($out_time === null) { + $end_second = \CoreLibs\Debug\RunningTime::hrRunningTimeFromStart(); + } else { + $end_second = \CoreLibs\Debug\RunningTime::hrRunningTimeFromStart($out_time); + } + $this->assertEquals( + $end_second, + $second, + 'assert end is equal second' + ); + // sleep again, second messurement + time_nanosleep(1, 500); + if ($out_time === null) { + $third = \CoreLibs\Debug\RunningTime::hrRunningTime(); + } else { + $third = \CoreLibs\Debug\RunningTime::hrRunningTime($out_time); + } + // third call is not null + $this->assertNotEquals( + 0, + $third, + 'assert third call not null' + ); + // third call is bigger than end + $this->assertNotEquals( + $second, + $third, + 'assert third different second' + ); + // last messurement, must match start - end + last + if ($out_time === null) { + $end = \CoreLibs\Debug\RunningTime::hrRunningTimeFromStart(); + } else { + $end = \CoreLibs\Debug\RunningTime::hrRunningTimeFromStart($out_time); + } + $this->assertGreaterThan( + $third, + $end, + 'assert end greater third' + ); + // new start + \CoreLibs\Debug\RunningTime::hrRunningTimeReset(); + $new_start = \CoreLibs\Debug\RunningTime::hrRunningTime(); + $this->assertEquals( + 0, + $new_start, + 'assert new run 0' ); } diff --git a/www/admin/class_test.runningtime.php b/www/admin/class_test.runningtime.php index 7d33d272..93472f03 100644 --- a/www/admin/class_test.runningtime.php +++ b/www/admin/class_test.runningtime.php @@ -52,8 +52,17 @@ echo "TIMED [hr]: " . RunningTime::hrRunningTime() . "
"; echo "TIMED [def]: " . RunningTime::runningTime() . "
"; echo "TIMED [string]: " . RunningTime::runningTimeString() . "
"; RunningTime::hrRunningTime(); +echo "TIMED [hr-end] " . RunningTime::hrRunningTimeFromStart() . "
"; +echo "
"; echo "RANDOM KEY [default]: " . \CoreLibs\Create\RandomKey::randomKeyGen() . "
"; -echo "TIMED [hr]: " . RunningTime::hrRunningTime() . "
"; +echo "TIMED 1 [hr]: " . RunningTime::hrRunningTime() . "
"; +echo "TIMED 1 [hr-n]: " . RunningTime::hrRunningTime() . "
"; +echo "TIMED 1 [hr-b]: " . RunningTime::hrRunningTime() . "
"; +echo "TIMED 1 [hr-end]: " . RunningTime::hrRunningTimeFromStart() . "
"; +RunningTime::hrRunningTimeReset(); +RunningTime::hrRunningTime(); +echo "TIMED 2 [hr]: " . RunningTime::hrRunningTime() . "
"; +echo "TIMED 2 [hr-end]: " . RunningTime::hrRunningTimeFromStart() . "
"; // error message print $log->printErrorMsg(); diff --git a/www/lib/CoreLibs/Debug/RunningTime.php b/www/lib/CoreLibs/Debug/RunningTime.php index 6e95478c..7058ef11 100644 --- a/www/lib/CoreLibs/Debug/RunningTime.php +++ b/www/lib/CoreLibs/Debug/RunningTime.php @@ -12,43 +12,30 @@ class RunningTime { // hr /** @var float */ - private static $hr_starttime; + private static $hr_start_time; /** @var float */ - private static $hr_runtime; + private static $hr_end_time; /** @var float */ - private static $hr_endtime; + private static $hr_last_time; // normal /** @var float */ - private static $starttime; + private static $start_time; /** @var float */ - private static $endtime; + private static $end_time; /** @var string */ - private static $runningtime_string; + private static $running_time_string; /** - * for messure run time between two calls for this method - * uses the hrtime() for running time - * first call sets start time and returns 0, - * second call sets end time and returns the run time - * the out_time parameter can be: - * n/ns (nano), y/ys (micro), m/ms (milli), s (seconds) - * default is milliseconds - * @param string $out_time set return time adjustment calculation - * @return float running time without out_time suffix + * sub calculation for running time based on out time. + * If no running time set, return 0 + * + * @param string $out_time + * @return float */ - public static function hrRunningTime(string $out_time = 'ms'): float - { - // if start time not set, set start time - if (!self::$hr_starttime) { - self::$hr_starttime = hrtime(true); - self::$hr_runtime = 0; - } else { - self::$hr_endtime = hrtime(true); - self::$hr_runtime = self::$hr_endtime - self::$hr_starttime; - // reset start and end time past run - self::$hr_starttime = 0; - self::$hr_endtime = 0; - } + private static function hrRunningTimeCalc( + float $run_time, + string $out_time = 'ms' + ): float { // init divisor, just in case $divisor = 1; // check through valid out time, if nothing matches default to ms @@ -74,8 +61,67 @@ class RunningTime break; } // return the run time in converted format - self::$hr_runtime /= $divisor; - return self::$hr_runtime; + return $run_time /= $divisor; + } + + /** + * for messure run time between two calls for this method + * uses the hrtime() for running time + * first call sets start time and returns 0, + * every other call sets end time and returns the run time since start + * the out_time parameter can be: + * n/ns (nano), y/ys (micro), m/ms (milli), s (seconds) + * default is milliseconds + * + * @param string $out_time set return time adjustment calculation + * @return float running time without out_time suffix + */ + public static function hrRunningTime(string $out_time = 'ms'): float + { + // if start time not set, set start time + if (!self::$hr_start_time) { + self::$hr_start_time = hrtime(true); + self::$hr_last_time = self::$hr_start_time; + $run_time = 0; + } else { + self::$hr_end_time = hrtime(true); + $run_time = self::$hr_end_time - self::$hr_last_time; + self::$hr_last_time = self::$hr_end_time; + } + return self::hrRunningTimeCalc($run_time, $out_time); + } + + /** + * print overall end time , can only be called after hrRunningtime + * see $out_time parameter description in hrRunningtime. + * Does not record a new timestamp, only prints different between start and + * last recoreded timestamp + * + * @param string $out_time set return time adjustment calculation + * @return float overall running time without out_time suffix + */ + public static function hrRunningTimeFromStart(string $out_time = 'ms'): float + { + if (!self::$hr_start_time) { + return (float)0; + } + $time = self::hrRunningTimeCalc( + self::$hr_end_time - self::$hr_start_time, + $out_time + ); + return $time; + } + + /** + * reset hr running time internal variables (start, end, last) + * + * @return void + */ + public static function hrRunningTimeReset(): void + { + self::$hr_start_time = 0; + self::$hr_end_time = 0; + self::$hr_last_time = 0; } /** @@ -91,24 +137,24 @@ class RunningTime list($micro, $timestamp) = explode(' ', microtime()); $running_time = 0; // set start & end time - if (!self::$starttime) { + if (!self::$start_time) { // always reset running time string on first call - self::$runningtime_string = ''; - self::$starttime = ((float)$micro + (float)$timestamp); - self::$runningtime_string .= $simple ? 'Start: ' : "Started at: "; + self::$running_time_string = ''; + self::$start_time = ((float)$micro + (float)$timestamp); + self::$running_time_string .= $simple ? 'Start: ' : "Started at: "; } else { - self::$endtime = ((float)$micro + (float)$timestamp); - self::$runningtime_string .= $simple ? 'End: ' : "Stopped at: "; + self::$end_time = ((float)$micro + (float)$timestamp); + self::$running_time_string .= $simple ? 'End: ' : "Stopped at: "; } - self::$runningtime_string .= date('Y-m-d H:i:s', (int)$timestamp); - self::$runningtime_string .= ' ' . $micro . ($simple ? ', ' : '
'); + self::$running_time_string .= date('Y-m-d H:i:s', (int)$timestamp); + self::$running_time_string .= ' ' . $micro . ($simple ? ', ' : '
'); // if both are set - if (self::$starttime && self::$endtime) { - $running_time = self::$endtime - self::$starttime; - self::$runningtime_string .= ($simple ? 'Run: ' : "Script running time: ") . $running_time . " s"; + if (self::$start_time && self::$end_time) { + $running_time = self::$end_time - self::$start_time; + self::$running_time_string .= ($simple ? 'Run: ' : "Script running time: ") . $running_time . " s"; // reset start & end time after run - self::$starttime = 0; - self::$endtime = 0; + self::$start_time = 0; + self::$end_time = 0; } return $running_time; } @@ -120,7 +166,7 @@ class RunningTime */ public static function runningTimeString(): string { - return self::$runningtime_string; + return self::$running_time_string; } }