Spent several hours worrying about the need to deep copy data before async cache flush and the performance implications of doing so, then realised there was no reason that would be necessary. Currently back to async flushing without deep copy, and profiling code. The profiling timer implementation for Windows is untested and may be broken. Also, fixed a nasty bug in OODeepCopy() where empty dictionaries ere turned into sets.

git-svn-id: http://svn.berlios.de/svnroot/repos/oolite-linux/trunk@2541 127b21dd-08f5-0310-b4b7-95ae10353056
2009-09-20 14:02:55 +00:00 · 2009-09-20 14:02:55 +00:00 · ec4aa91753
commit ec4aa91753
parent 2ba2b6f213
8 changed files with 296 additions and 18 deletions
--- a/1
+++ b/1
@ -77,6 +77,7 @@ OOLITE_DEBUG_FILES = \
 	OODebugSupport.m \
 	OODebugTCPConsoleClient.m \
 	OOJSConsole.m \
+	OOProfilingStopwatch.m \
 	OOTCPStreamDecoderAbstractionLayer.m

 OOLITE_ENTITY_FILES = \
--- a/Oolite.xcodeproj/project.pbxproj
+++ b/Oolite.xcodeproj/project.pbxproj
@ -29,6 +29,8 @@
 		0865431C06B8447D000CA0AB /* Cocoa.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = 1058C7A1FEA54F0111CA2CBB /* Cocoa.framework */; };
 		0865431D06B8447D000CA0AB /* OpenGL.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = 06AFA01500A58FB77F000001 /* OpenGL.framework */; };
 		0878FD30086EF845004CB752 /* Carbon.framework in Frameworks */ = {isa = PBXBuildFile; fileRef = 0878FD2F086EF845004CB752 /* Carbon.framework */; };
+		1A00C65510663D3700A8737D /* OOProfilingStopwatch.h in Headers */ = {isa = PBXBuildFile; fileRef = 1A00C65310663D3700A8737D /* OOProfilingStopwatch.h */; };
+		1A00C65610663D3700A8737D /* OOProfilingStopwatch.m in Sources */ = {isa = PBXBuildFile; fileRef = 1A00C65410663D3700A8737D /* OOProfilingStopwatch.m */; };
 		1A020E0B0D020AFB00C3F51E /* changedScriptHandlers.plist in Copy Config */ = {isa = PBXBuildFile; fileRef = 1A020E0A0D020AFB00C3F51E /* changedScriptHandlers.plist */; };
 		1A02FD460EE0490B008F9B09 /* oolite-tangent-space-vertex.vertex in Copy Shaders */ = {isa = PBXBuildFile; fileRef = 1A02FD340EE048E8008F9B09 /* oolite-tangent-space-vertex.vertex */; };
 		1A0365890D7CA05000B5F46F /* OOSkyDrawable.m in Sources */ = {isa = PBXBuildFile; fileRef = 1A15044A0C12C50D0032F3E8 /* OOSkyDrawable.m */; };
@ -1086,6 +1088,8 @@
 		0865432206B8447D000CA0AB /* Oolite.app */ = {isa = PBXFileReference; explicitFileType = wrapper.application; includeInIndex = 0; path = Oolite.app; sourceTree = BUILT_PRODUCTS_DIR; };
 		0878FD2F086EF845004CB752 /* Carbon.framework */ = {isa = PBXFileReference; lastKnownFileType = wrapper.framework; name = Carbon.framework; path = /System/Library/Frameworks/Carbon.framework; sourceTree = "<absolute>"; };
 		1058C7A1FEA54F0111CA2CBB /* Cocoa.framework */ = {isa = PBXFileReference; lastKnownFileType = wrapper.framework; name = Cocoa.framework; path = /System/Library/Frameworks/Cocoa.framework; sourceTree = "<absolute>"; };
