The grand memory gobbler

[winston]

Well, I can now shed a little insight on WHAT's being leaked. Finally, it happened to me when I was running my very simple memory analyser. (This is going to be a little long). The output in this is the time of allocation (seconds since the epoch), the name of the class, then the address of the object. In the immediate lead up to the problem we see this:

Code: Select all

1139775273 AI (92bb490)
1139775273 NSLock (922d120)
1139775273 ParticleEntity (ed7a5010)
1139775273 AI (95da060)
1139775273 NSLock (922c1f8)
1139775273 ParticleEntity (ed775010)
1139775273 AI (9648250)
1139775273 NSLock (9d04a18)
1139775273 ParticleEntity (ed745010)
1139775273 ParticleEntity (ed715010)
1139775273 AI (96479b0)
1139775273 NSLock (9ba5bf0)
1139775273 ParticleEntity (ed6e5010)
1139775273 ParticleEntity (ed6b5010)
1139775273 AI (9c86b70)
1139775273 NSLock (9222c10)
1139775273 ParticleEntity (ed685010)
1139775273 AI (93be298)
1139775273 NSLock (9d008d0)
1139775273 AI (93bf400)
1139775273 NSLock (9155cc0)
1139775273 AI (93c05a0)
1139775273 NSLock (916af00)
1139775273 AI (93c0188)
1139775273 NSLock (9165b80)
1139775273 AI (91dc4b8)
1139775273 NSLock (9c8af40)
1139775273 AI (91dd578)
1139775273 NSLock (919a038)
1139775273 AI (91de6b8)
1139775273 NSLock (9c939d0)
1139775273 AI (91a37b0)
1139775273 NSLock (9e716c0)
1139775273 AI (9401fd0)
1139775273 NSLock (9228e18)
1139775273 AI (9402e60)
1139775273 NSLock (8eeb6a0)
1139775273 AI (95d3088)
1139775273 NSLock (9d03f50)
1139775273 AI (95d3728)
1139775273 NSLock (9168240)
1139775273 ParticleEntity (ed655010)
1139775273 ParticleEntity (ed625010)
1139775273 ParticleEntity (ed5f5010)
1139775273 ParticleEntity (ed5c5010)
1139775289 SDLImage (92d6508)
1139775300 SDLImage (9e716f8)
1139775305 SDLImage (99b9058)
1139775306 AI (946ecd0)
1139775306 NSLock (9ba4e70)
1139775306 AI (95f5610)
1139775306 NSLock (9236e30)
1139775306 AI (9493c08)
1139775306 NSLock (9ba9438)
1139775320 SDLImage (9ba05b8)
1139775321 SDLImage (9816320)
1139775321 SDLImage (97e75f8)
1139775332 SDLImage (97b2e08)
1139775332 SDLImage (9726668)
1139775374 SDLImage (97640b0)
1139775397 AI (911e498)
1139775397 NSLock (9c99130)
1139775397 AI (95d36e0)
1139775397 NSLock (9c925b0)

