SQL Server Profiler – SQL achter de schermen

Inleiding

SQL Server Profiler – Met het gebruik van entity framework bestaat het risico dat het schrijven van queries naar de achtergrond verschuift. De kans bestaat dat je uit het oog verliest wat er daadwerkelijk gebeurt en welke impact constructies in EF kunnen hebben op de tijdsduur van requests in je applicatie. In mijn eigen ervaring is in de situatie vòòr object-relational mapping (ORM) frameworks het contact met de database veel directer. Stored procedures of ad hoc queries moest je zelf schrijven, waarbij je bewust verbanden legt tussen tabellen. Tijdens het ontwikkelen ervan voer je de query al snel uit en weet je of het resultaat klopt en of de snelheid in orde is. Met frameworks zoals EF Core, welke we tegenwoordig automatisch in veel projecten toepassen, laat je het maken van de SQL statements over aan de SQL generator. Vaak is de query die daaruit resulteert al redelijk optimaal, of in ieder geval snel genoeg dat het niet uitmaakt. Toch is het goed om te weten waar je kunt beginnen met debuggen als de performance niet voldoende is of wanneer het resultaat niet klopt.

SQL Profiler

De SQL Profiler is volgens mij in een standaard installatie van SQL Server Management Studio (SSMS) standaard aanwezig in het menu Tools:

Na het starten moet je eerst verbinden met een database naar keuze. Het scherm wat daarna volgt is interessanter:

Op het eerste tabblad kun je je trace een specifieke naam geven, maar persoonlijk wijzig ik nooit iets in deze velden. Er gaat vast een hele wereld schuil achter de mogelijke opties, maar deze post is vooral geschreven als pragmatische developer en niet vanuit de rol van “Professional Microsoft SQL Server Profiler”, voor zover dat al bestaat. Op het tweede tabblad begint het pas echt:

Ook hier heel veel mogelijkheden die ik nooit nodig heb gehad. Het belangrijkste dat ik wil laten zien is de knop “Column filters…”. Selecteer eerst “Show all columns”, klik daarna op “Column filters…”. Het filter dat ik het meest gebruik is “DatabaseName”. Dit helpt beperken van welke databases op de server waar je mee bent verbonden het dataverkeer wil bekijken. Zeker op database servers die meerdere databases hosten helpt dit de stroom van gegevens in te perken.

Tip! Als de specifieke database die je wil tracen op hetzelfde moment door veel andere gebruikers of processen gebruikt wordt (bijvoorbeeld als je op een productiemachine iets moet onderzoeken) is het mogelijk om in jouw specifieke connectiestring (bijvoorbeeld als je vanuit Visual Studio de code draait tegen een productiedatabase) de waarde “Application Name=MyAppName;” toe te voegen. Op deze waarde kun je weer filteren via de bovenste optie in dit menu, zodat je alleen requests ziet van jouw eigen sessie. Uitgebreidere informatie staat op https://www.connectionstrings.com/use-application-name-sql-server/.

Het tracen van queries

Als je alle opties hebt ingesteld stroomt het scherm waarschijnlijk al snel vol met events die op de database plaatsvinden. Hier zit heel veel informatie tussen die we voor deze blog negeren. De knoppen in de bovenbalk helpen om de stroom te beperken tot het moment waarop je de handelingen uitvoert die tot de events leiden die je wilt onderzoeken. Mijn aanpak is eerst pauzeren, dan clear. Bereid alle stappen voor zoals bijvoorbeeld inloggen in de applicatie en naar het desbetreffende scherm gaan waar een probleem is met de performance. Start de trace in de profiler tool en voer de handeling uit in de applicatie. Zodra de stap klaar is kun je de trace weer pauzeren.

Voor bovenstaande trace heb ik een simpele select top 100 * gedaan, maar voor complexe queries komt het natuurlijk op hetzelfde neer. Als je handeling heeft geleid tot heel veel output kun je met control+F zoeken op een deel van je instructies. Bijvoorbeeld met EF Core is dit de uitgelezen manier om te achterhalen wat er daadwerkelijk wordt uitgevoerd aan statements.

Een voorbeeld uit de praktijk is dat voor een bepaalde applicatie het laden van een scherm langer duurde dan verwacht. Het resultaat was wel goed, maar de traagheid trok mijn aandacht, mede doordat de op te halen data niet bijzonder complex was. Na uitvoering van de bovenstaande handelingen bleek dat er 100 bijna identieke statements voorbij kwamen in de profiler om 100 regels data te tonen in de applicatie. De code gaf niet direct aanleiding te vermoeden dat er een onlogische query zou worden bedacht door EF Core, maar in de praktijk was dat wel het geval. In plaats van 1x data ophalen en daarna in code structureren in 100 regels data werd er 100x verbinding gemaakt voor 1 regel data!

Conclusie

Met deze informatie heb ik hopelijk een stuk gereedschap laten zien dat kan helpen om meer inzicht te krijgen in (performance)problemen bij ORM frameworks. Hou in gedachten dat EF Core niet foutloos is en dus niet in alle gevallen de meest optimale queries zal genereren. Het kan ook een aanleiding zijn bij langzame queries de Database Engine Tuning Advisor in te zetten. Meer daarover in een volgend blog.