+		1A00C65310663D3700A8737D /* OOProfilingStopwatch.h */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.h; path = OOProfilingStopwatch.h; sourceTree = "<group>"; };
+		1A00C65410663D3700A8737D /* OOProfilingStopwatch.m */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = sourcecode.c.objc; path = OOProfilingStopwatch.m; sourceTree = "<group>"; };
 		1A020E0A0D020AFB00C3F51E /* changedScriptHandlers.plist */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = text.plist; path = changedScriptHandlers.plist; sourceTree = "<group>"; };
 		1A02FD340EE048E8008F9B09 /* oolite-tangent-space-vertex.vertex */ = {isa = PBXFileReference; fileEncoding = 4; lastKnownFileType = text; path = "oolite-tangent-space-vertex.vertex"; sourceTree = "<group>"; };
 		1A0365990D7CA0EE00B5F46F /* oolite-nebula-4.png */ = {isa = PBXFileReference; lastKnownFileType = image.png; path = "oolite-nebula-4.png"; sourceTree = "<group>"; };
@ -2568,6 +2572,8 @@
 				1ADA8AB10F42DBA80001BEC9 /* OODeepCopy.h */,
 				1ADA8AB20F42DBA80001BEC9 /* OODeepCopy.m */,
 				1A43F28A105170A8003FDE8B /* OONSOperation.h */,
+				1A00C65310663D3700A8737D /* OOProfilingStopwatch.h */,
+				1A00C65410663D3700A8737D /* OOProfilingStopwatch.m */,
 			);
 			name = Utilities;
 			sourceTree = "<group>";
@ -3058,6 +3064,7 @@
 				1A1F2842105AAB7900ADB8C5 /* OOSparkEntity.h in Headers */,
 				1A3BA259106555D100C5C6F3 /* NSNumberOOExtensions.h in Headers */,
 				1AB987B61065842700AF9B0A /* OOAsyncWorkManager.h in Headers */,
+				1A00C65510663D3700A8737D /* OOProfilingStopwatch.h in Headers */,
 			);
 			runOnlyForDeploymentPostprocessing = 0;
 		};
@ -3403,6 +3410,7 @@
 				1A1F2843105AAB7900ADB8C5 /* OOSparkEntity.m in Sources */,
 				1A3BA25A106555D100C5C6F3 /* NSNumberOOExtensions.m in Sources */,
 				1AB987B71065842700AF9B0A /* OOAsyncWorkManager.m in Sources */,
+				1A00C65610663D3700A8737D /* OOProfilingStopwatch.m in Sources */,
 			);
 			runOnlyForDeploymentPostprocessing = 0;
 		};
--- a/src/Core/GameController.m
+++ b/src/Core/GameController.m
@ -898,7 +898,7 @@ static NSComparisonResult CompareDisplayModes(id arg1, id arg2, void *context)

 - (NSApplicationTerminateReply)applicationShouldTerminate:(NSApplication *)sender
 {
-	[[OOCacheManager sharedCache] flushSynchronously];
+	[[OOCacheManager sharedCache] finishOngoingFlush];
 	OOLoggingTerminate();
 	return NSTerminateNow;
 }
--- a/src/Core/OOCacheManager.h
+++ b/src/Core/OOCacheManager.h
@ -69,6 +69,6 @@ enum
 - (void)setAllowCacheWrites:(BOOL)flag;

 - (void)flush;
- (void)flushSynchronously;
+- (void)finishOngoingFlush;	// Wait for flush to complete. Does nothing if async flushing is disabled.

@end
--- a/src/Core/OOCacheManager.m
+++ b/src/Core/OOCacheManager.m
@ -25,11 +25,14 @@ MA 02110-1301, USA.
 #import "OOCacheManager.h"
 #import "OOCache.h"
 #import "OOPListParsing.h"
-#import "OOAsyncWorkManager.h"
+#import "OODeepCopy.h"


 #define AUTO_PRUNE				0
 #define PRUNE_BEFORE_FLUSH		0
+#define WRITE_ASYNC				1
+#define WRITE_ASYNC_DEEP_COPY	0
+#define PROFILE_WRITES			1


 // Use the (presumed) most efficient plist format for each platform.
