I can confidently declare victory in the battle with the performance of cmScribe's permissions code. A page hit that was taking "about a minute" every time (the logging that enabled me to determine exactly how long things are taking wasn't added until later) is now taking 14 seconds on the first hit and is no different than other pages within the site on subsequent hits.

While working on this I re-learnt another obvious lesson about coding for performance, which can be summed up as: DON'T trust your instincts, MEASURE. This doesn't necessarily require complicated profiling tools (although I'm sure if you know how to use them they can be very useful). All I did was add code to log every permission lookup and every database hit to a file. But running a few "grep | wc" operations across the resulting log files gave me exceptionally useful information about which tables were being accessed excessively, and proved my gut instincts to be sorely lacking.

My initial feeling was that my best bet would be to try to avoid excessive hits to two tables, which we'll call TC and V. I spent a while working on TC and was disappointed to find that I'd only improved from 43 to 42 seconds. That was when I fired up grep and produced a little shell script which ran over my initial log giving output like this:

P: 9115
TC: 735
V: 4408

Turned out I was right about V being critical, entirely wrong that TC mattered at all (I'd reduced it to 234, which naturally made very little difference), and horrifyingly wrong to have entirely ignored P which was the worst offender by an order of magnitude.

The really scary thing about these numbers is that V contains 33 records and never changes at all (except with new builds of the software) while P contains about 250 and changes rarely (only on certain administrative actions).

Armed with this knowledge it was an absolute no-brainer to bring the entire contents of V and P into memory once and leave them there thereafter (with some code to re-fetch the contents of P when those administrative actions happen).

Performance improved by a factor of four, DB hits reduced by a factor of more than ten (from nearly 20,000 to under 1,700), and all without any need to fundamentally change the architecture of the system.

But I never would have got there if I'd only gone with my instincts about what could be improved. It was only by producing directly measurable information about what was really going on that I was able to spot the evil 9,000 hit table :)