Nog even over SQLite

Ik heb eerder al eens een artikel geschreven over SQLite, maar ondertussen ben ik verder gegaan met mijn onderzoek. Niet omdat MySite traag aanvoelt, integendeel. Het is vooral mijn testworkload voor Mprjv65 en de laatste tijd ben ik veel bezig geweest met observability. Daardoor ben ik beter gaan begrijpen waar de tijd binnen een HTTP-request daadwerkelijk naartoe gaat.

Uiteindelijk kwam ik uit op een eenvoudige opdeling:

HTTP request
├─ DB queries
├─ Template rendering
├─ Markdown rendering
└─ Overige verwerking

SQLite: sneller dan verwacht

Over mijn databasesetup kan ik eigenlijk kort zijn. Ik gebruik SQLite in combinatie met DBIx::Class. Waarschijnlijk omdat MySite voornamelijk leesacties uitvoert, blijkt dat verrassend snel te zijn. Op mijn ontwikkelomgeving staat de SQLite-database op een lokaal filesystem. De meeste query’s worden daar in minder dan 1 milliseconde afgehandeld. Per pagina doe ik gemiddeld vijf tot tien database-opvragingen, maar binnen een complete HTTP-request van grofweg 200 tot 300 milliseconden zijn die kosten praktisch verwaarloosbaar.

Op productie ligt dat anders. Daar draait dezelfde applicatie in een container en staat de database op een NFS-share. Dat merk je direct. Query’s duren daar eerder 5 tot 10 milliseconden. Nog steeds niet schokkend, maar zeker niet meer gratis. Uiteindelijk blijkt de database ongeveer 15-20% van de totale requesttijd voor zijn rekening te nemen.

Dat is overigens geen argument tegen SQLite. Als er al een boosdoener is, dan is het eerder de opslaglaag dan de database zelf.

Template rendering als onverwachte verdachte

Wat mij veel meer verraste was template rendering.

Van alle componenten die ik kon meten bleek dit vaak de grootste bekende kostenpost. Zelfs groter dan markdown rendering, terwijl ik juist markdown als hoofdverdachte had aangemerkt. Dat voelde vreemd. Ik gebruik immers Template Toolkit, en dat staat niet bepaald bekend als een trage template-engine.

Pas toen ik langer naar de Grafana-grafieken zat te kijken viel het kwartje.

De template-renderingtijd die ik meet is niet alleen de tijd die Template Toolkit nodig heeft om een template te verwerken. Het is de volledige tijd die Dancer2 binnen de template-engine doorbrengt. Alles wat vanuit het template wordt aangeroepen telt daarin mee.

Dus als een template:

• Markdown rendert
• Datums formatteert
• Database-opvragingen doet
• Helper-functies aanroept

dan wordt die tijd gewoon bij de template-rendering opgeteld.

Geen wonder dus dat template rendering duurder leek dan verwacht. In mijn applicatie wordt markdown vrijwel altijd vanuit een template aangeroepen en wordt die tijd dus onderdeel van de template-meting.

Markdown blijft duur

Gelukkig had ik aparte metingen voor markdown rendering, waardoor ik het verschil eenvoudig kon uitrekenen.

Gemiddelde productiemetingen

Component	Tijd/request	Percentage
HTTP totaal	350 ms	100%
Database	63 ms	18%
Template incl	187 ms	53%
Template self	91 ms	26%
Markdown	96 ms	27%
Overig	100 ms	29%

Template incl bevat markdown rendering. Percentages tellen daarom niet op tot 100%.

Wat direct opvalt is dat markdown-rendering ondanks alle aandacht voor de database nog steeds één van de grootste afzonderlijke kostenposten is.

Dat is overigens geen verrassing. Ja, er bestaan Perl-modules voor markdown rendering. Die zijn meestal ook een stuk sneller. Maar ik ben verwend geraakt door alles wat GitHub tegenwoordig ondersteunt. Tabellen, codeblokken, uitgebreide markdown-constructies, noem maar op.

Daarvoor gebruik ik Pandoc.

Pandoc ondersteunt een veel rijkere markdown-definitie dan de meeste Perl-modules. Het nadeel is dat er geen native Perl-oplossing bestaat. Voor iedere rendering start ik daarom een extern Pandoc-proces.

Dat betekent:

Perl
  ↓
fork
  ↓
Pandoc
  ↓
HTML
  ↓
terug naar Perl

En dat kost tijd.

Zoveel tijd zelfs dat ik markdown-rendering voor descriptions en abstracten al eerder had uitgeschakeld. Een overzichtspagina met tientallen artikelen betekende ook tientallen markdown-renders. Dat werd simpelweg te duur.

Eerst dacht ik aan caching

Mijn eerste gedachte was caching.

Dancer2 biedt daar genoeg mogelijkheden voor. Je kunt complete routes, objecten of datastructuren cachen in bijvoorbeeld Redis of Memcached.

Maar caching heeft altijd een prijs:

• cache warming
• cache invalidatie
• cache misses
• extra infrastructuur

Allemaal oplosbaar, maar ook allemaal extra complexiteit.

Waarom niet gewoon HTML opslaan?

Toen begon ik naar de cijfers te kijken: SQLite blijkt relatief goedkoop, en ik moet de data toch uit de database ophalen.

Dus waarom zou ik markdown ophalen en daarna renderen, als ik ook direct HTML kan ophalen?