generally in a repeating pattern. In total 89 AI objects and 167 ParticleEntity objects (the above is just a snippet - remember this is a snapshot of what's in memory - not a log - when an object is deleted it goes off this list). I think this is merely a battle occuring, I don't think the number of AIs is excessive. Then eventually it blows up like this:

Code: Select all

1139787334 AI (9465440)
1139787334 NSLock (9e71f70)
1139787334 ParticleEntity (efc99010)
1139787334 AI (979f138)
1139787334 NSLock (9228950)
1139787334 ParticleEntity (efb34010)
1139787334 AI (9465490)
1139787334 NSLock (9122f50)
1139787334 ParticleEntity (efb04010)
1139787418 WormholeEntity (98504f8)
1139787418 AI (9792260)
1139787418 NSLock (9e72058)
1139787418 ParticleEntity (987f630)
1139787481 WormholeEntity (eef95010)
1139787481 AI (960d780)
1139787481 NSLock (9785318)
1139787481 ParticleEntity (ee7f6010)
1139787481 ParticleEntity (ee7c6010)
1139787530 WormholeEntity (ee766010)
1139787530 AI (97a24a0)
1139787530 NSLock (9c16120)
1139787530 ParticleEntity (ee736010)
1139787530 ParticleEntity (ee706010)
1139787569 SDLImage (984be60)
1139787578 WormholeEntity (ee3e3010)
1139787578 AI (9797f60)
1139787578 NSLock (9d037c8)
1139787578 ParticleEntity (ee3b3010)
1139787692 WormholeEntity (ee353010)
1139787692 AI (97d5a20)
1139787692 NSLock (9c1a870)
1139787692 ParticleEntity (ee323010)
1139787787 AI (954a950)
1139787787 NSLock (910a498)
1139787787 ParticleEntity (ee2c3010)
1139787787 ParticleEntity (ee293010)
1139787787 ParticleEntity (ee263010)
1139787787 ParticleEntity (ee233010)
1139788343 GSDictionaryKeyEnumerator (91d41e0)
1139788343 GSDictionaryKeyEnumerator (9987ca8)
1139788343 GSDictionaryKeyEnumerator (97ccd80)
1139788343 GSDictionaryKeyEnumerator (9787060)
1139788343 GSDictionaryKeyEnumerator (917afe8)
1139788343 NSScanner (978f2d0)
1139788343 NSScanner (984e540)
1139788343 NSScanner (9824150)
1139788343 GSDictionaryKeyEnumerator (9c1e788)
1139788343 GSDictionaryKeyEnumerator (93520b8)
1139788343 NSScanner (9748680)
1139788343 NSScanner (97a29f0)
1139788343 NSScanner (9765dc0)
1139788343 GSDictionaryKeyEnumerator (979c6f0)
1139788343 NSScanner (9790fb8)
1139788343 NSScanner (97e37a0)
1139788343 GSDictionaryKeyEnumerator (9a3f1e8)
1139788343 GSDictionaryKeyEnumerator (97021f8)
1139788343 GSDictionaryKeyEnumerator (97d32f8)
1139788343 NSScanner (97f1020)
1139788343 NSScanner (9844460)
1139788343 NSScanner (9736d58)
1139788343 GSDictionaryKeyEnumerator (96fba68)
1139788343 GSDictionaryKeyEnumerator (97ad9e8)
1139788343 NSScanner (981eac8)
1139788343 NSScanner (972e5c0)
1139788343 NSScanner (9793718)
1139788343 GSDictionaryKeyEnumerator (96f7820)
1139788343 NSScanner (97ab2c8)
1139788343 NSScanner (97f6640)
1139788343 GSDictionaryKeyEnumerator (9821fa8)
1139788343 GSDictionaryKeyEnumerator (9778798)
1139788343 GSDictionaryKeyEnumerator (96fcb50)

And the pattern of NSScanner/GSDictionary repeats ad infinitum until the oom killer finally brutally kills the process off. Note the relative surfeit of WormholeEntity objects - a total of 5. I only bring up WormholeEntity as the first time I saw this behaviour was the time when wormholes were added.

Also note that many of the AI objects are actually quite long lived (as this is a snapshot of what's in memory right now, not a log) - several hundred seconds old.

The next step is to set an object ceiling and have the debugger hit a breakpoint at that point so I can have a look at the backtrace. Ahruman has also written a much more comprehensive memory stats system than mine; I'll be adding this to the svn tree (and probably putting it into development builds).

[JensAyton]

Unfortunately my one has to ignore NSScanners under Cocoa; dunno if this is also the case with GNUStep. I’ll look into the possibility of working around this using a custom libobjc (urgh). Event-driven feedback, such as per-class threshold-exceeded notifications, would be trivial.

[winston]

Mine actually adds an object to the list when NSObject's -init method is called. It seems that anything that's important to us at least calls -init. List entries are deleted in -dealloc.

Additionally, I've set a break point in the debugger when the object count exceeds a certain value so I can get a backtrace. I will leave it running while I'm out at work.

[JensAyton]

Hmm. -init seems unreliable; a lot of people don’t bother calling through to NSObject init since it isn’t expected to do anything. Since my implementation doesn’t track individual objects, just counts them, I can’t do it in two places.

Am I right in thinking the gobbler is only confirmed on non-Mac systems? If so, it’s tempting to suspect a bone fide bug in the NSScanner implementation, although it’s presumably triggered by something about the invocation. Using your implementation it ought to be possible to break on the threshold-exceeded event, then step out into the NSScanner and see what it’s trying to do. I’m assuming the problem is, at least to some extent, recursive rather than iterative.

The ability to dump stack traces on threshold events strikes me as useful, but the only stack trace code I’ve got is for good ol’ PPC-PEF.

[winston]

Well, if it was recursive, it shouldn't swamp up memory - it should blow the call stack and crash (but it's not doing that). So I'm betting it's iterative. As I said, I have a break point set now so I can find out the whole story.

IIRC, Oolite overrides NSScanner with a category. As for -init, it seems from my dumps, anything of any importance (at least in GNUstep) calls -init (I chose that originally so I could put things in the NSObject's member data, but as I said in my email, this caused GNUstep as a whole to break). At least the classes we're interested in seem to all get to NSObject's init (although I'm sure some don't).

The bug is only confirmed on non-Mac systems. But it's one of those awkward bugs - on my system it takes at a minimum several hours before the problem manifests itself (one time it took 14 hours). On other people's systems it happens within five minutes. I've had very few comments/complaints about this bug so I suspect most people never run into it.

Incidentally, my GNUstep base is compiled with -g so I can debug that, too.

[TGHC]

It happens all the time in windows, in a 2 hour session it happens 3 or 4 times on average, on my system anyway, and that's with a gig of ram.

Delighted (nay delerious) to see you're making progress in tracking down the blighter.

When you have just made several kills, scooped a fortune in cargo and can see the space station for dockingg it's so frustrating when it locks up and dies, now at the first sign of freezing, I try and cut and run with the witchspace injectors and dock and save, before it totally locks up.

[winston]

I just ssh'd into my machine, and it's done it again. Once again, it looks like the suspicious NSScanner activity is being started from the AI, and once again, there are multiple WormholeEntities in existence. It will be this evening before I can look at it in the debugger, though.

[JensAyton]

Clearly NSScanner is teh suck anyway, and I fart in its general direction. Most of the AI parsing stuff could probably be done much more efficiently with a simple functional approach. But since Giles ripped out my nearly-elegant functional XML plist parser and replaced it with a Cocoa monstrosity, I’m loath to do this spontaneously, so to speak. :-)

[aegidian]

But since Giles ripped out my nearly-elegant functional XML plist parser and replaced it with a Cocoa monstrosity...

**cries**

Stop it. I'm sensitive.

[JensAyton]

Aww. *pats Giles on head*

My XML code wasn’t that great. I don’t really miss it.

However, there are several uses of NSScanner which look rather inefficient, such as [ResourceManager scanTokensFromString:] and [Entity scanTokensFromString:] (which seem to do the same thing in slightly different ways). Of the top of your head, are these ever expected to be called with any separator other than space, or with more than, say, sixteen substrings to be found? If not, a single procedural replacement should be sufficient and simple, and save several hundred temporary object allocations per frame.

Potentially, several uses with their corresponding NSNumber-to-number conversions could be swapped to something like a safe version of sscanf(), although of course this would require more than the search-and-replace of the previous suggestion.

At some point I’m going to rewrite file loading for Dry Dock using flex. When I do, I’ll show you the results for evaluation. :-)

