I spent some time this weekend improving the performance of the server-side request processing logic for Imprint. This particular code path executes on every request for an Imprint impression, which on a casual day is around 10k requests / sec. The logic is fairly straight forward but several steps are required before we can send a single byte back to the client. A non-exhaustive list of computations required:

• Parse all parameters, including user GeoIP location, user agent and device capabilities
• Load from the cache (or DB if we are unlucky) data for the publisher requesting the Imprint impression
• Similarly, check the cache/db for any metadata on the specific article the user is consuming right now
• Determine which advertising campaigns the publisher is part of and then filter those by various targeting criteria
• Compute which Sidelines post to display, based on a non-trivial state-space
• For the particular user, determine the look & feel in order to make Imprint appear as native as possible. This includes main colors, accents, shades, fonts, font sizes, etc
• Render the HTML template to send to the user, including embedding JSON of various metadata pieces that will be hydrated into state for our ReactJS components

Over the past few months, we have slowly been adding more and more features. As a result, our request processing 95th percentile timings have crept uncomfortably high. The average was still OK, but we all know better than to just look at averages, right? Step 1 was wall-clock timings, using l33t techniques such as logger.debug((time.time() - benchmark_begin) * 1000). Of about 1000 iterations, half came back extremely fast and the other half extremely slow which would explain the very low average and high 95th percentile. I rigged the code to capture the state when a request would take more than 50ms and fired up my trusty profiler. Sampling profilers require a large number of iterations to paint an accurate picture, so I bombarded the endpoint with the problematic state.

I was fully expecting the slowdown to be either in the IPC call to the cache or the computation of fonts & colors. To my surprise, the biggest slowdown was translating nested Python data structures to JSON. To remedy the problem, I first micro-benchmarked a few different JSON libraries using relevant data and found that the Python built-in json module was good enough. Then I started gutting out our Python dictionaries, simplifying complex nested relationships and discarding data that is not used by the client. While this limits re-usability a bit, the speed-up is well worth it.

Different performance issues require different remedies. In this case, it was a slowness issue that did not repro all the time but occurred frequently enough to affect important metrics. My debugging methodology was:

1. Timed each suspect code path to try and pinpoint when & where the slowness was occurring.
2. The slowness is usually due to I/O. In this case, it was surprisingly CPU related.
3. Ran the program inside a CPU profiler, using inputs shown to cause slowness in step #1.
4. Took the profiler output and sorted by overall time spent (inclusive). The profiler gave me you the top level function, so drilled down to find the culprit and optimized my code accordingly.

Lesson learned: making performance gains that result in a cool graph is very satisfying.