[MUD-Dev] code profiling

[Chris Gray]

Since there has been recent discussion here of finding performance
problems and code profiling, I thought I'd briefly relate my experience
with this from the last half hour.

When I left my server over the weekend, I had been messing around with
some changes to my database. As part of that I had implemented some
data structure consistency checking, which I had forgotten I'd left
enabled. Well, of course the performance was quite poor. So, in testing
the performance effects of some changes, I was quite disappointed in
the result. Tonight I turned those changes off, and performance was still
terrible - much moreso that what I remembered. What was wrong? Profiling
to the rescue. I deleted my object files and re-compiled (using gcc)
with '-pg' enabled. Run my server for a couple of seconds, then shut it
down (there are 150 or so "machines" in my testbed database right now).

Run "gprof MUDServ | more", and the culprit (the consistency checker
routine" was blindingly obvious - it was using 95% of the time. So,
turn it off. Try again - much better! The top few lines now are:

  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 26.75      0.65     0.65   736529     0.00     0.00  ioRead
 22.63      1.20     0.55   636842     0.00     0.00  runExec
  7.41      1.38     0.18     8890     0.02     0.02  ioCacheFree
  4.94      1.50     0.12    11579     0.01     0.01  sendToMachines
  4.94      1.62     0.12    10029     0.01     0.01  ForEachAgent
  2.88      1.69     0.07  3498226     0.00     0.00  trace
....

'ioRead' fetches things from the database. Unexpectedly high - I'll
have to have a good look at it. 'runExec' is the main body of my
MUD-language interpreter; I expect that to be quite high. 'ioCacheFree'
is also in the DB cache - when a block is freed, that routine trys to
merge it with other free ones - could be expensive when I'm pounding
on the DB (3/4 million reads in 2.5 seconds). 'sendToMachines' and
'ForEachAgent' are used to tell characters (PC and NPC) about things
happening in the same location as them. Not unexpected when 150 NPC's
are moving at about 2-second intervals. I need better searching.

So, as you can see, a simple run using compiler profiling can tell
you an awful lot about where to look for performance improvements. The
amount of work is minimal. Fixing the problems is a lot harder!

--
Don't design inefficiency in - it'll happen in the implementation. - me

Chris Gray     cg at ami-cg.GraySage.Edmonton.AB.CA
               http://www.GraySage.Edmonton.AB.CA/cg/