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 tree with times on it

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:

POST /order (webshop.wsgi_app)
  order()
    shop:OrderService.place(amount=500, card='<redacted>', tenant='acme')
      shop:Gateway.charge(amount=500, card='<redacted>')
      shop:Gateway.charge -> {'id': 'ch_500', 'amount': 500} [8us]
      shop:Ledger.record(entry="<dict {'id': 'ch_500', 'amount': 500}>")
      shop:Ledger.record -> 'led_ch_500' [35.1ms]
    shop:OrderService.place -> {'id': 'ch_500', 'amount': 500} [35.9ms]
  order -> '<Response 29 bytes [200 OK]>' [36.3ms]
webshop.wsgi_app -> '200 OK' [37.3ms, body 10us over 1 chunk]

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:

import wrapture

from shop import Gateway, Ledger, OrderService
from webshop import app


def test_where_the_time_goes():
    place = wrapture.binding(OrderService, "place", capture=wrapture.redact("card"))
    charge = wrapture.binding(Gateway, "charge", capture=wrapture.redact("card"))
    record = wrapture.binding(Ledger, "record")

    with wrapture.instrumentation("flask"), wrapture.timeline(place, charge, record) as tape:
        client = app.test_client()
        response = client.post("/order", json={"amount": 500, "card": "4111-1111-1111-1111", "tenant": "acme"})
        assert response.status_code == 200

        print()
        print(tape.tree(times=True))

        order = place.events.assert_once()[0]
        ledger = record.events.assert_once()[0]
        assert tape.self_time(order) < 0.1 * order.duration
        assert tape.self_time(ledger) > 0.9 * order.duration

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:

shop:OrderService.place(amount=500, card='<redacted>', tenant='acme')  -> {'id': 'ch_500', 'amount': 500}  [31.0ms, self 173us]
  shop:Gateway.charge(amount=500, card='<redacted>')  -> {'id': 'ch_500', 'amount': 500}  [7us]
  shop:Ledger.record(entry={'id': 'ch_500', 'amount': 500})  -> 'led_ch_500'  [30.8ms]

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.

Across many requests

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:

[[window]]
name = "stats"
report = "stats.txt"

[[window.collect]]
type = "aggregate"

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:

aggregate "aggregate" run 1, 2026-09-01 14:57:29 to 14:57:31 +10:00 (1.6s), pid 87241
7 paths, 120 operations begun, 120 completed, 20 raised

calls    total     self  per-call     min     max  errors  path
   10  358.3ms  358.3ms    35.8ms  30.7ms  39.5ms          shop:Ledger.record
   30  385.2ms   11.9ms    12.8ms   534us  40.5ms          flask.app:Flask.wsgi_app
   20  369.8ms    5.7ms    18.5ms   296us  40.1ms          webshop:order
   20  364.1ms    5.7ms    18.2ms   105us  39.9ms      10  shop:OrderService.place
   10    2.2ms    2.2ms     223us    63us   1.6ms          flask:render_template
   10    3.5ms    1.3ms     354us   188us   1.8ms          webshop:quote
   20    106us    106us       5us     4us    11us      10  shop:Gateway.charge

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.

Slow for whom

An endpoint is often slow for one tenant, one account or one request id, and the middleware cannot know which header carries that. annotate() merges values into the in-flight event's data, and it is unconditionally safe to call, doing nothing when nothing is recording, which makes it reasonable to leave in application code permanently. In the shop a before_request hook is the natural place, since the request event is already open by the time it runs:

@app.before_request
def tag_tenant():
    wrapture.annotate(tenant=request.headers.get("X-Tenant"))

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:

$ jq -c 'select(.kind=="request" and .data.tenant=="acme") | {tenant: .data.tenant, path: .data.path, ms: ((.duration*1000*10|round)/10)}' trace.jsonl
{"tenant":"acme","path":"/order","ms":35.7}
{"tenant":"acme","path":"/order","ms":32.5}
{"tenant":"acme","path":"/order","ms":35.9}

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.

The cheaper cousin

Everything above retained a duration. Sometimes the answer is just a number, and the Counter collector counts operations as they begin and keeps nothing else, which makes it cheap enough to leave running under a whole test suite. Bind a database layer's execute once, register a counter, and give every test a query budget in a fixture, and the classic N+1 regression fails with a number attached rather than slipping through as a test that merely got slower. The collectors section of the ad-hoc tracing page has that example in full.

So far every trace has been rendered for a person or written to a file. The remaining step is feeding the same events to a tracing backend while the shop runs.