Kada vise CPU-a nije pomoglo: pracenje SQL Server THREADPOOL gladovanja do jedne SET opcije

Produkcijski Microsoft SQL Server je povremeno prestajao da odgovara.

Nije postojao jasan raspored niti ocigledan obrazac opterecenja. Izmedu incidenata, ista baza podataka je mogla da radi normalno, sto je postincidentno otklanjanje problema cinilo uglavnom neodlucnim.

Pre nego sto smo se mi ukljucili, tim klijenta je vec probao najocigledniju meru: povecanje kapaciteta servera. Dodeljeno je vise memorije i dodatna CPU jezgra su dodata.

Zastoji su se nastavili.

Nismo nastavili sa skaliranjem servera. Cinjenica da dodatni kapacitet nije promenio ponasanje bila je sama po sebi korisna indicija. Poceli smo da prikupljamo sta SQL Server radi tokom incidenta i umesto toga pratili smo wait-ove i blocking chain.

Koren problema se na kraju sveo na jednu nepotrebnu liniju unutar cesto izvrsavane stored procedure:

1

SET ANSI_WARNINGS OFF;

Uklanjanje te linije zaustavilo je incidente.

Promena koda bila je trivijalna. Pronaci je nije.

Problem

Sa strane aplikacije, kvar je izgledao kao ozbiljno preopterecena baza podataka.

Tokom incidenta:

• novi upiti su postajali izuzetno spori ili su prestajali da napreduju;
• aktivni i cekajuci zahtevi su se brzo gomilali;
• na kraju je moglo biti ukljuceno vise od hiljadu sesija;
• baza podataka je postajala prakticno nedostupna;
• kada bi incident prosao, SQL Server bi se vratio na naizgled normalan rad.

Skaliranje servera moze da zvuci kao najrazumniji odgovor na ovakav simptom. Ako baza izgleda zasiceno, dodavanje CPU-a ili memorije je laka hipoteza za testiranje.

U ovom slucaju to je vec bilo testirano, pre nego sto je nase ispitivanje pocelo, i nije resilo problem.

To je pomerilo pitanje sa kapaciteta na konkurenciju:

Sta je sprecavalo zahteve da se zavrse dovoljno dugo da server ostane bez radnika?

Prvi koristan trag: THREADPOOL

Pocetna analiza je pokazala THREADPOOL wait-ove.

1

THREADPOOL

SQL Server prijavljuje THREADPOOL kada task ceka worker thread. Microsoft napominje da se to najcesce desava kada izvrsavanja traju neuobicajeno dugo i smanjuju broj radnika dostupnih za drugi posao.¹

Dakle, THREADPOOL je objasnjavao zasto je server na kraju postao neodgovarajuci, ali ne i sta je pokrenulo incident.

Vidljiv kvar je otprilike izgledao ovako:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

zahtevi prestaju da se zavrsavaju
        ↓
aktivni zahtevi se gomilaju
        ↓
radnici ostaju zauzeti
        ↓
dostupni radnici se iscrpljuju
        ↓
THREADPOOL
        ↓
novi posao ne moze da napreduje

Promena max worker threads u ovoj fazi bi tretirala zavrsnu etapu kvara, umesto da objasni zasto je toliko radnika bilo zauzeto.

Microsoft takode opisuje max worker threads kao naprednu opciju i preporucuje da SQL Server-ova automatska konfiguracija ostane na snazi za vecinu sistema.²

Morali smo da idemo dalje uzvodno.

  flowchart TD
    A["SQL Server povremeno postaje neodgovarajuci"] --> B["Tim klijenta povecava CPU i memoriju"]
    B --> C["Incidenti se nastavljaju"]

    C --> D["Techpipe istrazivanje pocinje"]
    D --> E["Sakupljanje zahteva, wait-ova i blokiranja tokom incidenta"]
    E --> F["THREADPOOL detektovan"]
    F --> G["Pronaci zasto su radnici zauzeti"]
    G --> H["Pratiti blocking chain"]
    H --> I["Blokirani resurs pokazuje na stored proceduru"]
    I --> J["Ispitati konkurenciju pri kompajliranju"]

