Fix bug in timing + add example in readme + tests

README.md

@@ -18,7 +18,7 @@ The `$title` argument is optional; if present, it will be prepended to the messa
 
 # Quick example
 
-The following code
+The following code:
 
 ```php
 Logger::$log_level = 'debug';
@@ -37,6 +37,47 @@ $> 2021-07-21T11:11:03+02:00 [WARNING] : variable not set, something bad might h
 $> 2021-07-21T11:11:03+02:00 [ERROR] : file not found, exiting
 ```
 
+# Timing
+
+You can keep track of elapsed time by using the `time()` and `timeEnd()` function.
+
+### Timing example
+
+```php
+Logger::time();
+sleep(1);
+Logger::timeEnd();
+```
+
+will print:
+
+```
+$> 2022-04-19T17:26:26+00:00 [DEBUG] : Elapsed time => 1.003163 seconds
+```
+
+### Named timers
+
+If you need to time different processes at the same time, you can use named timers.
+
+For example:
+
+```php
+Logger::time('outer timer');
+sleep(1);
+Logger::time('inner timer');
+sleep(1);
+Logger::timeEnd('inner timer');
+Logger::timeEnd('outer timer');
+```
+
+will print:
+
+```
+$> 2022-04-19T17:32:15+00:00 [DEBUG] : Elapsed time for 'inner timer' => 1.002268 seconds
+$> 2022-04-19T17:32:15+00:00 [DEBUG] : Elapsed time for 'outer timer' => 2.006117 seconds
+```
+
+
 # Options
 
 To customize the logger, you can either:

src/Logger.php

@@ -60,6 +60,11 @@ class Logger {
  */
  public static $log_level = 'error';
 
+ /**
+ * Name for the default timer
+ */
+ public static $default_timer = 'timer';
+
  /**
  * Map logging levels to syslog specifications, there's room for the other levels
  */
@@ -130,7 +135,11 @@ public static function error( $message, $name = '' ) {
  * Returns the start time or false if a time tracker with the same name
  * exists
  */
- public static function time( string $name ) {
+ public static function time( string $name = null ) {
+
+ if ( $name === null ) {
+ $name = self::$default_timer;
+ }
 
  if ( ! isset( self::$time_tracking[ $name ] ) ) {
  self::$time_tracking[ $name ] = microtime( true );
@@ -149,14 +158,25 @@ public static function time( string $name ) {
  * Returns the total time elapsed for the given time-tracker, or false if the
  * time tracker is not found.
  */
- public static function timeEnd( string $name ) {
+ public static function timeEnd( string $name = null, int $decimals = 6, $level = 'debug' ) {
+
+ $is_default_timer = $name === null;
+
+ if ( $is_default_timer ) {
+ $name = self::$default_timer;
+ }
 
  if ( isset( self::$time_tracking[ $name ] ) ) {
  $start = self::$time_tracking[ $name ];
  $end = microtime( true );
- $elapsed_time = number_format( ( $end - $start), 2 );
- unset( self::$time_tracking[ $name] );
- self::add( "$elapsed_time seconds", "'$name' took", "timing" );
+ $elapsed_time = number_format( ( $end - $start), $decimals );
+ unset( self::$time_tracking[ $name ] );
+ if ( ! $is_default_timer ) {
+ self::add( "$elapsed_time seconds", "Elapsed time for '$name'", $level );
+ }
+ else {
+ self::add( "$elapsed_time seconds", "Elapsed time", $level );
+ }
  return $elapsed_time;
  }
  else {

tests/LoggerTest.php

@@ -64,4 +64,46 @@ public function testLogLevelTooLow()
 
  $this->assertSame( '', $result );
  }
+
+ public function testSingleTimer()
+ {
+ $seconds = 0.5;
+
+ $microSeconds = $seconds * 1e6;
+ Logger::$log_level = 'debug';
+ Logger::time( 'Testing the timing' );
+ usleep($microSeconds);
+ $result = Logger::timeEnd( 'Testing the timing', 6, 'debug' );
+
+ $this->assertEqualsWithDelta($seconds, $result, 0.01);
+ }
+
+ public function testMultipleTimers()
+ {
+ $seconds = 1;
+
+ Logger::$log_level = 'debug';
+ Logger::time('outer timer');
+ sleep($seconds);
+ Logger::time('inner timer');
+ sleep($seconds);
+ $result_2 = Logger::timeEnd('inner timer', 6, 'debug' );
+ $result_1 = Logger::timeEnd('outer timer', 6, 'debug' );
+
+ $this->assertEqualsWithDelta(2*$seconds, $result_1, 0.01);
+ $this->assertEqualsWithDelta($seconds, $result_2, 0.01);
+ }
+
+ public function testTimingWithDefaultParameters()
+ {
+ $seconds = 1;
+
+ $microSeconds = $seconds * 1e6;
+ Logger::$log_level = 'debug';
+ Logger::time();
+ usleep($microSeconds);
+ $result = Logger::timeEnd();
+
+ $this->assertEqualsWithDelta($seconds, $result, 0.01);
+ }
 }