| #import "PerformanceTesting.h" |
| #import "DDLog.h" |
| #import "DDASLLogger.h" |
| #import "DDTTYLogger.h" |
| #import "DDFileLogger.h" |
| |
| |
| #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 *csvRsults = [self csvResults]; |
| [csvResultsFile writeData:[csvRsults dataUsingEncoding:NSUTF8StringEncoding]]; |
| |
| NSLog(@"CSV results file written to:\n%@", csvResultsPath); |
| } |
| |
| @end |