5

I'm trying to optimize some code using hotshot, which I expected to be great since it's the high-performance profiler and all. But for some reason, I'm getting wildly inaccurate results from it. On my most recent profiling run, hotshot reported the cumulative time of the top-level function I called as 7.946 seconds. But without even timing it I can tell it's taking much longer than this. Timing the run time myself simply using time.time() gives me a runtime of 42.465 seconds. I'm guessing this is because hotshot doesn't count system IO time or something and my program is batch-processing a lot of binary files?

However, using some more time.time() blocks I narrowed most of the extra time usage (which hotshot fails to notice) down to a lower-level processing function that doesn't do any IO. hotshot reported the total and cumulative times that this function took as 4.414 and 6.185 seconds, respectively. However, again using time.time() statements I found that its cumulative time was over 30 seconds. The cumulative time spent in one relatively simply block of code was 7.32 seconds, longer than hotshot said was spent in the entire function. The block looks like this:

format = element[1]
if isinstance(format, tuple):
    format, operator, operand = format
else:
    operator, operand = (None, None)

That's it. This block was run over 9 million times, so maybe I shouldn't be surprised that this much time was spent in it. But there is plainly no IO being done here. Why is hotshot so underestimating the time this function (and the whole program) is taking?

And before you ask, no, I'm not using multiple threads or anything like that.

dpitch40
  • 2,421
  • 6
  • 25
  • 40

2 Answers2

2

If you are using Python 2.5+, try switching to cProfile. It appears that hotshot is no longer supported.

TorelTwiddler
  • 5,418
  • 2
  • 28
  • 39
0

You want to find out where all the time is going, right? Don't think of it as measuring time. Think of it as finding lines of code that are on the stack a large fraction of the time, regardless of the total. Here's an example.

Many profilers fall into the gprof traps, including ignoring blocked time, thinking that lines of code don't matter, thinking that "self time" does, and thinking that measurement has to be accurate.

Community
  • 1
  • 1
Mike Dunlavey
  • 38,662
  • 12
  • 86
  • 126
  • I think I was confused about the difference between CPU seconds and realtime seconds. The profiled times per method match up with the total elapsed CPU time recorded by hotshot, which is about 1/4 the real time the method took to run. I'm confused as to why the real time for the function to run was so much longer than the CPU time; this seems to indicate that my CPU spent a lot of time doing other tasks besides my program. But I'm not running any other intensive programs at the same time, so why is my code being scheduled so sparsely? – dpitch40 Jul 11 '11 at 20:01
  • @dpitch40: I wouldn't waste the effort to try to figure out why any profiler, let alone hotshot, is giving total times that don't make sense. The reason is my real goal is to make the code as fast as possible, and for that I want to know which statements are on the stack a high fraction of the wall-clock time. Exactly _how_ high doesn't matter - finding the statements is what matters. (Check the first link I gave.) I only really know of one profiler that "gets it", and that is Zoom. For measuring the improvement overall - don't laugh - my wristwatch is not bad. – Mike Dunlavey Jul 11 '11 at 20:12