[JensAyton]

Oh, on the subject of allocation efficiency: while writing my allocation profiling thing, I’ve found that 98.56% of objects allocated up to the “Load game y/n” screen are Geometrys - over three hundred thousand of them, and almost 30,000 at a time at some point, all autoreleased by the look of it. This seems a tad excessive to me. If nothing else, a more efficient allocator or a cacheing scheme might be in place.

You may have noticed that I’m something of a purist. ;-)

[aegidian]

Yeah, I never really grew past recursion in comp-sci.

Yes, the text handling part of Oolite would be better served by more efficient scanning. I just try to use what works, and NSScanner (largely) works - except for where it has bugs darnit.

WRT Geometry objects:-

Yeah, they're generated in another recursive algorithm, and hundreds/thousands of them are required for each octree calculation, which is done once for each model in the game. They were written with an eye for efficiency though, unlike my fixed-memory mess with entities. The aim of all this is to have a final, space-efficient octree implementation on a one-per-model basis (currently debugging iems bloat the octree slightly - but it should come down to about an int's worth of space per octant-leaf eventually).

Assuming models aren't going to change much (shapes should stay fixed) - the octree data can then be cached and read from disk rather than calculated each time - I'll make that optimisation when I've got them working properly.

[JensAyton]

Fair enough. Am I right in believing there will be well-defined moments when no Geometrys will be around, i.e. that you perform the octtree calculation and then throw away the only tree of Geometrys that’s around? If so, memory management could be significantly quickened quite simply. (Also, are bits of the Geometry tree actually recycled during the construction, i.e. are there any custom autorelease pools in effect? If not, it could be simplified even more.)