@ -40,6 +43,14 @@ MA 02110-1301, USA.
 #endif


+#if WRITE_ASYNC
+#import "OOAsyncWorkManager.h"
+#endif
+#if PROFILE_WRITES
+#import "OOProfilingStopwatch.h"
+#endif
+
+
 static NSString * const kOOLogDataCacheFound				= @"dataCache.found";
 static NSString * const kOOLogDataCacheNotFound				= @"dataCache.notFound";
 static NSString * const kOOLogDataCacheRebuild				= @"dataCache.rebuild";
@ -55,7 +66,7 @@ static NSString * const kOOLogDataCacheParamError			= @"general.error.parameterE
 static NSString * const kOOLogDataCacheBuildPathError		= @"dataCache.write.buildPath.failed";
 static NSString * const kOOLogDataCacheSerializationError	= @"dataCache.write.serialize.failed";

-static NSString * const kCacheKeyVersion					= @"CFBundleVersion";	// Legacy name
+static NSString * const kCacheKeyVersion					= @"version";
 static NSString * const kCacheKeyEndianTag					= @"endian tag";
 static NSString * const kCacheKeyFormatVersion				= @"format version";
 static NSString * const kCacheKeyCaches						= @"caches";
@ -64,7 +75,7 @@ static NSString * const kCacheKeyCaches						= @"caches";
 enum
 {
 	kEndianTagValue			= 0x0123456789ABCDEFULL,
-	kFormatVersionValue		= 31
+	kFormatVersionValue		= 32
 };


@ -97,6 +108,7 @@ static OOCacheManager *sSingleton = nil;
@end


+#if WRITE_ASYNC
@interface OOAsyncCacheWriter: NSObject <OOAsyncWorkTask>
 {
@private
@ -106,6 +118,7 @@ static OOCacheManager *sSingleton = nil;
 - (id) initWithCacheContents:(NSDictionary *)cacheContents;

@end
+#endif


@implementation OOCacheManager
@ -301,14 +314,11 @@ static OOCacheManager *sSingleton = nil;
 }


- (void)flushSynchronously
+- (void)finishOngoingFlush
 {
-	if (_permitWrites && [self dirty])
-	{
-		[self write];
-		[self markClean];
-		[[OOAsyncWorkManager sharedAsyncWorkManager] waitForTaskToComplete:_scheduledWrite];
-	}
+#if WRITE_ASYNC
+	[[OOAsyncWorkManager sharedAsyncWorkManager] waitForTaskToComplete:_scheduledWrite];
+#endif
 }


@ -332,7 +342,7 @@ static OOCacheManager *sSingleton = nil;
 	BOOL					accept = YES;
 	uint64_t				endianTagValue = 0;
 	
-	ooliteVersion = [[[NSBundle mainBundle] infoDictionary] objectForKey:kCacheKeyVersion];
+	ooliteVersion = [[[NSBundle mainBundle] infoDictionary] objectForKey:@"CFBundleVersion"];
 	
 	[self clear];
 	
@ -407,12 +417,22 @@ static OOCacheManager *sSingleton = nil;
 	if (_caches == nil) return;
 	if (_scheduledWrite != nil)  return;
 	
+#if PROFILE_WRITES
+	OOProfilingStopwatch *stopwatch = [[OOProfilingStopwatch alloc] init];
+	[stopwatch start];
+#endif
+	
+#if WRITE_ASYNC
+	OOLog(@"dataCache.willWrite", @"Scheduling data cache write.");
+#else
+	OOLog(@"dataCache.willWrite", @"About to write cache.");
+#endif
+	
 #if PRUNE_BEFORE_FLUSH
 	[[_caches allValues] makeObjectsPerformSelector:@selector(prune)];
 #endif
 	
-	OOLog(@"dataCache.willWrite", @"Scheduling data cache write.");	// Added for 1.69 to detect possible write-related crash. -- Ahruman
-	ooliteVersion = [[[NSBundle mainBundle] infoDictionary] objectForKey:kCacheKeyVersion];
+	ooliteVersion = [[[NSBundle mainBundle] infoDictionary] objectForKey:@"CFBundleVersion"];
 	endianTag = [NSData dataWithBytes:&endianTagValue length:sizeof endianTagValue];
 	formatVersion = [NSNumber numberWithUnsignedInt:kFormatVersionValue];
 	
