If you’re a regular here, you know how much we care about the full-stack view of applications. Today, let’s zoom in a bit, and talk about the performance of a single layer. In particular, let’s look at profiling in Python.

As an example, let’s take this bit of code for calculating confidence intervals of the mean of a set of data. If you’re not familiar with confidence intervals, they provide a set of bounds for a given statistic; a 95% interval implies that the true mean lies in the calculated range 95% of the time. One way of calculating this involves generating a number of new data sets from the data you have (random selection, with replacement), and looking at that (meta?-)data set. In practice, you typically run this a couple of times, look at the results, and see if they’re converging. If not, you keep running until they do converge, or you hit some max number of iterations.

It turns out, doing 1000 iterations of a reasonable data set size (say, 100k points) is a reasonably expensive operation — about 2 seconds (ish) on my laptop. That’s not too bad in isolation, but run every 15 minutes, on a variety of data sizes up to 1 million, over all customers here at AppNeta? We can do much better.

Since this is Python, let’s see if there’s an obvious way to do it. As it turns out, there is: the standard library module cProfile. This is Python’s flexible, deterministic, C-implemented profiler. (There’s also profile, a pure-python version, but unless you have good cause to avoid C extensions, cProfile is probably a better bet.) cProfile will give us a list of all function calls, sorted however we want. Let’s run it, and dump the result to a file:

There’s a few important things to take note of in these results. The first thing to notice is that 3 of the top 4 functions are in the random module. We only use the random module twice in our example, and the initial use (generating the data set) is a constant 100,000 calls. That leaves 4 million calls from the inner loop of confidence_interval. Since that’s a core part of the algorithm, I wonder if there’s a better way to do that?

For a start, let’s try using a different random number generator. As a rule, if you have a slow function in python, and numpy has a replacement function, the numpy version will be faster. Let’s replace random with numpy.random, and try again:

Much better! Unfortunately, now we have a different problem. Instead of a single line or function call, we only know our problem exists inside a function.

One way to drill down on this is to use statprof. This is a different type of profiler: instead of instrumenting each function call, statprof wakes up at pre-defined intervals and records a stack trace, including line number. Let’s run that:

Cool! Looking back at the code, lines 44 and 45 are the selection and array creation:

Interestingly, the absolute time reported by statprof is a bit lower than cProfile. That difference is due to the statistical nature of statprof. Even at the default setting of 1ms samples, it simply has to do less work than cProfile, who has to instrument all 4 million calls to the various parts of random. It’s worth remembering this difference in overhead, as some code will exihibit different behavior as the timing changes.

In any case, can we do better? It’s possible that the time here is no longer being spent on calculations, but instead on simply creating intermediate arrays. Let’s combine those lines, and re-run:

That certainly seems better: 1.92s vs 2.39s (1.54 + 0.85) from above. At this point, though, be careful. Up until now, we’ve avoided directly comparing profiling runs. Looking at the percentage of time spent, we’re actually at about the same place (85% of total); this run just completed faster than the last run. This is a common pattern — as the low-hanging fruit is picked off, it becomes more and more important to validate smaller gains in more formal ways. How, exactly, to collect those stats is a topic for another post.

It’s also worth mentioning Robert Kern’s line_profiler. It’s a deterministic profiler (like cProfile), but it captures profiling data on a line-by-line basis. It also allows selectively profiling specific functions, which can be invaluable on a larger codebase, to weed out the noise from other modules. Unfortunately, because it does capture every line call you ask it to, the overhead of instrumenting every line you run can be substantial (4x slowdown on my laptop). For completeness, here’s what it looks like on our sample:

Finally, remember that profiling is just one component of a performance toolkit. Most performance problems aren’t complex; they’re just well-hidden. Before writing the above code, I hadn’t realized how expensive random number generation could be. Simply taking the time to look for a faster function saved over 90% of the time spent.

Make it work, then make it pretty, then make it fast. And with the right tools, it doesn’t even take that long.

And if you want to find other ways to optimize your code and make it fast, start using TraceView for free - sign up here.

Related Articles

Python and gevent

Tracing Celery Performance For Web Applications

Tracing Python — An API

• Python Performance Tips, Part 2
• Sybase Adaptive Server Enterprise 15.7 Boosts Performance and Lowers Cost of Managing Exploding Data Volumes
• Challenges in Tracing JavaScript Performance by Example