Trage code vinden met wrapture

De gebruikelijke aanpak is het gebruik van een stopwatch: een perf_counter() voor en na de service-aanroep, een logregel met het verschil, en een volgend paar rondom de gateway en de ledger. Elk van deze acties vereist een codewijziging in een laag die eigenlijk niet zou moeten weten dat hij wordt gemeten. Bovendien komen de getallen binnen als afzonderlijke logregels die je handmatig moet correleren, en geen van deze gegevens is gekoppeld aan het specifieke verzoek waartoe ze behoren. Hierdoor is één traag verzoek tussen veel snelle verzoeken onzichtbaar in het gemiddelde. Een profiler heeft het tegenovergestelde probleem: deze ziet elk frame in het proces (waarvan het merendeel framework-internals zijn) en kan het ene verzoek niet onderscheiden van het volgende.

De boom met tijden

De configuratie uit het vorige bericht print al een verstreken tijd op elke sluitingsregel. De eerste order via de server geeft dus direct een groot deel van het antwoord:

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]

Als we van onder naar boven lezen, zien we dat het verzoek 37,3 ms duurde, de view 36,3 ms, de service 35,9 ms en de ledger 35,1 ms, terwijl de gateway slechts 8 $\mu$s in beslag nam. De cijfers zijn afkomstig uit één run en ze variëren, maar het patroon blijft gelijk. De ledger is verantwoordelijk voor vrijwel de gehele tijd van de service, die op zijn beurt verantwoordelijk is voor vrijwel de gehele tijd van de view. De service en de view zijn traag vanwege wat ze aanroepen; de ledger is echter inherent traag.

Dat onderscheid — traag op zichzelf versus traag vanwege een onderliggend proces (een 'child') — is iets wat een eenvoudige timer rondom de service-aanroep niet kan uitdrukken. Dit heeft een naam: self time. Self time is de duur van een operatie minus de tijd die de geobserveerde children in beslag nemen. wrapture berekent dit op basis van de parent-links zodra events sluiten.

In een test print tape.tree(times=True) beide waarden en geeft tape.self_time() de waarde voor één event. Zo kan dezelfde observatie worden omgezet in een assertie die de volgende regressie direct opvangt:

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

De context wrapture.instrumentation("flask") past dezelfde Flask-instrumentatie toe als in het configuratiebestand, maar dan beperkt tot dit blok. De timeline registreert wat de drie bindings zien. Wanneer dit wordt uitgevoerd met pytest -s, wordt de volgende boom geprint:

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]

De service besteedde slechts 173 $\mu$s van de 31,0 ms aan eigen werk. Geen enkele externe profiler kan dit getal produceren voor een willekeurige selectie van methoden, omdat een profiler alleen volledige call-stacks ziet; wrapture kan dit wel, omdat de events hun parents kennen.

Over meerdere verzoeken

Eén verzoek is slechts een anekdote. De Aggregate collector houdt per gebonden locatie één rij bij met informatie over hoeveel operaties zijn gestart en voltooid, hoeveel er een fout hebben opgeleverd, en de totale, self, snelste en traagste tijden. Deze worden gesorteerd op self time, de kolom waarop profilers doorgaans ranken. De collector bewaart geen individuele events, waardoor het geheugengebruik beperkt blijft tot het aantal bindings, ongeacht de hoeveelheid verkeer. Bovendien vraagt het niet om argument- of resultaatwaarden, waardoor de recording de capture-stap volledig overslaat wanneer dit de enige luisteraar is.

Hoewel dit in code als een sink kan worden geregistreerd, is voor een rapport over de gehele runtime van de server een window in het configuratiebestand geschikter:

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

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

Een window zonder trigger en zonder duur loopt gedurende het hele proces; het opent wanneer de configuratie wordt toegepast en sluit bij het afsluiten van de interpreter, wat resulteert in één rapport. Ik heb de server met deze configuratie gedraaid, dertig verzoeken gestuurd vanuit een loop (tien orders voor één tenant, tien geweigerde orders voor een andere, en tien offertes), de server gestopt en het bestand gelezen:

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

De ledger staat met een ruime marge bovenaan. De order-view en de place-methode hebben grote totalen maar kleine self times, wat hetzelfde verhaal vertelt als de individuele boom, maar nu over twintig orders met minimum- en maximumwaarden. De kolom errors toont de tien geweigerde kaarten twee keer: eenmaal waar de gateway een uitzondering wierp en eenmaal waar de service deze doorliet. Door een schema aan de window toe te voegen, kan hetzelfde rapport elk uur worden gegenereerd met geresette totalen.

Traag voor wie?

Een eindpunt is vaak traag voor slechts één specifieke tenant, één account of één request ID, en de middleware weet niet welk header-veld deze informatie bevat. annotate() voegt waarden samen in de data van het actieve event. Het is onvoorwaardelijk veilig om aan te roepen; als er niets wordt geregistreerd, doet het simpelweg niets. Dit maakt het zinvol om het permanent in de applicatiecode te laten staan. In de shop is een before_request hook de natuurlijke plek, aangezien het request-event al open is op het moment dat deze wordt uitgevoerd:

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

Dit is de enige aanpassing aan de applicatie in deze serie. De tag is gekoppeld aan het request-event. Met een jsonlines sink in de configuratie komt dit in het bestand terecht, waardoor trage verzoeken kunnen worden gefilterd op basis van de eigenaar:

$ 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}

De orders van de andere tenant werden allemaal geweigerd bij de gateway en bereikten de ledger nooit, waardoor ze rond de ene milliseconde bleven steken. Dezelfde expressie kan worden gebruikt om in een test een specifiek verzoek te selecteren via events.matching(), en een Filter rondom een printer kan de live weergave beperken tot de verzoeken van één tenant.

De goedkopere variant

Alle bovenstaande methoden hielden de duur van de operatie bij. Soms is het antwoord echter simpelweg een aantal. De Counter collector telt operaties zodra ze beginnen en bewaart verder niets. Dit is goedkoop genoeg om continu te laten draaien tijdens een volledige testsuite.

Bind bijvoorbeeld de execute-methode van een database-laag één keer, registreer een counter en geef elke test een query-budget in een fixture. De klassieke N+1 regressie zal dan falen met een specifiek getal, in plaats van dat de test simpelweg onopgemerkt iets trager wordt. Een volledig voorbeeld hiervan is te vinden in de sectie over collectors op de pagina over ad-hoc tracing.