MGBenchmark

Introduction

Easily measure code execution times. This is especially interesting for load operations that are difficult to profile with Instruments.

Features

Measure total execution times
Measure individual steps of execution
Find steps that take longest
Get the average execution time of all steps
Have multiple benchmark sessions at the same time
Use macros for easy usage
Implement custom output targets
Measure times across different threads (thread-safe)

Installation via CocoaPods

Install CocoaPods. See http://cocoapods.org
Add the MGBenchmark reference to the Podfile:

    platform :ios
    	pod 'MGBenchmark'
    end

Run pod install from the command line
Open the newly created Xcode Workspace file
Implement your commands

Quick Guide

The quickest way is to use the provided macros. They give you the basic console log functionality with very little code. The benchmark will only work when MGBENCHMARK is set, this is done by default, when DEBUG is set.

#import "MGBenchmark.h"

MGBenchStart(@"Test");

// code to measure

MGBenchStep(@"Test", @"1"); // << BENCHMARK [Test/1] 0.01s (step 1) >>

// code to measure

MGBenchStep(@"Test", @"2"); // << BENCHMARK [Test/2] 0.01s (step 2) >>
MGBenchEnd(@"Test"); // << BENCHMARK [Test/total] 0.02s (2 steps, average 0.01s) >>

That's it. For most cases that should be enough. However if you want to customize the output that's possible as well.

Using Class Methods

The aforementioned macros use the following class methods under the hood:

[MGBenchmark start:@"demo"]; // start measuring

// code to measure

[[MGBenchmark session:@"demo"] step:@"1"]; // << BENCHMARK [demo/1] 0.01s (step 1) >>

// code to measure

[[MGBenchmark session:@"demo"] step:@"2"]; // << BENCHMARK [demo/2] 0.01s (step 2) >>
[[MGBenchmark session:@"demo"] total]; // << BENCHMARK [demo/total] 0.02s (2 steps, average 0.01s) >>

[MGBenchmark finish:@"demo"]; // garbage collect

Nevertheless [MGBenchmark start:@"foo"] returns an instance as well:

MGBenchmarkSession *session = [MGBenchmark start:@"demo"];

[session step:@"1"];
[session step:@"2"];
[session total];

[MGBenchmark finish:@"demo"]; // garbage collect

Live Environment

You can keep the benchmark code integrated even in the live environment. But rather then logging to the console, you should send the results to a tracking database. Or set the target to nil to ignore the results.

#if DEBUG
[MGBenchmark setDefaultTarget:[[MGConsoleOutput alloc] init]]; // log to console
#elif RELEASE
[MGBenchmark setDefaultTarget:[[FlurryTarget alloc] init]]; // send to server
#else
[MGBenchmark setDefaultTarget:nil]; // ignore results
#endif

Customizing the Logs

There are different ways to customize the benchmark results:

Directly use the results
Customize the default target
Choose another pre-defined target
Implement your own output target

Using Results Directly

You can easily create your own console logs. For that you should disable the default console output:

[MGBenchmark setDefaultTarget:nil];

Then you can use the return values of step: and total to do your custom logging:

MGBenchmarkSession *benchmark = [MGBenchmark start:@"custom"];

// code to measure

NSLog(@"%.2fs", [benchmark step:@"sleep1"]); // 1.01s

// code to measure

NSLog(@"%.2fs", [benchmark step:@"sleep2"]); // 2.01s

You can also access the amount of steps as well as the average execution times:

NSLog(@"%.2fs (steps: %d | average: %d)", [benchmark total], benchmark.stepCount, benchmark.averageTime); // 3.03s (steps: 2 | average: 2.02s)

Customize the Default Target MGConsoleOutput

The provided console target is very customizable. You can configure the output by providing strings containing placeholders. The available placeholders differ for the step: and total benchmark:

Step

${sessionName}
${stepName}
${passedTime}
${stepCount}

Total

${sessionName}
${passedTime}
${stepCount}
${averageTime}

You can also change the measured time format. By changing the multiplier you can get measured times in milliseconds for example:

MGConsoleOutput *output = [[MGConsoleOutput alloc] init];
output.timeMultiplier = 1000; // to get ms rather than seconds
output.timeFormat = @"%.3fms"; // with 3 digits after comma
output.stepFormat = @"${stepName}: ${passedTime}";
output.totalFormat = @"total: ${passedTime}";

[MGBenchmark setDefaultTarget:output];

id session = [MGBenchmark start:@"demo"];
[session step:@"step1"]; 	// step1: 0.004ms
[session step:@"step2"]; 	// step2: 0.320ms
[session step:@"step3"]; 	// step3: 0.298ms
[session total]; 			// total: 0.884ms
[MGBenchmark finish:@"demo"];

MGConsoleSummaryOutput

Use this target to find steps that take longest. When using the total method it will print out all individual steps ordered by time.

Using...

[MGBenchmark setDefaultTarget:[[MGConsoleSummaryOutput alloc] init]];

... will result in these logs:

<< BENCHMARK [demo/total] 4.00138s (3 steps, average 1.33379s) >>
<< BENCHMARK 2.00084s (50.0%) step2 >>                           
<< BENCHMARK 1.00039s (25.0%) step1 >>                           
<< BENCHMARK 1.00010s (25.0%) step3 >>

You can customize this target as well (see the example code).

Custom Output Target

If you want to use a different output format, the best way is to define a custom target. For that you need to implement the MGBenchmarkTarget protocol. It declares 3 methods which are all optional:

passedTime:forStep:inSession – called for step time benchmark
totalTime:inSession – called for total time benchmark

Here is an example that sends the total benchmark to Flurry. Note that you need to initialize Flurry beforehand.

@interface FlurryTarget : NSObject <MGBenchmarkTarget>
@end

@implementation FlurryTarget

- (void)totalTime:(NSTimeInterval)passedTime inSession:(MGBenchmarkSession*)session
{
	[Flurry logEvent:session.name withParameters:@{
		@"totalTime": [NSString stringWithFormat:@"%.5fs", passedTime],
		@"steps": @(session.stepCount),
		@"averageStepTime": [NSString stringWithFormat:@"%.5fs", session.averageTime]
	}];
}

@end

Use your custom output target:

// set the default output for all sessions
[MGBenchmark setDefaultTarget:[[FlurryTarget alloc] init]]];

Changelog

0.3.0 (2014/01/17)

[NEW] Macros for easier usage (Thanks Nano)
[CHANGED] Simplified output target session handling (no need to store session)

0.2.0 (2013/03/28)

[NEW] MGBenchmark is now thread-safe
[NEW] MGBenchmarkTarget protocol methods are optional now
[NEW] MGConsoleSummaryOutput for sorted step times (what takes longest?)

0.1.1 (2013/03/24)

[BUGFIX] More fault-tolerant (doesn't use NSAssert anymore)

0.1.0 (2013/03/24)

[NEW] Measure total execution times
[NEW] Measure individual steps of execution
[NEW] Get the average execution time of all steps
[NEW] Have multiple benchmark sessions at the same time
[NEW] Implement custom output targets

Contribution

This library is released under the MIT licence. Contributions are more than welcome!

Also, follow me on Twitter if you like: @MattesGroeger.

MattesGroeger/MGBenchmark