The grand memory gobbler

Post by **winston** » Mon Feb 13, 2006 7:38 pm

Oh, I couldn't resist a little peek before I got on with the Chernobyl Chili, some interesting things:

ms_list contains 512 things. It looks like this inside:

Code: Select all

HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION, HOLD_POSITION

Well, except 512 of them.

It seems that the message being bandied around is 'performIdle' and there are a lot of them floating about. Specifically (this is

Code: Select all

241             actions = [NSArray arrayWithArray:[messagesForState objectForKey:message]];
 po [messagesForState objectForKey:message]
(performIdle, "pauseAI: 10.0", "setStateTo: GLOBAL")

I think something to dump the entire AI state would be handy just about now

aegidian · Post by **aegidian** » Mon Feb 13, 2006 7:41 pm

Mmm.. That's the docking system...

JensAyton · Post by **JensAyton** » Mon Feb 13, 2006 9:11 pm

As-is, a simple way to speed up the geometry stuff would be to write a custom +alloc which essentially returns the next Geometry-sized chunk from a malloc()ed block. When the block runs out, create a new one. When Geometry processing is done, free all the blocks.

If you add recycling of subtrees, it’d still be easy: override -dealloc to push the object onto a stack of dead Geometrys, and pop that stack if possible in +alloc. I’d use explicit releasing rather than autorelease pools, though.

Post by **winston** » Mon Feb 13, 2006 10:14 pm

Ah bugger, I crashed it :/
I need to find out how the AI actually works anyhow.

Post by **winston** » Fri Feb 17, 2006 8:33 am

OK, I seem to have (possibly, not yet really confirmed) to have found a common theme of this behaviour - the last two times I had it happen (once after 20 minutes, once after about 3.5 hours) there were two ships on short final for the space station (they were close enough to each other that the two ships could easily be mistaken for a single target on the scanner, and very close to the space station).

I tried to reproduce it on my Mac, but saw different behaviour - the game didn't hang, crash or eat memory, but when I checked the machine this morning there were perhaps a dozen stationary ships near the space station. (Unfortunately, I can't tell whether they are pirates or traders, but I suspect a mix). Shooting at the dozing ships didn't cause them to react - except one of them launched an escape capsule and I got attacked by a police Viper (this was all close to the space station).

JensAyton · Post by **JensAyton** » Fri Feb 17, 2006 11:07 am

At least one person has reported it happening when close to the station… this could be the trigger, rather than witchpoints, although there’s no particular reason for things to be docking more often while the player’s nearby.

Post by **winston** » Fri Feb 17, 2006 12:05 pm

I have only been able to recreate this when close to the station. If I leave the ship away from the station, the game never crashes, gobbles memory, or do anything otherwise untoward. However, in all the cases where I've been able to actually see what was going on out the window during the problem, there have been two ships on short final for the space station.

My normal method to try and recreate it is to fly to another system where there's likely to be a reasonable amount of activity, dock, then relaunch, then park by the navigation beacon facing the station. It still can take a considerable amount of time before I see it happen (I managed to recreate it only twice last night, out of an aggregate run time of over 4 hours).

Star Gazer · Post by **Star Gazer** » Fri Feb 17, 2006 12:45 pm

@ winston... ...

...wow! I'm impressed - that's real dedication!

Post by **winston** » Fri Feb 17, 2006 6:21 pm

Well, I left Oolite running when I left for work today, and 9 hours later it STILL hadn't crashed. My ship however had drifted away from the station's aegis though. So I flew back to the station, docked, launched and parked by the beacon.

This prompted the station to start splurging spacecraft (there was little activity when I arrived, but my docking/undocking seems to have stimulated the AI). Within minutes the memory gobbler began. There were numerous ships outside the station, I can't tell for sure but it looks like at least two were lined up for docking (one close in, and one close to the beacon).

So the common theme (on my hardware) is:

- if I'm not looking at the station, the game will run pretty much forever with no problems.
- the problem only seems to occur when there is more than one ship apparently docking.

I added some NSLogging to the AI (in the setState method), and got the following output:

Code: Select all

2006-02-17 18:13:30.986 oolite[5662] DEBUG: setState: I am <AI in state 'LURK'> and my state is set to COLLECT_LOOT
2006-02-17 18:13:30.988 oolite[5662] DEBUG: setState: I am <AI in state 'LURK'> and my state is set to COLLECT_LOOT
2006-02-17 18:13:33.191 oolite[5662] DEBUG: setState: I am <AI in state 'IDLE'> and my state is set to CHECK_FOR_DEBRIS
2006-02-17 18:13:33.340 oolite[5662] DEBUG: setState: I am <AI in state 'CHECK_FOR_DEBRIS'> and my state is set to IDLE
2006-02-17 18:13:35.921 oolite[5662] DEBUG: setState: I am <AI in state 'AWAIT_COORDS'> and my state is set to GLOBAL
2006-02-17 18:13:35.923 oolite[5662] DEBUG: setState: I am <AI in state 'GLOBAL'> and my state is set to AWAIT_COORDS
2006-02-17 18:13:35.925 oolite[5662] DEBUG: setState: I am <AI in state 'AWAIT_COORDS'> and my state is set to GLOBAL
2006-02-17 18:13:35.927 oolite[5662] DEBUG: setState: I am <AI in state 'GLOBAL'> and my state is set to AWAIT_COORDS
2006-02-17 18:13:35.928 oolite[5662] DEBUG: setState: I am <AI in state 'AWAIT_COORDS'> and my state is set to GLOBAL
2006-02-17 18:13:35.930 oolite[5662] DEBUG: setState: I am <AI in state 'GLOBAL'> and my state is set to AWAIT_COORDS