Hvatanje kvara dok se desava

Incident je bio povremen, pa je obican snapshot performansi uzet deset minuta kasnije imao ogranicenu vrednost.

Dodali smo monitoring oko stanja kvara i prikupili:

• aktivne sesije i zahteve;
• trajanje i status zahteva;
• trenutne wait-ove;
• odnose blokiranja;
• blokirane resurse.

Kada je incident jednom uhvacen, razmera nagomilavanja je postala jasna. Veliki broj sesija je cekao, ali blocking chain u pocetku nije izgledao kao tipican SQL Server locking problem.

Nije bilo ocigledne transakcije koja sedi na row ili table lock-u nekoliko minuta.

Sto je jos zbunjujuce, sesija na vrhu blocking chain-a mogla je da se pojavi bez korisnog wait type-a:

1
2

wait_type = NULL
status    = runnable

Samo gledanje kolone sa wait type-om nije nam govorilo sta je toj sesiji bilo potrebno.

Blokirani resurs jeste.

Pracenje resursa umesto wait type-a

Informacije o blokiranju su iznova ukazivale na isti objekat.

Nije bila tabela ili indeks. Bila je stored procedura.

To je promenilo smer istrazivanja.

SQL Server ima specifican obrazac blokiranja oko kompajliranja stored procedure. Microsoft dokumentuje slucajeve u kojima jedna sesija dobije ekskluzivni compile lock dok druge sesije koje pokusavaju da izvrse istu proceduru cekaju iza nje. Trenutni blocker moze da prikaze waittype = NULL, a uloga head blocker-a moze da prelazi sa jedne sesije na drugu kako svako kompajliranje napreduje.³

Wait resource u ovom tipu incidenta moze identifikovati zahvaceni objekat kao compile resurs:

1

OBJECT: <database_id>:<object_id> [[COMPILE]]

To se mnogo bolje poklapalo sa ponasanjem koje smo videli nego prvobitna pretpostavka o opstem pritisku na resurse.

Problem je sada bio uzi:

Zasto su se istovremena izvrsavanja ove konkretne stored procedure stalno ukljucivala u kompajliranje?

Kada kompajliranje postane problem konkurentnosti

Kompajliranje stored procedure samo po sebi obicno nije problem.

SQL Server moze da kompajlira proceduru, kesira njen execution plan i ponovo koristi taj plan za kasnija izvrsavanja. U normalnim uslovima, stotine ili hiljade poziva ne znace stotine ili hiljade kompajliranja.

Situacija se menja ako statement stalno zahteva recompilation.

Sa dovoljno istovremenih pozivaca, kompajliranje moze da postane tacka serijalizacije. Microsoft opisuje kako compile lock-ovi mogu da nateraju mnoge sesije koje izvrsavaju istu stored proceduru da blokiraju dok je ekskluzivni compile lock zadrzan.³

To daje potpuno drugaciji oblik kvara od jednostavno skupog upita.

Pojedinacni poziv procedure ne mora da trosi ekstremne kolicine CPU-a.

Dovoljno je da se dovoljno pozivaca redja iza iste tacke.

U nasem slucaju putanja kvara je postajala jasnija:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

cesto izvrsavana stored procedura
        ↓
ponovljena recompilation
        ↓
compile-lock konkurencija
        ↓
istovremeni zahtevi se gomilaju
        ↓
radnici ostaju zauzeti
        ↓
THREADPOOL

Sada smo razumeli mehanizam.

I dalje nismo znali zasto se procedura recompajlira.

  flowchart TD
    A["Mnogo istovremenih poziva"] --> B["Cesto izvrsavana stored procedura"]
    B --> C["SET ANSI_WARNINGS OFF"]
    C --> D["SET opcija menja execution context"]
    D --> E["Recompilation statement-a"]
    E --> F["Compile-lock konkurencija"]
    F --> G["Istovremena izvrsavanja cekaju u redu"]
    G --> H["Blocking chain raste"]
    H --> I["Radnici ostaju zauzeti"]
    I --> J["Iscrpljivanje worker pool-a"]
    J --> K["THREADPOOL"]
    K --> L["SQL Server postaje neodgovarajuci"]

    C --> M["Ukloniti nepotrebnu SET naredbu"]
    M --> N["Obrazac recompilacije nestaje"]
    N --> O["Compile konkurencija prestaje"]
    O --> P["Incidenti prestaju"]

