Profiling a slow loader

Six minutes. That’s how long GTA Online took to load on t0st’s machine, an AMD FX-8350 with an SSD, according to the post that’s been all over Hacker News since the weekend. Story mode on the same machine loaded in about a minute ten. The game came out in 2013, and people have been complaining about the online load times for most of the time since.

He didn’t have the source. He didn’t have debug symbols. He watched the process in Task Manager, noticed one CPU core pegged for minutes while the disk and network sat idle, and then pointed a stack-sampling profiler (Luke Stackwalker, which I’d never heard of) at it to see where that core was spending its time. Then he disassembled the hot spots. What he found was two bugs, and they’re the same bug wearing different clothes.

The game downloads a JSON file of about 10MB, the in-game store’s catalog, roughly 63,000 items. The parser reads values out of it with sscanf. And sscanf, in the C runtime the game uses, calls strlen on its input every time it’s called, before doing anything else. The input is a pointer into the middle of the 10MB string. So every token parsed walks the rest of the file looking for the terminating zero, and the total work grows with the square of the file size. It’s this, more or less:

const char *p = json;
int value, used;
while (sscanf(p, "%d,%n", &value, &used) == 1) {
    /* sscanf did strlen(p) before it parsed one digit */
    p += used;
}

Every line of that looks fine. That’s what makes it nasty. Joel Spolsky called this Schlemiel the Painter’s algorithm about 20 years ago, after the painter who keeps walking back to the paint can at the start of the road, and it keeps turning up because the slow part is hidden inside a library call that looks cheap.

The second bug is the one I see in code reviews every month. As each item is parsed, the loader checks whether it’s already been stored, by comparing it against every item stored so far, in an array. For 63,000 items, t0st works out (n² + n)/2 comparisons, which is a little under two billion. A hash set would make that check constant time. Apparently the items are all unique anyway, so the check isn’t doing anything.

His proof of concept patched both, caching the string length and skipping the duplicate check, and the load went from six minutes to one minute fifty. Fixing only the parser got it to 2:50, and fixing only the duplicate check got it to 4:30, so the parser was the bigger of the two by a fair margin. That’s a 69.4% improvement by his own arithmetic, rounded up to 70 in the title.

I’m not going to pile on Rockstar’s developers. I’ve written both of these bugs. Everyone who’s been programming for a while has. What gets me about this story is the gap between how hard the problem looked from outside (a giant game, years of complaints, presumably lots of smart people) and how little it took once someone actually measured.

The one we had

Ours was a customer CSV import. Customers upload a spreadsheet of contacts, we validate it, dedupe it and write it to the database. It had been fine for years, and then one of our bigger customers started uploading files of 90,000 rows and the import job took 25 minutes and occasionally hit the job timeout. The theory on the team was the database, because it’s always the database, and someone had already started on a plan to batch the inserts.

I ran the job locally under a sampling profiler (stackprof, since this is Ruby) on a copy of the file. About 95% of the samples were in one line:

unique << row unless unique.include?(row)

include? on an array is a linear scan. Same bug as GTA’s, in a nicer language. Swapping the array for a Set keyed on the normalized email got the job down to about 9 seconds, most of which was, as it happens, the database. Nobody needed to batch anything.

The reason it took years to show up is the reason these bugs always take years to show up. With 2,000 rows a quadratic loop is 2 million comparisons and nobody notices. With 90,000 it’s about 4 billion. Quadratic code passes every test you write with realistic small data, then falls off a cliff at a size nobody tested, usually your biggest customer’s.

How I look for these now

Profile first, and use a sampling profiler. Instrumenting profilers change the timing of what they measure, and you don’t need precision, you need to know which few lines a sampled stack keeps landing in. On Windows I reach for PerfView or the Windows Performance Recorder. On Linux it’s perf, and for Ruby, Python and Node there’s a decent sampling profiler for each (stackprof or rbspy, py-spy, --prof or the Chrome DevTools profiler). I spent about ten years guessing at slow code before I got into the habit of measuring first, and my guesses were wrong often enough that I’ve stopped trusting them. (I wrote up a bit of micro-optimization back in 2008, which was fun, but that was a puzzle where I already knew where the time went. Production code is almost never like that.)

Look at what the CPU is doing while it’s slow. One core pegged and no I/O is the signature of an algorithm problem, and that’s what t0st saw in Task Manager before he did anything clever.

Then, when you find a loop, ask what’s inside it that also loops. A strlen, an include?, an indexOf, a list.contains, a LINQ .Any() over a List<T>, a query per row. It’s almost never the outer loop that’s the problem.

And test with big inputs on purpose. We now have one fixture for the import that’s 200,000 rows, generated, and a test that fails if it takes more than 30 seconds. It’s caught one regression already.

I remember doing exactly the strlen-in-a-loop thing in Turbo C at about 15, for (i = 0; i < strlen(s); i++), on strings that were never more than 80 characters long, so it never mattered and I never learned. It took a 10MB string to make it matter for Rockstar. I’m curious whether they’ll ship a fix now that it’s this public. I’d guess yes, given how small the patch is, but I’ve been wrong about bigger companies doing smaller things.