....
....2006-02-17 18:13:37.324 oolite[5662] DEBUG: setState: I am <AI in state 'GLOBAL'> and my state is set to AWAIT_COORDS
2006-02-17 18:13:37.327 oolite[5662] DEBUG: setState: I am <AI in state 'AWAIT_COORDS'> and my state is set to GLOBAL
2006-02-17 18:13:37.331 oolite[5662] DEBUG: setState: I am <AI in state 'GLOBAL'> and my state is set to AWAIT_COORDS
2006-02-17 18:13:37.335 oolite[5662] DEBUG: setState: I am <AI in state 'AWAIT_COORDS'> and my state is set to GLOBAL
2006-02-17 18:13:37.339 oolite[5662] DEBUG: setState: I am <AI in state 'GLOBAL'> and my state is set to AWAIT_COORDS
2006-02-17 18:13:37.342 oolite[5662] DEBUG: setState: I am <AI in state 'AWAIT_COORDS'> and my state is set to GLOBAL
2006-02-17 18:13:37.346 oolite[5662] DEBUG: setState: I am <AI in state 'GLOBAL'> and my state is set to AWAIT_COORDS
2006-02-17 18:13:37.350 oolite[5662] DEBUG: setState: I am <AI in state 'AWAIT_COORDS'> and my state is set to GLOBAL
2006-02-17 18:13:37.353 oolite[5662] DEBUG: setState: I am <AI in state 'GLOBAL'> and my state is set to AWAIT_COORDS
2006-02-17 18:13:37.357 oolite[5662] DEBUG: setState: I am <AI in state 'AWAIT_COORDS'> and my state is set to GLOBAL
2006-02-17 18:13:37.361 oolite[5662] DEBUG: setState: I am <AI in state 'GLOBAL'> and my state is set to AWAIT_COORDS

This flipping between GLOBAL and AWAIT_COORDS goes on until memory is exhausted. It just spews and spews on the log output. Hopefully I'll have some more time to dig this weekend but if Giles has some more insight, we'd sure appreciate it at this stage

I'll add an AI state to my object listing (as well as output the address of the object flipping state) so the two can be tied together, unless some insight fixes this problem before I get to doing that.

JensAyton · Post by **JensAyton** » Fri Feb 17, 2006 9:48 pm

I’m not at home in the AI, but take a look at dockingAI.plist:

Code: Select all

GLOBAL = {
    ENTER = ("setSpeedTo: 0.0", requestDockingCoordinates, "setStateTo: AWAIT_COORDS");
    EXIT = ();
    UPDATE = ();
}; 
"AWAIT_COORDS" = {
    /* ... */
    "RESTART_DOCKING" = ("setStateTo: GLOBAL");
    /* ... */
};

The only transition from AWAIT_COORDS to GLOBAL is in response to the RESTART_DOCKING message. The only place that is sent appears to be in -[ShipEntity resumePostProximityAlert]… except in the Mac trunk it’s commented out. In other words, that transition shouldn’t be happening.

It would possibly be easier to analyse the situation if you put in a message at the start of each frame (e.g. in -[Universe update]) and added owner_desc to the string returned by -[AI description]. Printing the name of the AI plist would be helpful, too, but there isn’t a convenient ivar to use.

Post by **winston** » Fri Feb 17, 2006 11:26 pm

Ah. That's probably why the problem doesn't show up in the Mac version then. Anyway, I've just been to the pub and I'm a bit drunk so I'll not do any debugging right now...

Post by **winston** » Sat Feb 18, 2006 8:56 am

Hmm. That's also commented out in the Linux source (the files are identical in the Mac and Linux trunks of equivalent revisions).

However...dockingAI.plist appears to be different.

Post by **winston** » Sat Feb 18, 2006 10:01 am

... in fact there were about half a dozen plists that were out of date. I'll put this out as 1.62-3 today hopefully (still need to test it).

It's ironic that the very thing I was making the Grand Unified Source Tree for Oolite for - i.e. to avoid merging errors such as this - has happened, sending me on a wild goose chase and delaying me in actually working on the Grand Unified Source Tree for Oolite!

Gah gah gah gah.

If anyone wants to try the fixes, just replace your Resources/AIs directory in the oolite.app/Contents folder with the latest in SVN. Or wait for me to test and put a new version on berlios and rsync.

Post by **winston** » Sat Feb 18, 2006 1:02 pm

So far, 2.5 hours of run time on two separate machines (one running a debug build, the other running the autopackaged 1.62-3) and not one hint of a problem despite doing all the things that normally reproduced the bug. Confidence is high that this is fixed... if I still haven't reproduced it by this evening it'll be released.

aegidian · Post by **aegidian** » Sat Feb 18, 2006 5:59 pm

I'll take a look at the old unrevised dockingAI and see if I can spot the problem - it's worrying that my simple AI system might cause a crasher like this.