@ -429,8 +449,45 @@ static OOCacheManager *sSingleton = nil;
 	[newCache setObject:endianTag forKey:kCacheKeyEndianTag];
 	[newCache setObject:pListRep forKey:kCacheKeyCaches];
 	
-	_scheduledWrite = [[OOAsyncCacheWriter alloc] initWithCacheContents:newCache];
+#if PROFILE_WRITES && (!WRITE_ASYNC || WRITE_ASYNC_DEEP_COPY)
+	OOTimeDelta prepareT = [stopwatch reset];
+#endif
+	
+#if WRITE_ASYNC
+	NSDictionary *cacheData = newCache;
+#if WRITE_ASYNC_DEEP_COPY
+	// This shouldn't be necessary, and if used slows async flushing down to slower than sync flushing.
+	cacheData = [OODeepCopy(cacheData) autorelease];
+#endif
+	_scheduledWrite = [[OOAsyncCacheWriter alloc] initWithCacheContents:cacheData];
+	
+#if PROFILE_WRITES
+	OOTimeDelta endT = [stopwatch reset];
+#if WRITE_ASYNC_DEEP_COPY
+	OOLog(@"cache.profile", @"Time to prepare cache data: %g seconds; time to deep copy and set up async writer, %g seconds.", prepareT, endT);
+#else
+	OOLog(@"cache.profile", @"Time to prepare cache data: %g seconds.", endT);
+#endif
+	[stopwatch release];
+#endif
+	
 	[[OOAsyncWorkManager sharedAsyncWorkManager] addTask:_scheduledWrite priority:kOOAsyncPriorityLow];
+#else
+#if PROFILE_WRITES
+	[stopwatch release];
+	OOLog(@"cache.profile", @"Time to prepare cache data: %g seconds.", prepareT);
+#endif
+	
+	if ([self writeDict:newCache])
+	{
+		[self markClean];
+		OOLog(kOOLogDataCacheWriteSuccess, @"Wrote data cache.");
+	}
+	else
+	{
+		OOLog(kOOLogDataCacheWriteFailed, @"Failed to write data cache.");
+	}
+#endif
 }


@ -512,6 +569,11 @@ static OOCacheManager *sSingleton = nil;
 	path = [self cachePathCreatingIfNecessary:YES];
 	if (path == nil) return NO;	
 	
+#if PROFILE_WRITES
+	OOProfilingStopwatch *stopwatch = [[OOProfilingStopwatch alloc] init];
+	[stopwatch start];
+#endif
+	
 	plist = [NSPropertyListSerialization dataFromPropertyList:inDict format:CACHE_PLIST_FORMAT errorDescription:&errorDesc];
 	if (plist == nil)
 	{
@ -522,8 +584,22 @@ static OOCacheManager *sSingleton = nil;
 		return NO;
 	}
 	
+#if PROFILE_WRITES
+	OOTimeDelta serializeT = [stopwatch reset];
+#endif
+	
 	BOOL result = [plist writeToFile:path atomically:NO];
+	
+#if PROFILE_WRITES
+	OOTimeDelta writeT = [stopwatch reset];
+	[stopwatch release];
+	
+	OOLog(@"cache.profile", @"Time to serialize cache: %g seconds. Time to write data: %g seconds.", serializeT, writeT);
+#endif
+	
+#if WRITE_ASYNC
 	DESTROY(_scheduledWrite);
+#endif
 	return result;
 }

@ -773,6 +849,7 @@ static OOCacheManager *sSingleton = nil;
 #endif


+#if WRITE_ASYNC
@implementation OOAsyncCacheWriter

 - (id) initWithCacheContents:(NSDictionary *)cacheContents
@ -819,3 +896,4 @@ static OOCacheManager *sSingleton = nil;
 }

