Bepaal zelf dependencies
Een call kan verschillende soorten dependencies hebben, denk bijvoorbeeld aan een database-afhankelijkheid of de afhankelijkheid van een ander (extern) systeem.
In ons geval geeft Application Insights duidelijk inzicht in onze afhankelijkheden en hoeveel tijd eraan besteed is door gebruik te maken van de drill down functionaliteit op het POST-request naar artikel/artikelen.
We zien in het overzicht dat onze call twee dependencies heeft; één is onze eigen back-end, de tweede is het uitvoeren van een SQL-query op onze database. De tweede duurt 50 milliseconden, wat ten opzichte van onze totale request-duur van 31 seconden niet bijzonder veel is.
We gaan dus inzoomen op onze back-end code. Wanneer uit dit overzicht was gebleken dat er veel tijd in een query ging zitten, konden we in Application Insights ook zien welke query dat was. Op die manier kan je makkelijk query optimization toepassen.
Inzoomen met dotTrace
Wie ‘inzoomen op onze back-end code’ zegt, zegt ‘dotTrace’. Of nou ja, niet letterlijk, maar dotTrace maakt het inzoomen wel enorm eenvoudig. Om dit te doen, gaan we onze applicatie vanuit dotTrace opstarten en tracen.
We hebben onze applicatie al eerder lokaal gedraaid, hebben het performance probleem weten te reproduceren en gaan die gebruiken om onze trace op uit te voeren. Dit doen we door dotTrace op te starten, te kiezen voor Profile Local App, vervolgens .NET Core Application en vervolgens in het venster rechts onze instellingen in te voeren.
En oja, vink Collect profiling data from start ook even uit; dit voorkomt ruis. Wanneer we op Run klikken, start onze applicatie en begint de profiler zijn werk te doen. Wanneer je een specifieke actie binnen je applicatie ‘op wil nemen’, klik je in de profiler op Start. Er verschijnt een timeline-grafiek met enkele realtime statistieken. Alles wat je vanaf dat moment doet, wordt gerecord.
De volgende stap is het uitvoeren van de operatie die we verder willen analyseren. In ons geval is dat een zoekactie met een specifieke zoekterm, dus die voeren we uit nadat we in de profiler op Start hebben gedrukt. Na uitvoer van de zoekactie klik je in de profiler op Get Snapshot And Wait.
Tip: hou er rekening mee dat je vanaf het moment dat je op Start drukt, alle requests ‘opneemt’. Het kan dus handig zijn even te wachten tot je applicatie goed en wel is opgestart, dan op Start te klikken en direct je handeling uit te voeren.
De entry-point van de artikel/artikelen call is de methode GetArtikelen. Deze kunnen we opzoeken in de dotTrace snapshot die is geopend. Het gekke is, als we kijken naar de uitvoer van de code, dat deze slechts verantwoordelijk is voor 560 milliseconden terwijl ons request meer dan 20 seconden duurde in totaal. Wat we ook zien is dat er in totaal meer dan 720.000 records op worden gehaald. Blijkbaar zit de voornaamste vertraging dus in het verwerken van 720.000 records door de SQL-client.
Wat gaat er mis?
In een applicatie waar gebruik gemaakt wordt van paginering voor het tonen van zoekresultaten, is het vreemd dat er één enkele query is die blijkbaar meer dan 720.000 records ophaalt. Dit gaat enorm ten koste van de performance van die zoekopdracht, en zal dus moeten veranderen.
Blijkbaar wordt de paginering van de zoekresultaten generiek en client-side opgelost, wat ook direct de oorzaak van ons probleem is. Er zijn overzichten (zoals het overzicht van zoekresultaten) waar meer dan 720.000 records voor worden gevonden, en doordat we client-side paginering gebruiken worden al die records in één klap naar de front-end gestuurd. Dat heeft een beste impact.