Now, these tell you that CPU is being spent in the function (which is great) but its not the entire picture. The trouble is this: there's 527 functions in the top-level list, and 25 of them account for 1 or more percent of total runtime. Those top 25 account for ~ 45% of the total CPU time - so another 55% is being spent in the 501 functions remaining.

You may now ask yourself what the problem with that is - just optimise those top 25 functions and you'll be fine. Unfortunately, those top 25 functions aren't being called in one place - they're being called all over the shop.

Note that the CPU times above "vsnprintf" are from the functions which call it, and CPU times below "vsnprintf" are the calls which it makes. Its not immediately obvious that I have to optimise "vsnprintf" calls from the top-level trace, as most of the *printf() calls end up being to "vsnprintf" (which shows up at 0.3% of CPU time) rather than "vfprintf" and friends.

Its obvious here that finding those places which call the *printf() functions in performance critical code - and then exorcising them - will probably help quite a bit.

What about the rest of the 500 odd functions? What I'd like to do is build aggregates of CPU time spent in different functions, including their called functions, and figure out which execution stacks are chewing the most CPU. Thats something to do after Cacheboy-1 is stable, and then only after my June exams.

The important thing here is that I have the data to figure out where Squid does things poorly and given enough time, I'm going to start fixing them in the next Cacheboy release.