@end
+#endif	// WRITE_ASYNC
--- a/src/Core/OODeepCopy.m
+++ b/src/Core/OODeepCopy.m
@ -88,7 +88,9 @@ id OODeepCopy(id object)

 - (id) ooDeepCopyWithSharedObjects:(NSMutableSet *)objects
 {
-	if ([self length] == 0)  return [[NSString string] retain];
+	OOUInteger length = [self length];
+	if (length == 0)  return [[NSString string] retain];
+	if (length > 128)  return [self copy];
 	
 	id object = [objects member:self];
 	if (object != nil && [object isKindOfClass:[NSString class]])
@ -271,7 +273,7 @@ id OODeepCopy(id object)
 	NSEnumerator			*keyEnum = nil;
 	
 	count = [self count];
-	if (count == 0)  return [[NSSet set] retain];
+	if (count == 0)  return [[NSDictionary dictionary] retain];
 	
 	keys = malloc(sizeof *keys * count);
 	values = malloc(sizeof *values * count);
--- a/src/Core/OOProfilingStopwatch.h
+++ b/src/Core/OOProfilingStopwatch.h
@ -0,0 +1,81 @@
+/*	OOProfilingStopwatch.h
+	Oolite
+	
+	Testing utility to monitor elapsed times at high precision.
+*/
+
+#import "OOCocoa.h"
+#import "OOFunctionAttributes.h"
+#import "OOTypes.h"
+
+
+/*	Platform-specific high-resolution timer:
+	
+	OOHighResTimeValue is a time value. This could be a scalar, struct or pointer.
+	OOHighResTimeValue OOGetHighResTime(void) returns the current time.
+	OODisposeHighResTime() destroys an existing OOHighResTimeValue, if necessary.
+	It must do nothing if the value passed is zeroed out.
+	OOCopyHighResTime(x) returns a timer value equal to x.
+	OOTimeDelta OOHighResTimeDeltaInSeconds(OOHighResTimeValue startTime, OOHighResTimeValue endTime)
+	returns the difference between two time values, in seconds.
+*/
+
+#if OOLITE_MAC_OS_X
+#define OO_PROFILING_STOPWATCH_MACH_ABSOLUTE_TIME 1
+#import <mach/mach_time.h>
+
+typedef uint64_t OOHighResTimeValue;
+
+#define OOGetHighResTime mach_absolute_time
+#define OODisposeHighResTime(time)  do { (void)time; } while (0)
+#define OOCopyHighResTime(time) ((OOHighResTimeValue)time)
+
+OOTimeDelta OOHighResTimeDeltaInSeconds(OOHighResTimeValue startTime, OOHighResTimeValue endTime);
+#elif OOLITE_WINDOWS
+#define OO_PROFILING_STOPWATCH_WINDOWS 1
+typedef DWORD OOHighResTimeValue;	// Rolls over once every 50 days, but we can live with that.
+
+#define OOGetHighResTime timeGetTime
+#define OODisposeHighResTime(time)  do { (void)time; } while (0)
+#define OOCopyHighResTime(time) ((OOHighResTimeValue)time)
+
+OOTimeDelta OOHighResTimeDeltaInSeconds(OOHighResTimeValue startTime, OOHighResTimeValue endTime);
+#else
+#define OO_PROFILING_STOPWATCH_GETTIMEOFDAY 1
+#import <sys/time.h>
+
+typedef struct timeval OOHighResTimeValue;
+
+OOINLINE OOHighResTimeValue OOGetHighResTime(void)
+{
+	struct timeval tv;
+	gettimeofday(&tv, NULL);
+	return tv;
+}
+
+#define OODisposeHighResTime(time)  do { (void)time; } while (0)
+#define OOCopyHighResTime(time) ((OOHighResTimeValue)time)
+
+OOTimeDelta OOHighResTimeDeltaInSeconds(OOHighResTimeValue startTime, OOHighResTimeValue endTime);
+#endif
+
+
+@interface OOProfilingStopwatch: NSObject
+{
+@private
+	OOHighResTimeValue	_start;
+	OOHighResTimeValue	_end;
+	BOOL				_running;
+}
+
+- (void) start;
+- (void) stop;
+- (OOTimeDelta) currentTime;	// Returns stop time - start time if stopped, or now - start time if running.
+
+/*	Resets timer to zero, returning the current value. This is drift-free, i.e.
+	if it is called twice in a row while running the sum is an accurate time
+	since the timer started.
+*/
+- (OOTimeDelta) reset;
+
+@end
--- a/src/Core/OOProfilingStopwatch.m
+++ b/src/Core/OOProfilingStopwatch.m
@ -0,0 +1,108 @@
+//
+//  OOProfilingStopwatch.m
+//  Oolite
+//
+//  Created by Jens Ayton on 2009-09-20.
+//  Copyright 2009 the Oolite team. All rights reserved.
+//
+
+#import "OOProfilingStopwatch.h"
+
+
+@implementation OOProfilingStopwatch
+
+- (void) dealloc
+{
+	OODisposeHighResTime(_start);
+	OODisposeHighResTime(_end);
+	
+	[super dealloc];
+}
+
+
+- (void) start
+{
+	OOHighResTimeValue temp = _start;
+	_start = OOGetHighResTime();
+	OODisposeHighResTime(temp);
+	_running = YES;
+}
+
+
+- (void) stop
+{
+	OOHighResTimeValue temp = _start;
+	_end = OOGetHighResTime();
+	OODisposeHighResTime(temp);
+	_running = NO;
+}
+
+
+- (OOTimeDelta) currentTime
+{
+	if (_running)
+	{
+		OOHighResTimeValue temp = _start;
+		_end = OOGetHighResTime();
+		OODisposeHighResTime(temp);
+	}
+	return OOHighResTimeDeltaInSeconds(_start, _end);
+}
+
+
+- (OOTimeDelta) reset
+{
+	OOTimeDelta result;
+	if (_running)
+	{
+		OOHighResTimeValue now = OOGetHighResTime();
+		result = OOHighResTimeDeltaInSeconds(_start, now);
+		OODisposeHighResTime(_start);
+		_start = now;
+	}
+	else
+	{
+		result = OOHighResTimeDeltaInSeconds(_start, _end);
+		OODisposeHighResTime(_end);
+		_end = OOCopyHighResTime(_start);
+	}
+	return result;
+}
+
+@end
+
+
+#if OO_PROFILING_STOPWATCH_MACH_ABSOLUTE_TIME
+OOTimeDelta OOHighResTimeDeltaInSeconds(OOHighResTimeValue startTime, OOHighResTimeValue endTime)
+{
+	uint64_t diff = endTime - startTime;
+	static double conversion = 0.0;
+	
+	if (EXPECT_NOT(conversion == 0.0))
+	{
+		mach_timebase_info_data_t info;
+		kern_return_t err = mach_timebase_info(&info);
+		
+		if (err == 0)
+		{
+			conversion = 1e-9 * (double)info.numer / (double)info.denom;
+		}
+	}
+	
+	return conversion * (double)diff;
+}
+#elif OO_PROFILING_STOPWATCH_WINDOWS
+OOTimeDelta OOHighResTimeDeltaInSeconds(OOHighResTimeValue startTime, OOHighResTimeValue endTime)
+{
+	return 1e-6 * (double)(endTime - startTime);
+}
+#elif OO_PROFILING_STOPWATCH_GETTIMEOFDAY
+OOTimeDelta OOHighResTimeDeltaInSeconds(OOHighResTimeValue startTime, OOHighResTimeValue endTime)
+{
+	int_fast32_t deltaS = (int_fast32_t)endTime.tv_sec - (int_fast32_t)startTime.tv_sec;
+	int_fast32_t deltaU = (int_fast32_t)endTime.tv_usec - (int_fast32_t)startTime.tv_usec;
+	double result = deltaU;
+	result = (result * 1e-6) + deltaS;
+	return result;
+}
+#endif