Ook te maken met een performance-degradatie sinds de upgrade naar SQL Server 2022? Bij een van onze klanten stonden hierdoor hele vrachtwagens vol met versproducten op het spel. Edward laat je zien hoe hij het probleem oploste dat werd veroorzaakt door het wait type preemptive_os_queryregistry.
Verschillende database engineers zijn al tegen problemen aangelopen na het upgraden naar SQL 2022. Het is bijvoorbeeld een stuk trager dan voorheen om bepaalde systeemtabellen te raadplegen.
Trace flag 12502
Sinds CU5 is daar een fix voor:
“2351584 – Fixes an issue where high PREEMPTIVE_OS_QUERYREGISTRY waits occur. To apply this fix, you need to turn on trace flag 12502, which is used to disable external authorization policies for on-premises SQL Server instances.”
Met trace flag 12502 disable je External Authorisation Policies. Daarover later meer.
Performancedegradatie na SQL Server 2022
Ook wij zijn hier al een paar keer tegenaan gelopen maar de impact was tot nu toe minimaal. (Geen excessief gebruik van systeemtabellen.) We hadden er vooral zelf last van omdat wij als data engineers veel vaker systeemtabellen raadplegen. Maar onlangs hadden we een klant die door deze bug wel degelijk last had van enorme performance degradatie. Deze klant handelt in versproducten. De druk was hier dan ook groot, want als bij deze klant het handelssysteem praktisch tot stilstand komt, kunnen er uiteindelijk hele vrachtwagens vol met producten zo weggegooid worden.
Deze klant heeft een applicatie die gebruikt maakt van Enterprise Library en specifiek van de method DiscoverParameters() om te achterhalen wat de parameters van een stored procedure zijn.
Achterhalen of je last hebt van deze bug
Er zijn heel veel applicaties die gebruik maken van deze library. Daarom vinden we het belangrijk om te laten zien hoe je achterhaalt of je zelf last hebt van deze bug. De uitleg van Microsoft bij de fix is namelijk heel beperkt. De link tussen QueryRegistry waits en het disablen van “external Authorisation Policies” is niet bepaald intuïtief. (Er is wel een link; die vind je verderop.)Tot slot is dit ook gewoon heel leuk detectivewerk.
Wat meer over wait stats
SQL Server houdt van alle handelingen die uitgevoerd worden bij hoeveel microseconden de server ergens op moet wachten. Er kan op van alles gewacht worden. Op een gebruiker die een record gelocked houdt, op een stukje vrij werkgeheugen, op een datapage die van de disk gehaald moet worden. De lijst is eindeloos. (Nou ja, de lijst eindigt om precies te zijn bij wait type nummer 1.375.)
Van al onze klanten bewaren we meerdere jaren aan performance metrics zodat we goede baselines hebben. Zo kun je met zekerheid zien wat de impact is als de klant, de softwareleverancier of wij iets wijzigen.
Wachttijd in totaal verdubbeld
Dit is de wait statistics grafiek van onze klant op de eerste ochtend ná de migratie naar SQL 2022. De verschillende wait types zijn gestacked. De paarse types zijn de wait times die de klant altijd al had. Het rode wait type is er sinds die dag bij gekomen. Je kunt zien dat deze op de piek load de totale wait time van alle wait types bij elkaar meer dan verdubbelt. Logisch dat de klant een flinke impact ervoer na de upgrade!
Over Preemptive_os_queryregistry
Het gaat hierbij om het wait type: PREEMPTIVE_OS_QUERYREGISTRY. Een wait type dat door SQL Server gebruikt wordt als aan het operation system gevraagd wordt om een actie uit te voeren in het Windows registry. Dit kan zowel lezen als schrijven zijn, vermeldt SQLskills.
Maar wélke queries?
De klant heeft een merkbaar performanceprobleem, we zien in SQL Server duidelijk terug dat wait times zijn verdubbeld. Het is dus zeer waarschijnlijk dat de oorzaak van het probleem binnen de databaseserver gevonden kan worden.
Als je dit ziet is het eerste wat je je afvraagt: welke queries zijn dit dan? Op het eerste gezicht is dat misschien nog niet zo eenvoudig te achterhalen.
Welke onderzoeksmethodiek werkt hier het beste?
Query Store verzamelt wel wait statististics per categorie maar niet gedetailleerd genoeg om per query het wait type te achterhalen.
Speurwerk op de live productieserver
Je kunt met diverse scriptoplossingen op basis van DMV’s een eind komen door een delta te maken van de geaccumuleerde wait statistics als je op een geïsoleerde testserver zit. Maar op een productieserver werken oplossingen op basis van DMV’s niet. Gelukkig kun je dit perfect doen met Extended Events. Als je maar weet hoe.
GUID’s voor gevorderden
Er zijn events voor de statements en events voor de Waitinfo informatie. Je kunt deze events niet standaard aan elkaar correleren. Maar! Dat kan wel als je bij het aanmaken van een Extended Event Sessie deze optie meegeeft: TRACK_CAUSALITY=ON. Wanneer je dit aanzet krijgen alle statements die in de sessie komen een activity GUID. Alle vervolgacties die door zo’n statement worden veroorzaakt, dus ook de waits, krijgen diezelfde GUID mee. Vanaf dat moment kun je statements met hun bijbehorende wait events correleren. En dat is precies wat we hier nodig hebben.
We moeten 5 event types toevoegen aan onze Extended Event sessie om een totaalbeeld te hebben:
- rpc_completed (stored procs, triggers)
- sp_ statement_completed (statements binnen rpc’s
- batch_completed (adhoc batches)
- sql_statement_completed (statements binnen batches)
- wait_info_external (externe waits zoals preemptive waits)
- wait_completed (interne waits)
Deze sessiedefinitie gebruikten wij
Onderstaande sessiedefinitie kun je gebruiken om RPC gerelateerde statements op te sporen. (Wij weten tijdens het schrijven van dit artikel al dat we op zoek zijn naar een stored procedure. Weet je dat nog niet, dan moet je ook de batch based events toevoegen.)
CREATE EVENT SESSION [Twintos_QueryWaits] ON SERVER
ADD EVENT sqlos.wait_completed(
WHERE ([sqlserver].[database_id]=13)),
ADD EVENT sqlos.wait_info_external(
WHERE ([sqlserver].[database_id]=13)),
ADD EVENT sqlserver.rpc_completed(
WHERE ([sqlserver].[database_id]=13)),
ADD EVENT sqlserver.sp_statement_completed(
WHERE ([sqlserver].[database_id]=13))
ADD TARGET package0.event_file(SET filename=N'twintos_Waitstats_withqueries')
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS,MAX_EVENT_SIZE=0 KB,MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=ON,STARTUP_STATE=OFF)
GOWachten op je wait occurrences
Let even op voor je hem start: Op een druk systeem kan dit veel events genereren. Je krijgt een entry per statement én per wait occurrence! Dit is dus geen typische sessie om te starten en dan even naar de barista corner beneden in de hal te lopen.
Na het stopzetten van de sessie open je hem. Voeg de kolommen attach_activity.ID, wait_type, Batch_text, en statement toe. Je ziet nu alle events. (In dit screenshot zie je de events van een nagebootst scenario, op het productiessysteem waren het er aanzienlijk meer. Je kunt in dat geval overwegen om de event files te openen op je laptop.)
Filteren op wait type
Wat we nu moeten doen is een GUID vinden van een activiteit met het wait type PREEMPTIVE_OS_QUERYREGISTRY. We filteren het overzicht dus eerst op dat wait type:
Na filtering hebben we enkel de wait events van het juiste type over. Alle activity ID’s die je hier ziet zijn dus van activiteiten die hebben moeten wachten op een call naar het Windows Registry. We zijn al op de helft!
Nog een keer filteren
Vervolgens kopieer je een GUID uit de attach_activity.id kolom en pas je het filter aan zodat je nu alleen op die activity ID filtert. (En niet meer op waitype.)
Bingo: statement gevonden
Nu zie je voor die specifieke activiteit zowel de statements als de voorafgaande wait type en bingo: we hebben de statement gevonden. Het gaat om de system stored procedure sp_procedure_params_100_managed.
Dit is een procedure die gebruikt wordt door onder andere .Net applicaties die gebouwd zijn met Enterprise Library en gebruik maken van de method DiscoverParameters() om te achterhalen welke parameters een stored procedure heeft.
Kennelijk triggert het uitvoeren van de sp_procedure_params_100_managed een call naar het Windows register. Maar wat precies?
Wat gebeurt er dan op dat moment?
We onderzoeken met Process Monitor wat SQL Server precies doet op het moment dat deze stored procedure wordt afgetrapt:
We stellen Process Monitor zo in dat hij enkel het proces SQLServr.exe meeneemt en enkel acties in het Windows Registry. Alle andere acties filtert hij uit. Let wederom op: Op een druk productiesysteem wil je het filteren op orde hebben vóór je de trace start.
Duizenden keren een registry key openen
We zien bij het uitvoeren van de stored procedure dat SQL Server duizenden keren een registry key probeert te open gerelateerd aan Microsoft Purview. “HKLM\Software\Microsoft\Microsoft SQL Server\MSSQL16.XXXX\MSSQLServer\PurviewConfig”
Microsoft Purview biedt een homogene manier van data governance om het makkelijker te maken toegang tot data die verspreid staat over on premise en cloud dataoplossingen te managen. De bug in SQL Server is dus gerelateerd aan het feit dat in bepaalde scenario’s waar de on premise SQL 2022 server niet onderdeel is van Purview configuratie er toch gezocht wordt naar deze configuratiegegevens.
Trace flag 12502: welke rode berg?
Ik word hier ontzettend blij van. In een eerdere case heeft Microsoft mij uitgelegd dat er verschillende issues zijn in SQL 2022 waarbij SQL Server ondanks dat hij geen onderdeel is van een Azure Purview configuratie toch een Purview configuratie probeert te achterhalen uit het Windows Registry. Een paar van die scenario’s noemde ik al in de introductie. Deze functionaliteit kan simpel uitgezet worden door trace flag 12502 global aan te zetten. De klant had serieus te maken met de mogelijkheid dat er vrachtwagens vol versproducten weggegooid moesten worden. Dan is het lekker als je met het intoetsen van 5 cijfers die rode berg in één klap op kunt lossen.
Kortom:
- Controleer op al je SQL 2022 Servers of je last hebt van PREEMPTIVE_OS_QUERYREGISTRY waits.
- Zo ja, controleer dan met een Extended Event sessie met TRACK_CAUSALITY = ON welke queries dit veroorzaken.
- Overweeg de trace flag aan te zetten. Letop, Dit is niet een standaard supported trace flag. Je moet officieel eerst een support case openen bij Microsoft.