// // PerformanceTesting.m // Benchmarking // // CocoaLumberjack Demos // #import "PerformanceTesting.h" #import #import "BaseNSLogging.h" #import "StaticLogging.h" #import "DynamicLogging.h" // Define the number of times each test is performed. // Due to various factors, the execution time of each test run may vary quite a bit. // Each test should be executed several times in order to arrive at a stable average. #define NUMBER_OF_RUNS 20 /** * The idea behind the benchmark tests is simple: * How does the logging framework compare to basic NSLog statements? * * However, due to the complexity of the logging framework and its various configuration options, * it is more complicated than a single test. Thus the testing is broken up as follows: * * - 3 Suites, each representing a different configuration of the logging framework * - 5 Tests, run within each suite. * * The suites are described below in the configureLoggingForSuiteX methods. * The tests are described in the various logging files, such as StaticLogging or DynamicLogging. * Notice that these file are almost exactly the same. * * BaseNSLogging defines the log methods to use NSLog (the base we are comparing against). * StaticLogging uses a 'const' log level, meaning the compiler will prune log statements (in release mode). * DynamicLogging use a non-const log level, meaning each log statement will incur an integer comparison penalty. **/ @implementation PerformanceTesting static NSTimeInterval base[5][3]; // [test][min,avg,max] static NSTimeInterval fmwk[3][2][5][3]; // [suite][file][test][min,avg,max] static DDFileLogger *fileLogger = nil; + (void)initialize { bzero(&base, sizeof(base)); bzero(&fmwk, sizeof(fmwk)); } + (DDFileLogger *)fileLogger { if (fileLogger == nil) { fileLogger = [[DDFileLogger alloc] init]; fileLogger.maximumFileSize = (1024 * 1024 * 1); // 1 MB fileLogger.rollingFrequency = (60 * 60 * 24); // 24 Hours fileLogger.logFileManager.maximumNumberOfLogFiles = 4; } return fileLogger; } /** * Suite 1 - Logging to Console only. **/ + (void)configureLoggingForSuite1 { [DDLog removeAllLoggers]; [DDLog addLogger:[DDASLLogger sharedInstance]]; [DDLog addLogger:[DDTTYLogger sharedInstance]]; } /** * Suite 2 - Logging to File only. * * We attempt to configure the logging so it will be forced to roll the log files during the test. * Rolling the log files requires creating and opening a new file. * This could be a performance hit, so we want our benchmark to take this into account. **/ + (void)configureLoggingForSuite2 { [DDLog removeAllLoggers]; [DDLog addLogger:[self fileLogger]]; } /** * Suite 3 - Logging to Console & File. **/ + (void)configureLoggingForSuite3 { [DDLog removeAllLoggers]; [DDLog addLogger:[DDASLLogger sharedInstance]]; [DDLog addLogger:[DDTTYLogger sharedInstance]]; [DDLog addLogger:[self fileLogger]]; } + (void)executeTestsWithBase:(BOOL)exeBase framework:(BOOL)exeFramework frameworkSuite:(int)suiteNum { if (!exeBase && !exeFramework) return; int sn = suiteNum - 1; // Zero-indexed for array int i, j, k; int start = exeBase ? 0 : 1; int finish = exeFramework ? 3 : 1; for (i = start; i < finish; i++) { Class class; switch (i) { case 0 : class = [BaseNSLogging class]; break; case 1 : class = [StaticLogging class]; break; default : class = [DynamicLogging class]; break; } for (j = 0; j < 5; j++) { NSTimeInterval min = DBL_MAX; NSTimeInterval max = DBL_MIN; NSTimeInterval total = 0.0; for (k = 0; k < NUMBER_OF_RUNS; k++) { @autoreleasepool { NSDate *start = [NSDate date]; switch (j) { case 0 : [class performSelector:@selector(speedTest0)]; break; case 1 : [class performSelector:@selector(speedTest1)]; break; case 2 : [class performSelector:@selector(speedTest2)]; break; case 3 : [class performSelector:@selector(speedTest3)]; break; default : [class performSelector:@selector(speedTest4)]; break; } NSTimeInterval result = [start timeIntervalSinceNow] * -1.0; min = MIN(min, result); max = MAX(max, result); total += result; } [DDLog flushLog]; } if (i == 0) { // Base base[j][0] = min; base[j][1] = total / (double)NUMBER_OF_RUNS; base[j][2] = max; } else { // Framework fmwk[sn][i-1][j][0] = min; fmwk[sn][i-1][j][1] = total / (double)NUMBER_OF_RUNS; fmwk[sn][i-1][j][2] = max; } } } } + (NSString *)printableResultsForSuite:(int)suiteNum { int sn = suiteNum - 1; // Zero-indexed for array NSMutableString *str = [NSMutableString stringWithCapacity:2000]; [str appendFormat:@"Results are given as [min][avg][max] calculated over the course of %i runs.", NUMBER_OF_RUNS]; [str appendString:@"\n\n"]; [str appendString:@"Test 0:\n"]; [str appendFormat:@"Execute %i log statements.\n", SPEED_TEST_0_COUNT]; [str appendString:@"The log statement is above the log level threshold, and will not execute.\n"]; [str appendString:@"The StaticLogging class will compile it out (in release mode).\n"]; [str appendString:@"The DynamicLogging class will require a single integer comparison.\n"]; [str appendString:@"\n"]; [str appendFormat:@"BaseNSLogging :[%.4f][%.4f][%.4f]\n", base[0][0], base[0][1], base[0][2]]; [str appendFormat:@"StaticLogging :[%.4f][%.4f][%.4f]\n", fmwk[sn][0][0][0], fmwk[sn][0][0][1], fmwk[sn][0][0][2]]; [str appendFormat:@"DynamicLogging:[%.4f][%.4f][%.4f]\n", fmwk[sn][1][0][0], fmwk[sn][1][0][1], fmwk[sn][1][0][2]]; [str appendString:@"\n\n\n"]; [str appendString:@"Test 1:\n"]; [str appendFormat:@"Execute %i log statements.\n", SPEED_TEST_1_COUNT]; [str appendString:@"The log statement is at or below the log level threshold, and will execute.\n"]; [str appendString:@"The logging framework will execute the statements Asynchronously.\n"]; [str appendString:@"\n"]; [str appendFormat:@"BaseNSLogging :[%.4f][%.4f][%.4f]\n", base[1][0], base[1][1], base[1][2]]; [str appendFormat:@"StaticLogging :[%.4f][%.4f][%.4f]\n", fmwk[sn][0][1][0], fmwk[sn][0][1][1], fmwk[sn][0][1][2]]; [str appendFormat:@"DynamicLogging:[%.4f][%.4f][%.4f]\n", fmwk[sn][1][1][0], fmwk[sn][1][1][1], fmwk[sn][1][1][2]]; [str appendString:@"\n\n\n"]; [str appendString:@"Test 2:\n"]; [str appendFormat:@"Execute %i log statements.\n", SPEED_TEST_2_COUNT]; [str appendString:@"The log statement is at or below the log level threshold, and will execute.\n"]; [str appendString:@"The logging framework will execute the statements Synchronously.\n"]; [str appendString:@"\n"]; [str appendFormat:@"BaseNSLogging :[%.4f][%.4f][%.4f]\n", base[2][0], base[2][1], base[2][2]]; [str appendFormat:@"StaticLogging :[%.4f][%.4f][%.4f]\n", fmwk[sn][0][2][0], fmwk[sn][0][2][1], fmwk[sn][0][2][2]]; [str appendFormat:@"DynamicLogging:[%.4f][%.4f][%.4f]\n", fmwk[sn][1][2][0], fmwk[sn][1][2][1], fmwk[sn][1][2][2]]; [str appendString:@"\n\n\n"]; [str appendString:@"Test 3:"]; [str appendFormat:@"Execute %i log statements per level.\n", SPEED_TEST_3_COUNT]; [str appendString:@"This is designed to mimic what might happen in a regular application.\n"]; [str appendString:@"25% will be above log level threshold and will be filtered out.\n"]; [str appendString:@"50% will execute Asynchronously.\n"]; [str appendString:@"25% will execute Synchronously.\n"]; [str appendString:@"\n"]; [str appendFormat:@"BaseNSLogging :[%.4f][%.4f][%.4f]\n", base[3][0], base[3][1], base[3][2]]; [str appendFormat:@"StaticLogging :[%.4f][%.4f][%.4f]\n", fmwk[sn][0][3][0], fmwk[sn][0][3][1], fmwk[sn][0][3][2]]; [str appendFormat:@"DynamicLogging:[%.4f][%.4f][%.4f]\n", fmwk[sn][1][3][0], fmwk[sn][1][3][1], fmwk[sn][1][3][2]]; [str appendString:@"\n\n\n"]; float total = 0.0F; total += SPEED_TEST_4_VERBOSE_COUNT; total += SPEED_TEST_4_INFO_COUNT; total += SPEED_TEST_4_WARN_COUNT; total += SPEED_TEST_4_ERROR_COUNT; float verbose = (float)SPEED_TEST_4_VERBOSE_COUNT / total * 100.0F; float info = (float)SPEED_TEST_4_INFO_COUNT / total * 100.0F; float warn = (float)SPEED_TEST_4_WARN_COUNT / total * 100.0F; float error = (float)SPEED_TEST_4_ERROR_COUNT / total * 100.0F; [str appendString:@"Test 4:\n"]; [str appendString:@"Similar to test 3, designed to mimic a real application\n"]; [str appendFormat:@"Execute %i log statements in total.\n", (int)total]; [str appendFormat:@"%04.1f%% will be above log level threshold and will be filtered out.\n", verbose]; [str appendFormat:@"%04.1f%% will execute Asynchronously.\n", (info + warn)]; [str appendFormat:@"%04.1f%% will execute Synchronously.\n", error]; [str appendString:@"\n"]; [str appendFormat:@"BaseNSLogging :[%.4f][%.4f][%.4f]\n", base[4][0], base[4][1], base[4][2]]; [str appendFormat:@"StaticLogging :[%.4f][%.4f][%.4f]\n", fmwk[sn][0][4][0], fmwk[sn][0][4][1], fmwk[sn][0][4][2]]; [str appendFormat:@"DynamicLogging:[%.4f][%.4f][%.4f]\n", fmwk[sn][1][4][0], fmwk[sn][1][4][1], fmwk[sn][1][4][2]]; [str appendString:@"\n\n\n"]; return str; } + (NSString *)csvResults { NSMutableString *str = [NSMutableString stringWithCapacity:1000]; // What are we trying to do here? // // What we ultimately want is to compare the performance of the framework against the baseline. // This means we want to see the performance of the baseline for test 1, // and then right next to it we want to see the performance of the framework with each various configuration. // // So we want it to kinda look like this for Test 1: // // Base, [min], [avg], [max] // Suite 1 - Static, [min], [avg], [max] // Suite 1 - Dynamic, [min], [avg], [max] // Suite 2 - Static, [min], [avg], [max] // Suite 2 - Dynamic, [min], [avg], [max] // Suite 3 - Static, [min], [avg], [max] // Suite 3 - Dynamic, [min], [avg], [max] // // This will import into Excel just fine. // However, I couldn't get Excel to make a decent looking graph with the data. // Perhaps I'm just not familiar enough with Excel. // But I was able to download OmniGraphSketcher, // and figure out how to create an awesome looking graph in less than 15 minutes. // And thus OmniGraphSketcher wins for me. // The only catch is that it wants to import the data with numbers instead of names. // So I need to convert the output to look like this: // // 0, [min], [avg], [max] // 1, [min], [avg], [max] // 2, [min], [avg], [max] // 3, [min], [avg], [max] // 4, [min], [avg], [max] // 5, [min], [avg], [max] // 6, [min], [avg], [max] // // I can then import the data into OmniGraphSketcher, and rename the X-axis points. // static NSTimeInterval base[5][3]; // [test][min,avg,max] // // static NSTimeInterval fmwk[3][2][5][3]; // [suite][file][test][min,avg,max] int row = 0; int suite, file, test; for (test = 0; test < 5; test++) { [str appendFormat:@"%i, %.4f, %.4f, %.4f\n", row++, base[test][0], base[test][1], base[test][2]]; for (suite = 0; suite < 3; suite++) { for (file = 0; file < 2; file++) { [str appendFormat:@"%i, %.4f, %.4f, %.4f\n", row++, fmwk[suite][file][test][0], fmwk[suite][file][test][1], fmwk[suite][file][test][2]]; } } row += 3; } return str; } + (void)startPerformanceTests { BOOL runBase = YES; BOOL runSuite1 = YES; BOOL runSuite2 = YES; BOOL runSuite3 = YES; if (!runBase && !runSuite1 && !runSuite2 && !runSuite3) { // Nothing to do, all suites disabled return; } NSLog(@"Preparing to start performance tests..."); NSLog(@"The results will be printed nicely when all logging has completed.\n\n"); [NSThread sleepForTimeInterval:3.0]; if (runBase) { [self executeTestsWithBase:YES framework:NO frameworkSuite:0]; } NSString *printableResults1 = nil; NSString *printableResults2 = nil; NSString *printableResults3 = nil; if (runSuite1) { [self configureLoggingForSuite1]; [self executeTestsWithBase:NO framework:YES frameworkSuite:1]; printableResults1 = [self printableResultsForSuite:1]; NSLog(@"\n\n\n\n"); } if (runSuite2) { [self configureLoggingForSuite2]; [self executeTestsWithBase:NO framework:YES frameworkSuite:2]; printableResults2 = [self printableResultsForSuite:2]; NSLog(@"\n\n\n\n"); } if (runSuite3) { [self configureLoggingForSuite3]; [self executeTestsWithBase:NO framework:YES frameworkSuite:3]; printableResults3 = [self printableResultsForSuite:3]; NSLog(@"\n\n\n\n"); } if (runSuite1) { NSLog(@"======================================================================"); NSLog(@"Benchmark Suite 1:"); NSLog(@"Logging framework configured to log to console only."); NSLog(@"\n\n%@", printableResults1); NSLog(@"======================================================================"); } if (runSuite2) { NSLog(@"======================================================================"); NSLog(@"Benchmark Suite 2:"); NSLog(@"Logging framework configured to log to file only."); NSLog(@"\n\n%@", printableResults2); NSLog(@"======================================================================"); } if (runSuite3) { NSLog(@"======================================================================"); NSLog(@"Benchmark Suite 3:"); NSLog(@"Logging framework configured to log to console & file."); NSLog(@"\n\n%@", printableResults3); NSLog(@"======================================================================"); } #if TARGET_OS_IPHONE NSString *csvResultsPath = [@"~/Documents/LumberjackBenchmark.csv" stringByExpandingTildeInPath]; #else NSString *csvResultsPath = [@"~/Desktop/LumberjackBenchmark.csv" stringByExpandingTildeInPath]; #endif if (![[NSFileManager defaultManager] fileExistsAtPath:csvResultsPath]) { [[NSFileManager defaultManager] createFileAtPath:csvResultsPath contents:nil attributes:nil]; } NSFileHandle *csvResultsFile = [NSFileHandle fileHandleForWritingAtPath:csvResultsPath]; NSString *csvResults = [self csvResults]; [csvResultsFile writeData:[csvResults dataUsingEncoding:NSUTF8StringEncoding]]; NSLog(@"CSV results file written to:\n%@", csvResultsPath); } @end