on garbled profiles

geoff on 2007-09-28T15:07:23

anyone who has used dprofpp has seen entries like this:

Garbled profile, missing an enter time stamp at /usr/bin/dprofpp line 785,  line 144174.

or

Modification of non-creatable array value attempted, subscript -1 at /usr/bin/dprofpp line 679,  line 142590

ungarbling a profile is a lesson in patience and rote: you go down to the line in question, figure out what sub it's talking about (the number at that line), go to the top of the file, grep for that number, find the subroutine it's talking about, add that sub to your ignore list, lather, rinse, repeat until the problems go away.



ugh



while overloaded subroutines are notorious for this behavior, they are easy to weed out via a simple code scan. but once you remove the low-hanging fruit, it's a chore to ungarble a profile if your codebase is anything more than something very simple. and, for some reason, it always seems to boil down to DBI-based calls once I get to the bottom of things.



well, this morning I decided enough was enough, I'm going to figure this out.I generally don't care about specific, low-level DBI-ish things - the amount of time (and number of calls) to fetch() is much more important to see than what DBI is doing under the hood in that mire of package madness. so, using a lot of verbose Devel::Profiler tracing and some moxy, I was able to add these packages to by bad_pkgs entry:

  DBD::_::st
  DBD::_::db
  DBD::st
  DBD::db
  DBI::st
  DBI::db
  DBI::dr)

which hides low-level DBI calls from the profiler but not those from specific drivers (which contain enough of the database overhead to be interesting). so, with my profiling back in order, I can see all the stuff I'm interested in, including entries like

  1.31   0.293  0.293   2365   0.0001 0.0001  DBD::mysql::st::execute
  1.02   0.229  0.229   4942   0.0000 0.0000  DBD::mysql::st::fetch

anyway, I hope this helps some of you out there. happy profiling :)