dprofpphas seen entries like this:
Garbled profile, missing an enter time stamp at
/usr/bin/dprofpp line 785, <fh> line 144174.
Modification of non-creatable array value attempted, subscript -1 at
/usr/bin/dprofpp line 679, <fh> 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.
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
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