Wednesday, December 30, 2009

Optimizations are great, but sometimes it helps not to be an idiot...

So, if you've been following my progress on magecrawl, you'll remember my article on optimization trying to cut down on memory usage and map generation time. If not, here and here.

Well, I did a bit of programming this morning before work, and on the way driving to work I had one of those "Wait a second..." moments. Here's the guilty section of code:

private void GenerateMapFromGraph(MapNode current, Map map, Point seam, ParenthoodChain parentChain)
       {
            if (current.Generated)
                return;

            current.Generated = true;
            bool placed = false;

            System.Console.WriteLine(string.Format("Generating {0} - {1}", current.Type.ToString(), current.UniqueID.ToString()));

It's that last line that got me. It was some debugging code that I forgot to remove. This function gets called recursively during map generation, a huge number of times and writing to stdout is very slow.

Some baseline numbers (release mode attached to debugger) in generating 100 maps gives me:
  • Before - 47473ms
  • After - 1041ms
Yeah, only a 45x speedup. While all the other optimizations were great, and needed due to memory usage, this appears to be the root cause of my performance issues.

The lesson for today, next time performance is terrible, check stdout to make sure you aren't dumping 10000 lines of text to it during map generation.

Update: Now I just need to find some crazy optimization for my cave map generator and I can get rid of my "loading" screen, since I can generate 100 of the stitch levels in about a second.

3 comments:

Mingos said...

Amen to that! I once made my map generator display a line on stdout for each map cell visited by some sort of recursive function too. My maps are 112x90 and each cell got visited several times. It took ages to generate even a single map. Duh!

droid factorial said...

I wonder if you have a profiler. This is the kind of thing that can easily be detected with one, it really helps focus optimization efforts. I remember using one to identify where an infinite loop in a parser a few years ago.

donblas said...

I actually did use a profiler EQATEC's one for .NET. The issue that for some reason the System.Console stuff wasn't showing up clearly. I'm not sure if they scrub out system calls or what, but i figured it'd be obvious in a profiler but it wasn't.