Extended Events je identifikovao uzrok recompilacije

Ovde su Extended Events dali nedostajuci deo.

SQL Server izlagje dogadjaj:

1

sql_statement_recompile

za recompilation na nivou statement-a.

Jos vaznije za ovo istrazivanje, dogadjaj ukljucuje recompile_cause. Microsoft dokumentuje vise mogucih vrednosti, ukljucujuci promene schema i statistics, deferred compilation, promene na temporary table-u, eksplicitni OPTION (RECOMPILE), i ⁴:

1

SET option changed

To je bio zabelezeni razlog za zahvacenu proceduru.

Time su odjednom eliminisane vise verovatnih puteva istrage. Više nismo trazili deployment sheme, statistics churn, pritisak na plan cache ili eksplicitni hint za recompile.

Poceli smo da gledamo execution context procedure.

Koren problema bila je jedna SET naredba

Procedura je sadrzala:

1

SET ANSI_WARNINGS OFF;

ANSI_WARNINGS je SET opcija na nivou sesije. Microsoft dokumentuje da se njena vrednost primenjuje u vreme izvrsavanja i da utice na trenutnu sesiju.⁵

Extended Events trag je pokazao recompilation sa:

1

SET option changed

a pregled procedure je vodio nazad do promene ANSI_WARNINGS.

U tom trenutku smo proverili da li procedura zapravo zavisi od ANSI_WARNINGS OFF.

Nije.

Naredba je bila zaostali kod i mogla je da se ukloni bez promene potrebne logike procedure.

Pre

1
2
3
4
5
6
7
8

CREATE PROCEDURE dbo.ProcessSomething
AS
BEGIN
    SET ANSI_WARNINGS OFF;

    -- logika procedure
    ...
END;

Posle

1
2
3
4
5
6

CREATE PROCEDURE dbo.ProcessSomething
AS
BEGIN
    -- logika procedure
    ...
END;

Stvarna produkcijska promena je u sustini bila:

1

- SET ANSI_WARNINGS OFF;

Nije bilo potrebe za povecavanjem max worker threads, dodavanjem vise CPU-a ili redizajniranjem procedure.

Rezultat

Nakon uklanjanja nepotrebne SET naredbe, uoceni obrazac recompilacije je stao.

Compile konkurencija je nestala zajedno sa njim. Veliki blocking chain-ovi su prestali da se formiraju, worker starvation se vise nije razvijao i periodicni SQL Server zastoji se nisu vratili.

Server koji je vec dobio vise CPU-a i RAM-a je popravljen brisanjem jedne linije T-SQL-a.

Koristan deo ovog slucaja nije bila velicina popravke. Bio je to put kojim je pronadjen.

Stvarni lanac kvara

Kada su svi dokazi bili dostupni, incident je mogao da se rekonstruiše od uzroka do simptoma:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19

SET ANSI_WARNINGS OFF
        ↓
SET execution context changes
        ↓
recompilation statement-a
        ↓
compile-lock konkurencija
        ↓
istovremena izvrsavanja cekaju u redu
        ↓
veliki blocking chain
        ↓
radnici ostaju zauzeti
        ↓
iscrpljivanje worker pool-a
        ↓
THREADPOOL
        ↓
SQL Server postaje prakticno nedostupan

Pritisak na CPU i memoriju pojavio se pri kraju ovog lanca.

Zbog toga ranija povecanja resursa nisu uklonila uslov kvara. Mogla su da promene koliko opterecenja server trpi pre nego sto stigne do istog stanja, ali nisu uklonila tacku serijalizacije koja je stvarala red.

Zasto je ovaj problem bilo lako pogresno dijagnostikovati

Nekoliko stvari je cinilo da incident izgleda konvencionalnije nego sto jeste.

Bio je povremen

