// HACKER NEWS — CYBERSECURITY
Finding Slow Code with Wrapture
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.
The usual move is a stopwatch. A perf_counter() before and after the service call, a log line with the difference, another pair around the gateway, another around the ledger. Each of those is a code change in a layer that should not know it is being measured, the numbers arrive as separate log lines that you correlate by eye, and none of them are tied to the request they belong to, so one slow request among fast ones is invisible in the average. A profiler has the opposite problem: it sees every frame in the process, most of them framework internals, and cannot tell one request from the next.
The config from last time already prints an elapsed time on every closing line, so the first order through the server is most of the answer:
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.
That distinction, slow itself versus slow because of a child, is the one a wall-clock timer around the service call cannot express, and it has a name. Self time is an operation's duration minus the time its observed children account for, and wrapture computes it from the parent links as events close. In a test, tape.tree(times=True) prints both figures and tape.self_time() gives it for one event, so the same observation can be turned into an assertion that will catch the next regression:
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.
One request is an anecdote. The Aggregate collector keeps one row per bound location, with how many operations began and completed, how many raised, and the total, self, fastest and slowest times, sorted by self time, which is the column profilers rank by. It retains no events, so its memory is bounded by the number of bindings however much traffic flows, and it asks for no argument or result values, so the recording skips capture entirely while it is the only thing listening. It can be registered as a sink in code, but the shape I wanted was a report for the whole run of the server, which is a window in the config file:
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:
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.