Yii 1.1: benchmark

Very simple yet useful benchmarking/logging class
5 followers

Designed to provide running stats and summary at the end. Since it can output results to STDOUT only, its usefulness is enjoyed by the CLI scripts. Next versions will support logging to files and/or injecting it to HTML pages.

Idea and Concept

I had a need for a quick and easy solution for CLI scripts to be more verbose - what they're doing and how long it took to perform various chunks of code with a summary of operations, average and total elapsed time for each. Another requirement was to support forked kids' logs in one place (as opposed to having as many log files as there were kids).

Yii log classes won't be of much help for the reasons outlined in this comment.

...more to follow.

Configuration

At the moment it supports none. As implied, all output goes to STDOUT.

Import class in protected/config/main.php or simply do the following:

Yii::import('ext.Benchmark');
$bench = Benchmark::getInstance();

Sample output

Running log is clean, minimal and easy to grasp the idea of what's going on inside a script. In square brackets - elapsed time (in fractional seconds) of each operation. Timestamp appears just once at the top. Calculated summary in the form of [average op time] total_time / number of repetitions is at the bottom.

This is how the output looks:

 --- Benchmark testing ---
2012-06-24 17:06:31
[    0.0003] First operation
[    0.0211] Second operation 1
[    0.0002] First operation
[    0.0211] Second operation 2
[    0.0002] First operation
[    0.0211] Second operation 3
[    0.0002] First operation
[    0.0212] Second operation 4
[    0.0002] First operation
[    0.0212] Second operation 5
[    0.0002] Third operation of the 1 run
[    0.0002] Third operation of the 1 run
[    0.0002] Third operation of the 1 run
[    0.0002] Third operation of the 1 run
[    0.0002] Third operation of the 1 run
[    0.0002] Third operation of the 2 run
[    0.0002] Third operation of the 2 run
[    0.0002] Third operation of the 2 run
[    0.0002] Third operation of the 2 run
[    0.0002] Third operation of the 2 run

Benchmark testing totals:
memory: 8.85MB
peak  : 9.02MB
[    0.1120] Execution time
[    0.0002] 0.0011 / 5 First operation
[    0.0211] 0.1057 / 5 Second operation
[    0.0002] 0.0020 / 10 Third operation
--- kaput ---

Usage

The most important method is mark($description). Just use it everywhere you want to test something

Yii::import('ext.Benchmark');
$bench = Benchmark::getInstance();
 
$bench->mark('some operation');
// Do something interesting

It supports an optional second parameter, it will be appended to the description printed on the screen but not used in grouping in a summary section.

The second important method is cutoff(). It stops the mark and prints the message and execution time:

Yii::import('ext.Benchmark');
$bench = Benchmark::getInstance();
 
$bench->mark('some operation');
// Do something interesting
$bench->cutoff();

cutoff() method is optional, as it is called internally every time any other class method is called. Most of the time just mark() method is used, like so:

foreach ($files as $file)
{
    $bench->mark('reading file');
    // ...
    $bench->mark('processing file');
    // ...
    $bench->mark('saving file');
    // ...
    $bench->cutoff();
}

start($message) method prints out the message and the current timestamp. It ensures that summary will be printed at the end of the script even if kaput() is not called.

kaput() prints summary and clears log storage. Called automatically from the destructor, so no need to call explicitly.

logging in forked kids

The three class methods - lock_marks(), save($folder) and load(folder) - are all that is needed to support continuos logs and a single summary in case if some kids are forked.

lock_marks() is to be called right before pcntl_fork(...) to ensure single and accurate summary.

save($folder) is called at the end of each kid. To avoid intermediate summary (and to make sure that active database connection descriptor is not gone away and still available for the parent process) it is advisable to terminate a kid by calling posix_kill(getmypid(),9); and not use exit or return.

Parameter $folder - is any folder writable by the current process. This is where serialized marks will be saved ('/tmp' usually works just fine).

load($folder) merges all intermediate serialized kids 'marks' into the current process. Always called by the parent after it ensures that all kids are gone (after pcntl_waitpid).

Have a look at BenchmarkTest.php to see a usage example.

Saving log to a file

It is easily done in UNIX:

./yiic somecommand 2>&1 | tee logs/current.log

This way the log is printed on the screen as well as saved in a file for future reference.

Feature requests

  1. Provide configuration options
  2. Make the output somewhat more appealing
  3. Add 'error' messages type; they might be independently configured to be saved to a errors file.
  4. Add 'trace' messages - those are not benchmarked, just printed out preserving an output formatting (indentation and such).
  5. Summary injected to HTML if run from a browser (?)
  6. Add support for operations grouping

Resources

Total 2 comments

#8788 report it
Nick Makarov at 2012/06/26 04:07pm
A built-in logging system has quite a few issues
  1. CProfileLogRoute extends CWebLogRoute. That means it can't be used in a console application as is.

  2. It is possible to make something on top of the CFileLogRoute class, but it is quite cumbersome to use, too many extra steps to make it work:

// in config:
'preload'=>array('log')
 
// in app:
Yii::getLogger()->autoFlush = 1;
Yii::getLogger()->autoDump = true;

and then a whole config section in 'components'.

These are non-trivial, many people had difficulties figuring out how to use default logging, for example, here and here. Too much hassle for a simple problem.

3.The output is ugly, considering the following log snapshot:

2012/06/26 12:55:51 [info] [application] sleeping 10
2012/06/26 12:55:52 [profile] [application] end:mark 1
2012/06/26 12:55:52 [warning] [test] warning

I do not want to see the full date and timestamp for every line. Useful info for me is a timestamp when the important operation starts, duration of every operation with a description and totals at the end.

So it was much easier to come up with something totally new rather then adopt one of the built-in routes.

Besides, my Benchmark logger supports some extra features, like continuous logging in multi-process apps (forking kids, merging back etc.).

#8784 report it
redguy at 2012/06/26 11:58am
why extension, when Yii has built-in profiler?

You just place markers in your code:

Yii::beginProfile( 'mark 1' );
..... code
Yii::endProfile( 'mark 1' );

and use CProfileLogRoute:

array( 'class'=>'CProfileLogRoute', 'report'=>'summary' ),

doesn't it do pretty same? oh - and it works in HTML :)

Leave a comment

Please to leave your comment.

Create extension