Vecina korisnih dokaza postojala je samo dok je baza podataka kvarila. Cim bi se blokiranje razresilo, obicne server metrike su izgledale mnogo manje zanimljivo.

THREADPOOL je bio stvaran, ali je bio nizvodno

SQL Server je zaista imao premalo dostupnih radnika.

To je bila tacna opservacija. Samo nije bila koren problema.

Head blocker nije izgledao ocigledno blokiran

Blocker sa praznim wait type-om ne ukazuje odmah na kompajliranje. Pracenje blokiranog resursa bilo je korisnije od zurenja u wait_type.

Nije bilo klasicne dugotrajne transakcije

Compile-lock konkurencija moze da proizvede pokretni blocking chain umesto da jedna sesija drzi isti database lock tokom celog incidenta.³

SQL je bio ispravan

Nista se nije srusilo kada je procedura naisla na:

1

SET ANSI_WARNINGS OFF;

Procedura je radila tokom normalnog rada.

Kvar je postao vidljiv tek kada je njeno ponasanje pri izvrsavanju srelo dovoljno konkurencije.

Taj spoj je upravo ono sto cini povremene incidentne baze podataka skupim za dijagnostiku samo iz simptoma aplikacije.

Praktičan dijagnosticki redosled za THREADPOOL

Kada SQL Server povremeno prestaje da odgovara i pojavi se THREADPOOL, koristimo ga kao pocetnu tacku, a ne kao dijagnozu.

Korisni redosled istrage je:

1. Uhvatiti stanje servera tokom incidenta.
2. Proveriti koji su zahtevi aktivni, a koji cekaju.
3. Izgraditi blocking chain.
4. Pregledati blocking_session_id i stvarni blokirani resurs.
5. Proveriti sta trosi ili zadrzava radnike.
6. Ne odbacivati head blocker samo zato sto mu je wait_type prazan.
7. Ako blokirani resurs mapira na stored proceduru, proveriti compile konkurenciju.
8. Uhvatiti recompilation dogadjaje pomocu Extended Events.
9. Pregledati recompile_cause.
10. Povezati taj uzrok sa kodom procedure i podesavanjima sesije.
11. Ukloniti izvor konkurencije pre menjanja SQL Server kapaciteta.

Ovaj redosled takodje izbegava cestu zamku pri otklanjanju problema: tretiranje resursa koji je slucajno iscrpljen kao komponente koju treba uvecati.

Iscrpljivanje resursa je cesto nekoliko koraka udaljeno od defekta

Isti obrazac se pojavljuje i u drugim incidentima baza podataka.

Connection pool moze da se popuni zato sto se zahtevi vise ne zavrsavaju.

CPU moze ostati zasicen zato sto su execution plan-ovi nestabilni ili se statement-i recompajliraju.

Storage latency moze da poraste zato sto je nekada selektivni upit postao veliki scan.

Replication lag moze biti vidljiv problem dok se stvarna promena desila u volumenu pisanja ili obliku transakcije.

U ovom slucaju, vidljiva metrika je bilo iscrpljivanje radnika.

Korisno pitanje je bilo sta je drzalo radnike zauzetim.

Dijagnostika baza podataka treba da sacuva stanje kvara

Povremeni produkcijski incidenti se mnogo lakse resavaju kada je baza instrumentisana tako da zadrzi dokaze iz failure prozora.

Za SQL Server to obicno znaci kombinovanje runtime session/request podataka sa informacijama o blokiranju i ciljanih Extended Events, umesto oslanjanja na snapshot performansi uzet nakon oporavka.

Istraga tada moze da krene od dokaza:

1
2
3
4
5
6
7
8
9

Sta je prestalo da napreduje?
        ↓
Na sta je cekalo?
        ↓
Koji resurs je bio ukljucen?
        ↓
Zasto je taj resurs bio u konkurenciji?
        ↓
Koja je najmanja promena koja uklanja uzrok?

Tako pristupamo i ogranicenim istrazivanjima performansi baza podataka u Techpipe-u: prvo uhvatimo kvar, zatim rekonstruisemo zavisnosti i menjamo sloj na kome problem zaista pocinje.

Reference