Finding Slow Code with Wrapture
Recorded: Sept. 12, 2026, 1 p.m.
| Original | Summarized |
Finding slow code with wrapture - Graham Dumpleton Graham Dumpleton Home Posts Guides Labs About Finding slow code with wrapture 10 September 2026 python wrapture tracing performance The /order endpoint of the Flask shop is slow. The view calls the order service, the service calls the gateway and then the ledger, and the question is which of those the time is going to. To give the question a real answer for this post I put a time.sleep(0.03) in Ledger.record, and the rest of the post pretends I did not know that. Reading up from the bottom, the request took 37.3ms, the view 36.3ms, the service 35.9ms, and the ledger 35.1ms, with the gateway at 8us. The figures are from one run, and they vary, but the shape does not. The ledger accounts for essentially all of the service, which accounts for essentially all of the view. The service and the view are slow because of what they call. The ledger is slow in its own right. from shop import Gateway, Ledger, OrderService def test_where_the_time_goes(): with wrapture.instrumentation("flask"), wrapture.timeline(place, charge, record) as tape: print() order = place.events.assert_once()[0] The wrapture.instrumentation("flask") context applies the same Flask instrumentation the config file named, scoped to the block, and the timeline records what the three bindings see. Running it with pytest -s prints the tree: The service spent 173us of its 31.0ms doing anything itself. No external profiler can produce that number for an arbitrary handful of methods, because a profiler only sees whole call stacks; wrapture can, because the events know their parents. [[window.collect]] A window with no trigger and no duration is one run for the whole process, opened when the config applies and closed at interpreter exit, one report. I ran the server under that config, sent it thirty requests from a loop (ten orders for one tenant, ten declined orders for another, and ten quotes), stopped it, and read the file: calls total self per-call min max errors path The ledger is the top row by a wide margin. The order view and place have large totals and small self times, which is the same story the single tree told, now over twenty orders with a minimum and maximum attached. The errors column shows the ten declined cards twice, once where the gateway raised and once where the service let it escape. The same report can be produced every hour on the hour with totals reset, from the same file, by giving the window a schedule; the scheduled tracing page covers that, and I will leave it there. This is the one edit to the application in this series, and it is the same annotate() the testing series used to attach what the code knows to an event. The tag rides on the request event, so with a jsonlines sink in the config beside the printer it is in the file, and the slow requests can be sliced by who they were for: The other tenant's orders were all declined at the gateway and never reached the ledger, so they sit around a millisecond. The same expression selects the request to assert on in a test, through events.matching(), and a Filter around a printer narrows the live view to one tenant's requests. Back to All Posts Home Graham Dumpleton Software developer, open source creator, and technical education advocate. Quick Links All Posts All Guides About Me Sponsor Me © 2007-2026 Graham Dumpleton. All rights reserved. |
Graham Dumpleton explores methods for accurately identifying performance bottlenecks in layered systems, addressing the limitations of traditional timing and profiling techniques. In typical web service architectures, such as a Flask application interacting with services like an Order Service, a Gateway, and a Ledger, measuring time using simple wall-clock timers across different layers provides fragmented data that is difficult to correlate with specific request contexts or pinpoint the source of latency. This approach fails to distinguish between time spent executing code versus time spent waiting for subordinate operations, making it challenging to determine if a perceived slowdown is intrinsic to a module or caused by its dependencies. Wrapture introduces a mechanism to solve this problem by capturing internal timing information through event relationships, focusing on the concept of self time. Unlike external profilers that focus on call stacks and internal framework details, wrapture allows events to know their parent origins, enabling the calculation of self time for any specific operation. Self time is defined as an operation's duration minus the time accounted for by all the events it spawned, thereby isolating the execution time directly related to that specific operation, independent of its children’s execution time. This distinction allows for creating assertions, such as verifying that a specific operation spent a certain proportion of its duration performing its own work versus waiting for other parts of the execution flow. The practical application of wrapture involves instrumenting components of the application, such as the Flask framework, and linking specific operations, like charging or recording ledger entries, into a timeline. This instrumentation allows for a detailed reconstruction of event flows across multiple requests, revealing how time is distributed throughout the system. By aggregating data across numerous requests, the method moves beyond anecdotal single-request measurements to provide a systemic view. This aggregation can be structured into reports that summarize operation counts, total time, and self-time statistics for entire server runs, allowing for historical performance analysis, including scheduled reporting. Furthermore, the framework addresses the issue of context—determining which specific request or tenant caused the slowdown. Since middleware often cannot easily access request-specific headers within ongoing events, wrapture employs annotation capabilities. This allows contextual data, such as tenant identifiers, to be attached to in-flight events, typically via hooks like before_request. This ensures that tracing events carry the necessary context, enabling subsequent filtering and reporting to isolate performance metrics for a single tenant or specific request ID. This contextualization allows operators to slice the aggregated performance data to pinpoint slow requests based on specific attributes. In scenarios where only a quantitative measure of duration is required rather than a detailed tracing of event relationships, an alternative approach involving counters can be utilized. This method focuses on counting operations as they commence, providing a cost-effective way to measure execution time, which is particularly useful for diagnosing regression issues, such as identifying N+1 query problems with an attached timing budget. Ultimately, the methodology provides a comprehensive system for capturing, contextualizing, and reporting performance data from complex, asynchronous execution flows, a process that requires feeding the generated events into a suitable tracing backend for complete analysis. |