[winston]

OK, here's the backtrace from the runaway allocation breakpoint. It's not a recursive runaway, it appears to be an iterative one (simply because the backtrace is only 18 entries long). Bear in mind I've not started to debug it yet and I now have to go and make a chili for tomorrow's dinner...

Code: Select all

#0  MDAddObject (classname=0xd315b1 "NSScanner", addr=0x0) at NSObject.m:2481
#1  0x00bd0c3a in -[NSObject init] (self=0x9f20af0, _cmd=0xd71030)
    at GSObjCRuntime.h:281
#2  0x00bf0be9 in -[NSScanner initWithString:] (self=0x9f20af0, _cmd=0xd71010,
    aString=0x9c94a10) at NSScanner.m:172
#3  0x00bf0b1b in +[NSScanner scannerWithString:] (self=0xd70fa0,
    _cmd=0x81731b8, aString=0x9c94a10) at NSZone.h:277
#4  0x08053399 in +[Entity scanTokensFromString:] (self=0x8172e40,
    _cmd=0x8171d88, values=0x9c94a10) at Core/Entity.m:221
#5  0x080515d0 in -[AI takeAction:] (self=0xa16d660, _cmd=0x8171d68,
    action=0x9c94a10) at Core/AI.m:268
#6  0x080514fe in -[AI reactToMessage:] (self=0xa16d660, _cmd=0x8171d40,
    message=0x8189d44) at Core/AI.m:249
#7  0x08051b44 in -[AI think] (self=0xa16d660, _cmd=0x818c708) at Core/AI.m:344
#8  0x0812253f in -[Universe update:] (self=0x98e2768, _cmd=0x8174460,
    delta_t=0.019998987947474234) at Core/Universe.m:5087
#9  0x0805d967 in -[GameController doStuff:] (self=0x976d698, _cmd=0x8177a48,
    sender=0x0) at Core/GameController.m:510
#10 0x08073bdc in -[MyOpenGLView pollControls:] (self=0x978e400,
    _cmd=0x8174408, sender=0xa490368) at SDL/MyOpenGLView.m:976
#11 0x00bd1a24 in -[NSObject performSelector:withObject:] (self=0x978e400,
    _cmd=0xd75ff8, aSelector=0x8174408, anObject=0xa490368) at NSObject.m:1791
#12 0x00c12c60 in -[NSTimer fire] (self=0xa490368, _cmd=0xd70b20)
    at NSTimer.m:218
#13 0x00bef138 in -[NSRunLoop limitDateForMode:] (self=0x983b9e8,
    _cmd=0xd70a80, mode=0xd70c78) at NSRunLoop.m:815
#14 0x00befedc in -[NSRunLoop runMode:beforeDate:] (self=0x983b9e8,
    _cmd=0xd70bb0, mode=0xd70c78, date=0x9840f28) at NSRunLoop.m:1107
#15 0x00bf016b in -[NSRunLoop runUntilDate:] (self=0x983b9e8, _cmd=0xd70ba8,
    date=0x9840f28) at NSRunLoop.m:1165
#16 0x00bf00ca in -[NSRunLoop run] (self=0x983b9e8, _cmd=0x8174438)
    at NSRunLoop.m:1148
#17 0x0805d793 in -[GameController applicationDidFinishLaunching:] (
    self=0x976d698, _cmd=0x8177050, notification=0x0)
    at Core/GameController.m:375
#18 0x08070a4e in main (argc=1, argv=0xfeee7294) at SDL/main.m:55

I will prolly look at it further in a couple of hours and report back what I find.

[aegidian]

Fair enough. Am I right in believing there will be well-defined moments when no Geometrys will be around, i.e. that you perform the octtree calculation and then throw away the only tree of Geometrys that’s around?

That's the general idea - and indeed what happens now in [ShipEntity setModel:] - the octree-Array of geometries is generated and chucked away once the octree is initialised from it.

(Also, are bits of the Geometry tree actually recycled during the construction, i.e. are there any custom autorelease pools in effect? If not, it could be simplified even more.)

No, in Geometry - (NSObject*) octreeWithinRadius:(GLfloat) octreeRadius toDepth: (int) depth; could be improved quite simply. I should go do that.