Fwd: non-linearly bad performance when encoding dictionaries?
-
> From: Alberto Ricart <aricart...>
> Date: July 25, 2005 11:27:27 PM CDT
> To: Michael B. Johnson <wave...>
> Subject: Re: non-linearly bad performance when encoding dictionaries?
>
>
> What version of OS X are you running?
> If I run your code as you posted, I get fairly linear performance.
>
> If you substitute all your [NSMutableX x], for [[NSMutableX
> allocWithZone:nil]init], and then bracketed with a [x release] when
> done using/or adding I can improve the performance by a tiny bit
> because you eliminate some messaging, but not enough to make any
> difference. I AM encoding different (unique objects):
>
> 2005-07-25 23:06:18.714 Performance[2207] took 0.10 seconds to
> encode 1000 objects
> 2005-07-25 23:06:18.903 Performance[2207] took 0.16 seconds to
> encode 2000 objects
> 2005-07-25 23:06:19.175 Performance[2207] took 0.23 seconds to
> encode 3000 objects
> 2005-07-25 23:06:19.553 Performance[2207] took 0.33 seconds to
> encode 4000 objects
> 2005-07-25 23:06:20.026 Performance[2207] took 0.41 seconds to
> encode 5000 objects
> 2005-07-25 23:06:20.654 Performance[2207] took 0.55 seconds to
> encode 6000 objects
> 2005-07-25 23:06:21.317 Performance[2207] took 0.58 seconds to
> encode 7000 objects
> 2005-07-25 23:06:22.062 Performance[2207] took 0.65 seconds to
> encode 8000 objects
> 2005-07-25 23:06:22.954 Performance[2207] took 0.77 seconds to
> encode 9000 objects
>
> for the same object, I get:
>
> 2005-07-25 23:13:30.145 Performance[2239] took 0.08 seconds to
> encode 1000 objects
> 2005-07-25 23:13:30.296 Performance[2239] took 0.13 seconds to
> encode 2000 objects
> 2005-07-25 23:13:30.520 Performance[2239] took 0.20 seconds to
> encode 3000 objects
> 2005-07-25 23:13:30.813 Performance[2239] took 0.27 seconds to
> encode 4000 objects
> 2005-07-25 23:13:31.186 Performance[2239] took 0.34 seconds to
> encode 5000 objects
> 2005-07-25 23:13:31.631 Performance[2239] took 0.41 seconds to
> encode 6000 objects
> 2005-07-25 23:13:32.155 Performance[2239] took 0.49 seconds to
> encode 7000 objects
> 2005-07-25 23:13:32.760 Performance[2239] took 0.56 seconds to
> encode 8000 objects
> 2005-07-25 23:13:33.449 Performance[2239] took 0.64 seconds to
> encode 9000 objects
>
>
> I am wondering if you are running into a memory issue where your
> machine is starting to page, and that is really the issue you are
> observing. Tweaking the initial size of the arrayk or dictionary
> doesn't really improve performance much. If you run shark on it,
> you find that 40% of the time is spent in the allocator, and
> growing the dictionary (when values are getting removed).
>
> I think you are running into OS X's slow memory allocation. BTW, I
> am running on a 1.67GHz G4, with 1.5GB of RAM.
>
>
> /a
>
> On Jul 25, 2005, at 2:58 PM, Michael B. Johnson wrote:
>
>
>> I'm assuming I'm doing something really stupid, and usually the
>> best way to find it is to write a little program to show someone.
>> Unfortunately, I've written the program, and I still don't see
>> what I'm doing wrong.
>>
>> I've got a class that has a mutable dictionary in it.
>> I have an array of N of these objects;
>>
>> The dictionary in each object has (say) a single entry with a
>> key. Note that it doesn't seem to matter much if that object is
>> the same or unique among the array of these objects.
>>
>> I have an array of these simple objects,
>> I put that array in a dictionary.
>> I then do an encodeWithCoder: on that dictionary using keyed
>> coding. The performance is pretty bad after about 1000 of them:
>>
>> 2005-07-25 12:30:12.211 EncodeBugCL[7252] took 0.48 seconds to
>> encode 1000 objects
>> 2005-07-25 12:30:14.562 EncodeBugCL[7252] took 2.34 seconds to
>> encode 2000 objects
>> 2005-07-25 12:30:18.632 EncodeBugCL[7252] took 4.05 seconds to
>> encode 3000 objects
>> 2005-07-25 12:30:27.431 EncodeBugCL[7252] took 8.76 seconds to
>> encode 4000 objects
>> 2005-07-25 12:30:47.366 EncodeBugCL[7252] took 19.89 seconds to
>> encode 5000 objects
>> 2005-07-25 12:31:10.564 EncodeBugCL[7252] took 23.14 seconds to
>> encode 6000 objects
>> 2005-07-25 12:31:38.528 EncodeBugCL[7252] took 27.90 seconds to
>> encode 7000 objects
>> 2005-07-25 12:32:35.041 EncodeBugCL[7252] took 56.43 seconds to
>> encode 8000 objects
>> 2005-07-25 12:33:42.335 EncodeBugCL[7252] took 67.20 seconds to
>> encode 9000 objects
>>
>> If the object is the same it looks better, but still bad:
>> 2005-07-25 12:39:28.485 EncodeBugCL[7287] took 0.49 seconds to
>> encode 1000 objects
>> 2005-07-25 12:39:30.246 EncodeBugCL[7287] took 1.75 seconds to
>> encode 2000 objects
>> 2005-07-25 12:39:34.952 EncodeBugCL[7287] took 4.68 seconds to
>> encode 3000 objects
>> 2005-07-25 12:39:46.002 EncodeBugCL[7287] took 11.01 seconds to
>> encode 4000 objects
>> 2005-07-25 12:39:59.725 EncodeBugCL[7287] took 13.69 seconds to
>> encode 5000 objects
>> 2005-07-25 12:40:18.462 EncodeBugCL[7287] took 18.66 seconds to
>> encode 6000 objects
>> 2005-07-25 12:40:52.035 EncodeBugCL[7287] took 33.51 seconds to
>> encode 7000 objects
>> 2005-07-25 12:41:30.208 EncodeBugCL[7287] took 38.10 seconds to
>> encode 8000 objects
>> 2005-07-25 12:42:14.975 EncodeBugCL[7287] took 44.69 seconds to
>> encode 9000 objects
>>
>> Just to be clear, if I don't add anything to the properties
>> dictionary, here's what it looks like:
>>
>> 2005-07-25 12:43:25.350 EncodeBugCL[7309] took 0.08 seconds to
>> encode 1000 objects
>> 2005-07-25 12:43:25.514 EncodeBugCL[7309] took 0.14 seconds to
>> encode 2000 objects
>> 2005-07-25 12:43:25.697 EncodeBugCL[7309] took 0.15 seconds to
>> encode 3000 objects
>> 2005-07-25 12:43:25.942 EncodeBugCL[7309] took 0.20 seconds to
>> encode 4000 objects
>> 2005-07-25 12:43:26.226 EncodeBugCL[7309] took 0.25 seconds to
>> encode 5000 objects
>> 2005-07-25 12:43:26.562 EncodeBugCL[7309] took 0.29 seconds to
>> encode 6000 objects
>> 2005-07-25 12:43:27.007 EncodeBugCL[7309] took 0.39 seconds to
>> encode 7000 objects
>> 2005-07-25 12:43:27.481 EncodeBugCL[7309] took 0.42 seconds to
>> encode 8000 objects
>> 2005-07-25 12:43:28.034 EncodeBugCL[7309] took 0.49 seconds to
>> encode 9000 objects
>>
>>
>>
>> Here's the code for a main.m to show it:
>>
>> #import <Foundation/Foundation.h>
>> #include <sys/time.h>
>> #include <sys/types.h>
>> #include <unistd.h>
>>
>> static double _getCurrentTime_(void){
>> struct timeval v;
>> double seconds;
>> double useconds;
>>
>> gettimeofday(&v, NULL);
>> seconds = v.tv_sec;
>> useconds = (1.0e-6) * v.tv_usec;
>> seconds += useconds;
>> return seconds;
>> }
>>
>> @interface MyElement : NSObject {
>> NSMutableDictionary* _properties;
>> }
>> @end
>>
>>
>> @implementation MyElement
>> - init {
>> [super init];
>> _properties = [[NSMutableDictionary dictionary] retain];
>> // make them the same:
>> NSString* str = [NSString stringWithFormat:@"why is this slow?"];
>> // make them all different:
>> //NSString* str = [NSString stringWithFormat:@"%p", self];
>> [_properties setObject:str forKey:@"anyOldKey"];
>> return self;
>> }
>>
>> - (NSDictionary*)properties {
>> return _properties;
>> }
>>
>> - (void)encodeWithCoder:(NSCoder *)encoder {
>> if ([encoder allowsKeyedCoding]) {
>> NSKeyedArchiver* coder = (NSKeyedArchiver*)encoder;
>> [coder encodeObject:[self properties]
>> forKey:@"MyElement__properties"];
>> } else {
>> NSLog(@"MyElement only supports keyed coding");
>> }
>> }
>> @end
>>
>>
>> encode(unsigned int count) {
>> NSMutableDictionary* stuff = [NSMutableDictionary dictionary];
>> NSMutableArray* elements = [NSMutableArray array];
>> unsigned int i;
>>
>> for (i = 0; i < count; i++) {
>> MyElement* e = [[[MyElement alloc] init] autorelease];
>> [elements addObject:e];
>> }
>> [stuff setObject:elements forKey:@"elements"];
>>
>> double startTime = _getCurrentTime_();
>> NSData* data = [NSKeyedArchiver
>> archivedDataWithRootObject:stuff];
>> double duration = _getCurrentTime_() - startTime;
>> NSLog(@"took %5.2f seconds to encode %d objects", duration,
>> count);
>> }
>>
>>
>>
>> int main (int argc, const char * argv[]) {
>> NSAutoreleasePool * pool = [[NSAutoreleasePool alloc] init];
>> unsigned int i, howMany = 10;
>>
>> for (i = 1; i < howMany; i++) {
>> NSAutoreleasePool* pool2 = [[NSAutoreleasePool alloc] init];
>> unsigned int count = i * 1000;
>> encode(count);
>> [pool2 release];
>> }
>>
>> [pool release];
>> return 0;
>> }
>>
>>
>>
>>
>> --> Michael B. Johnson, PhD
>> --> http://homepage.mac.com/drwave (personal)
>> --> http://xenia.media.mit.edu/~wave (alum)
>> --> MPG Lead
>> --> Pixar Animation Studios
>>
>> _______________________________________________
>> MacOSX-dev mailing list
>> <MacOSX-dev...>
>> http://www.omnigroup.com/mailman/listinfo/macosx-dev
>>
>>
>>
>>
>
>
