yob/pdf-reader — pull request #66 by alexdowad (2012-09-17 19:33:40+00:00)
Title: Requested profiling scripts

James, I've been busy lately, but I just took some time to write some scripts for profiling pdf-reader. You will need to have "ruby-prof" and "memprof" installed under Ruby 1.8, and "perftools.rb" installed under Ruby 1.9. (Perhaps add to the Gemfile?) The "ruby-prof" binstub must be on your system path. ("ruby-prof -v" to check.)

The key script is tools/bench.rb, which can be used for benchmarking, CPU profiling, or memory-allocation profiling (with different command-line args). Have a look, I think it should be self-explanatory.

Then there is tools/profile.rb, which automates the process of calling tools/bench.rb to get various types of profiles, and saves them all in tools/profiles. After you run that you should have...

- rubyprof.txt, perftools.txt: flat text files generated by ruby-prof and perftools (respectively), which identify the methods with the highest "self" time. (Time spent in the body of the method itself, rather than in its callees.) This is usually a good place to start when looking for bottlenecks.
- perftools.pdf: a PDF graph from perftools, showing hot methods and paths through the code. GOOD: it shows the amount of time spent in the garbage collector. BAD: unless the benchmark runs for long enough, it may not collect enough samples to provide reliable results.
- memprof.txt: this will identify how many objects were allocated by the benchmark, and where. Decreasing those numbers can squeeze down the time spent in the GC.
- rubyprof-graph.htm: This also organizes the methods by "self time", but it identifies which methods call into each "hot" method, and how many times. It is hyperlinked so you can click around find out who is calling the callers, etc.
- rubyprof-stack.htm: Open this up and you'll get the concept right away. You can see all the code paths, from the top-level entry method right on down, and how much time was spent in each of those paths.

If the "GC" time which you see in perftools.txt or perftools.pdf seems high, use memprof.txt to find out where memory is being allocated (and stop it). To attack the time spent in computation itself:

Finding out the methods with the highest "self time" is a good first step. It's the fastest way to identify CPU bottlenecks. But you'll also want to examine the "call stack" display of times in rubyprof-stack.htm, as well as rubyprof-graph.htm. These different ways of displaying information will help you find different bottlenecks.

For example, you might have a mid-level method which calls a bunch of lower level methods, which in turn call a bunch more lower level methods, etc. All together, they are taking a lot of time. But you won't see it in the "self time" display, because that time is spread out over a bunch of methods. However, in the "call stack" display, it will come out clearly.

Another problem with the "self time" display is when you are spending a lot of time on things like Array#map, Fixnum#*, and so on. If you see very general core methods like that high in the "self time" display, go to rubyprof-graph.htm to find out where they are being called from (and pay special attention to the *number* of calls from each call site). If you find that the calls are coming from other "general" core methods, then you may have to resort to searching in the "call stack" display to find the problem site.

On the other hand, when you have a low-level method which is inefficient, and it's used *all over* the codebase, rather than being called many times from one specific place, it may not come out clearly in the "call stack" display. In that case, the "self time" display will show the problem more clearly.

When you find a certain method is consuming a lot of time, *always* pay attention to the *number of times* it is being called. In some cases, the problem is not that the method is slow, but that it is called too many times. This may point to some O(n^2) behavior somewhere, or the need for caching. Even if the solution is to optimize the method, knowing how many times it is being used can help you understand what kind of optimizations will be effective. When the number of calls is *very, very* high, that's when you temporarily put good coding style aside and do really detailed, low-level optimizations like manually inlining methods.

One thing which I have identified might be helpful, though I don't have the time to do it now, is to use symbols rather than strings for tokens like "(", "[", and so on. It will require using something else for PDF names (because otherwise the name ">>" would be indistinguishable from an "end-of-dictionary" token).

Note also that the code is getting fast enough that a more intensive benchmark may be needed. I'm using spec/data/no_text_spaces.pdf, but perhaps you have a really big, slow PDF which would be better for benchmarking.