Performance Victory

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 :)