1. Idea and Concept
2. Configuration
3. Sample output
4. Usage
5. logging in forked kids
6. Saving log to a file
7. Feature requests
8. Resources

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 ¶

• Benchmark on GitHub