This story is part bug hunt, part open-source love-story. The bug was a particularly gnarly, beautiful little bug and I'm going to try to convey some of that to you. But the other half of the story is really the thing here; The Guardian is serious about engaging with the wider technology community - while we work hard to open out our data to the world at large, we also participate by speaking at conferences, sponsoring events, and sometimes in the simplest way of all; contributing code and fixes for the Open Source software that we use.



To tell you this story I'll need to give you some background into the problem we were trying to solve - a problem of caching. A computer uses a cache (a chunk of memory) to locally store information (like a Guardian article, or a set of headlines) that it would otherwise have to request from another system. We use caches on our servers to speed up the Guardian website. Our caches are much smaller than the set of data we're attempting to serve to the public, and so spend all their time 100% full - the least recently used data gets chucked out as new data from uncached articles gets chucked in. Those uncached articles have to be loaded from the database, and on average every time someone hits a page on the Guardian site, we have to make about half a dozen requests to load data that isn't in the cache. Given the popularity of the Guardian site, this means we're making over a thousand database requests a second of our single database machine, which - if it were not for the fact that it's a massive box administered by a crack squad of elite Ninja DBAs - should have melted into an ill-smelling puddle a long time ago.

This precarious situation is only going to get worse as the Guardian continues to grow more popular and so we've been working on making our caching much more effective - a first step on this road was to use a more flexible caching engine, namely JBoss Cache, which is a powerful caching solution released under the LGPL (an Open Source licence that aims to encourage use of the software by as large an audience as possible - you can read the code, change the code, and redistribute it as you please).

After several weeks of development work, we had sown JBoss Cache into our development version of the Guardian website, and found that it performed well under quick 1-hour stress tests. Then we performed a long running soak test, starting on Friday afternoon. We went home, came back on Monday morning, and found a graph like this:

Our cache fills up- and then mysteriously starts to empty...

Oh dear. Verrrrrry Bad. The cache was, for some reason, getting smaller and smaller over time. In our case, It Really Shouldn't Do That. The cache - the cache we so desperately depend on to take load off the database - should stay 100% full all the time. If our cache starts to evaporate without explanation, well, that's just not going to do anyone any good.

We investigated. This part should be fun, but there are a lot of unknowns. Are we doing something wrong? Is there something wrong with JBoss Cache? If so, why doesn't everyone else see it? Yet in the face of these unknowns, we can do this. JBoss Cache is Open Source - we can read the code.

The questions start:

The Cache is getting smaller. Why?

It thinks it's full when it isn't, so it chucks stuff out of the cache when it doesn't have to. Why?

Ah, interesting. JBoss Cache decides to evict stuff based on the length of it's 'Eviction Queue', which is basically a list of every single thing that's currently in the Cache. If the list is longer than the maximum number of things we've said we want in the Cache, JBoss Cache will chuck old items (the oldest items are the ones at the front of the queue...!) until the list is back down to size. But something's gone wrong. JBoss Cache is getting rid of stuff before the cache is full because the Eviction Queue list is a different length than the number of items in the cache: It's longer. Why?

There are items in the Eviction Queue which are not in the Cache. Why?

in the Cache. Why? Ah. Now you're asking.

and so on

At this point, it really does look like there must be something wrong with JBoss Cache, so the temptation is to just raise a bug report with them and wait for them to fix it. However, we don't pay them any money, and they're busy people - plus the bug report would be so vague as to be ignorable.

We made a simplified example of the problem to make investigating it easier, stripping out everything that was 'Guardian', and retaining the simplest possible code that still reproduced the issue. This let us progress much more rapidly in our pursuit of the bug - and provided a simple demonstration that we could later show to JBoss.

Ultimately, the problem turned out to be a misunderstanding within the JBoss Cache code itself, and it was a pretty rare misunderstanding - it could only happen if we decided to remove an item from the cache at exactly the same time that JBoss Cache itself decided to evict it. But provided that happened, in just the right order, you would get a situation where JBoss Cache would try to evict item X from the Cache - when in fact X wasn't even in the cache any more, and had been removed an instant earlier. The code would get confused, and think to itself:

"I wasn't able to remove X from the Cache - it's still there - keep it in the Eviction Queue!"

That difference - the difference between not doing something and not being able to do it, was at the root of our problems. The Eviction Queue list filled up with phantom items it thought were still there because it couldn't get rid of them, and the number of items actually allowed to live in the Cache ended up far less.

The thing that made the bug so hard to find, and the reason no-one else

had noticed it, was that it only occurred when two things happened

simultaneously. To see the bug you have to be evicting and removing

items all the time. Our caches are so full that we are evicting things

out of them pretty much constantly - and we're a news organization, so

we're also explicitly removing out-of-date content with almost equal

frequency. For the Guardian, it was certain we'd hit this bug like a

brick wall, but for other users of JBoss Cache the problem might not be

as immediately evident. In a commercial closed-source product, a bug

that affected a minority of users in this way might never gain

attention, and could remain unfixed for months or even years. With JBoss Cache, we had everything we needed to fix the bug ourselves.

We quickly wrote a patch for the code that straightened out the misunderstanding, and re-ran our soak test. We saw a beautiful horizontal line - our caches stayed a hundred percent full, just the way they're meant to. HUZZAH!

The story doesn't end there - though we had rid ourselves of the phantoms that haunted our cache, we still needed to get our fix accepted by JBoss so that they could incorporate it into later versions of JBoss Cache and pass the benefit of the fix on to other users. We had no idea how soon JBoss would respond - would they even take the time to read the bug report?

As it turns out, JBoss were outstanding. No sooner had we filed the bug report than the issue was promptly elevated to 'Critical' by JBoss, who thanked us for "excellent report and analysis" - and within 24 hours Manik Surtani, the Lead R&D Engineer on JBoss Cache, had released a new snapshot version of JBoss Cache containing our fix.

So there it is - the fairy tale really did come true. Open Source did everything it's meant to for us - let us understand our problems, and accepted our solutions- and we got to give back to the community.