Markdown blijft dan de bron van waarheid. Daar wil ik niet aan tornen. Maar tijdens het opslaan van een artikel zou ik eenvoudig ook een gerenderde HTML-versie kunnen opslaan.

Zoiets als:

body_md     ← source of truth
body_html   ← gegenereerde versie

De auteur betaalt dan de prijs van het renderen tijdens het opslaan.

De bezoeker hoeft daarna alleen nog maar de HTML-versie op te vragen.

Geen Pandoc. Geen fork. Geen rendering. Gewoon uitlezen en tonen.

Hetzelfde principe kan ik toepassen op descriptions en abstracten. Dan zijn die ook weer terug als gerenderde content.

En dan hebben we het gat nog

Als je naar de breakdown van een request kijkt dan zie je ook een categorie die grofweg 1/3 de request tijd voor zijn rekening neemt. Bij gebrek aan beter heb ik die maar overig genoemd. Goede kandidten voor deze categorie zijn bijvoorbeeld:

• routing binnen Dancer2
• request- en response-opbouw
• middleware
• netwerk- en opslaglatency
• framework-overhead

Maar eigenlijk weet ik nog niet wat daar gebeurt. Met ongeveer 100 milliseconde per request is dit zelfs de grootste afzonderlijke kostenpost, die ik bovendien momenteel niet kan verklaren. Juist daardoor is dit waarschijnlijk het interessantste onderwerp voor verder onderzoek.

De grenzen van Prometheus

De getoonde verdeling komt van een korte testrun. Memcached clearen en dan wat rondklikken op de site. Alhoewel een run over langere tijd betere data oplevert heb ik dit niet gedaan. Gedurende de dag komen er nogal wat scrapers langs. Search engines, die van harte welkom zijn, leveren goed data op. Ze bezoeken mijn pagina’s. Maar er is ook een andere categorie scrapers: de script kiddies en en andere kwaad willenden. Op zoek naar gaten in de Wordpress installaties op het internet. Die leveren alleen maar 404’s op, maar tellen wel als request. En prometheus werkt met gemiddelden. Dit heeft dan tot gevolg dat het grotere aantal requests gedeeld wordt door, bijvoorbeeld, het aantal database queries van de meer legitieme requests. En dat vertekende het beeld. Zeker bij een site die eigenlijk niet zo vaak bezocht wordt en de minder legitieme requests een onredelijk groot aandeel in de requests hebben.

Ik kan mijn verzamel tactiek hierop aanpassen uiteraard, de script kiddies gaan herkennen. Dan krijg ik waarschijnlijk een aparte categorie voor dit soort requests, weet ik gelijk hoeveel last je er nu eigenlijk van hebt. Maar er is meer…

Prometheus is fantastisch om trends en gemiddelden zichtbaar te maken. Het laat me snel zien waar tijd gemiddeld wordt besteed. Maar zodra ik wil begrijpen waarom één specifieke request traag was, loop ik tegen de grenzen van metrics aan. Een gemiddelde vertelt immers niets over individuele uitschieters.

Loki, een andere manier van kijken.

Ik maak voor elke request een ID aan. En zolang ik mij binnen het Dancer2 framework bevindt kan ik die ID meegeven aan het event wat naar Loki gaat.

Daarna kan ik dus aan Loki een vraag stellen als “Maak een overzicht per request op kosten” en daarna “Geef mij alle events waarvan de request a1ff484… is” van de duurste events.

Daar zit echter een probleem in. dBIC::Class zit niet in de Dancer2 context. De manier waarop ik het request ID op dit moment deel werkt niet, omdat dat alleen binnen Dancer2 werkt.

Ik moet dus een manier verzinnen om de request ID wel beschikbaar te krijgen in de dBIC::Class context.

Dit begint al heel erg op tracing te lijken. Termen als OpenTelemetry of Jaeger komen voorbij in mijn hoofd. Misschien is het ook tijd om wat aandacht aan die onderwerpen te geven.

Een andere tweede aanpak?

Loki en request-correlatie helpen om te begrijpen welke request tijd kost. Maar ze vertellen nog niet altijd welke code die tijd verbruikt.

Dat bracht me op een andere associatie… Borland Pascal.

Ik was één van die gelukkige mensen die de beschikking had over de professional versie, en daar zat een profiler bij. En een profiler gebruik je om er achter te komen waar code nu eigenlijk zijn tijd aan besteedt.

Perl heeft, naar ik heb gehoord, ook een profiler. Misschien een goed moment om die te onderzoeken. Eens zien of ik langs die weg “het gat” kan verklaren en daarna meetbaar kan maken.

De conclusie

Observability heeft dus niet alleen geholpen om problemen te vinden. Het heeft vooral geholpen om de juiste vragen te stellen.

Ik begon met SQLite en eindigde bij markdown rendering, request-correlatie, tracing en zelfs profilers. Onder elke laag die ik afschil blijkt weer een nieuwe laag te zitten. Misschien is dat nog wel de leukste ontdekking van allemaal.

Voorlopig wijst alles erop dat de grootste winst niet zit in sneller renderen, maar in minder vaak renderen. De HTML-opslaglaag lijkt daarvoor een logische volgende stap. Daarnaast ben ik inmiddels minstens zo nieuwsgierig geworden naar het onverklaarbare gat van ongeveer 100 milliseconde per request.

Ik hoef het alleen nog maar te bouwen. 😉