Rollback

(disclaimer: mivel a hibaelhárítás során nem gondoltam volna, hogy ebből még post lesz, az outputok egy részét utólag “gyártottam”, minden igyekezetem mellett maradhatott bennük hiba – ha valaki talál egyet, veszek neki egy óriás túrórudit)

Pár napja azt vettem észre, hogy az egyik SQL szerverünk egyik adatbázisába a replikáció nagyon belassult. Ugyanazt a publikált adatbázist több helyre is replikáljuk, semmi gond nem volt a többivel. Mivel ezen az adatbázison riportokat is futtattak, elsőre megnéztem, hogy nem blokkolja-e valaki valami hosszan futó lekérdezéssel a táblákat:

select * from sysprocesses 
where 
spid in (select blocked from sysprocesses where spid <> blocked)
and dbid = db_id('MyDatabase')

(A where spid <> blocked kitétel azért kell, mert SQL 2000 SP4-től az “önblokkolás” is megjelenik blokkolásként, de ez alapvetően nem érdekel senkit a processzen kívül. A fenti script SQL 2000-re lett írva, de futott a 2005-ös szerveren is.) Azt vártam, hogy megtalálom az egyik riportírót, ahogy valami veszett nagy joint meg filterezést nyom le a szerver torkán, de nem így történt. Semmit nem találtam. Egy lehetőséget kizártam. Azt sejtettem a lelkem mélyén, hogy ha újraindítom a szervert, ez az egész megoldódik, de mivel a helyzet nem volt teljesen tragikus, a szerver még használható állapotban volt, inkább szerettem volna a végére járni, mivel utálom a megoldatlan rejtélyeket.

Ezután bánatomban elkezdtem nézegetni a distribution agent historyját, amiben szintén nem találtam semmit, igazából csak azt láttam, hogy nagyon lassúak az agentek. Úgy döntöttem, hogy az egyiket megnézem közelebbről. Megnéztem a process monitorban, és azt láttam, hogy nagyon sok időt tölt ő is, meg a barátai is RESOURCE_SEMAPHORE wait állapotban. Nem igazán tudtam, hogy mi ez, de van egy kiváló whitepaper a waitekről, azt felütöttem, és megnéztem, hogy mit ír erről. Azt írta, hogy ez tipikusan azt jelzi, hogy nagy konkurrens terhelés miatt a processznek várnia kell arra, hogy memóriához jusson, jellemző lehet a nagy lekérdezéseket futtató rendszerekre. Mivel a nagy lekérdezést már korábban kizártam, elég ötlettelen voltam, gondoltam, megnézem a memóriahasználatot.

SQL 2005-ben az SQL 2000-ben lelkesen használt DBCC MEMUSAGE parancs már nem létezik, de sebaj, van helyette sokkal jobb. Míg a memusage a 30 legtöbb memóriát foglaló objektumot adta csak vissza, addig 2005-ben a DMV-k (dynamic management view-k) segítségével minden objektumra le tudjuk kérni ezt az adatot. Ha az ember felüti a Books Online-t a sys.dm_os_buffer_descriptors címszónál, megtalálja a két lenti példascriptet ami per adatbázis, illetve adatbázison belül per tábla mondja meg a helyfoglalást.

-- szerver szinten
SELECT count(*)AS cached_pages_count
    ,CASE database_id 
        WHEN 32767 THEN 'ResourceDb' 
        ELSE db_name(database_id) 
        END AS Database_name
FROM sys.dm_os_buffer_descriptors
GROUP BY db_name(database_id) ,database_id
ORDER BY cached_pages_count DESC

-- adatbázis szinten
SELECT count(*)AS cached_pages_count 
    ,name ,index_id 
FROM sys.dm_os_buffer_descriptors AS bd 
    INNER JOIN 
    (
        SELECT object_name(object_id) AS name 
            ,index_id ,allocation_unit_id
        FROM sys.allocation_units AS au
            INNER JOIN sys.partitions AS p 
                ON au.container_id = p.hobt_id 
                    AND (au.type = 1 OR au.type = 3)
        UNION ALL
        SELECT object_name(object_id) AS name   
            ,index_id, allocation_unit_id
        FROM sys.allocation_units AS au
            INNER JOIN sys.partitions AS p 
                ON au.container_id = p.hobt_id 
                    AND au.type = 2
    ) AS obj 
        ON bd.allocation_unit_id = obj.allocation_unit_id
WHERE database_id = db_id()
GROUP BY name, index_id 
ORDER BY cached_pages_count DESC

Ez azt mondta, hogy a memória 95%-át az én kis problémás adatbázisom használja, és azon belül a memória 95%-át, mintegy 140000 lapot a MSreplication_subscriptions tábla. Ez erősen meglepett, mivel úgy emlékeztem, hogy az egy kicsi tábla, de közben fellőttem egy profilert is.

A profilerben azt láttam, hogy vannak lekérdezések, amik horrorisztikusan lassan futnak le, nagy I/O-val. A lekérdezések a következőképpen néztek ki:

(@P1 varbinary(14),@P2 datetime,@P3 nvarchar(11),@P4 nvarchar(4),@P5 nvarchar(16))
update MSreplication_subscriptions 
set transaction_timestamp = cast(@P1 as binary(15)) + 
cast(case datalength(transaction_timestamp) 
when 16 then isnull(substring(transaction_timestamp, 16, 1), 0) 
else 0 end as binary(1)), 
time = @P2 where UPPER(publisher) = UPPER(@P3) and 
publisher_db = @P4 and publication = @P5 and subscription_type = 1 16)

Tehát update-elte a subscriber adatbázisban található MSreplication_subscriptions táblát (a sok @P-s változó lekérdezésparaméter, gondoljunk valamit a helyükre). Ez nem egy nagy szám, elméletileg egy sor per subscription van benne, de akkor miért olvas több, mint százezret a processz? Lekérdeztem a táblát, és megkértem a szervert, hogy mondja el hozzá az IO statisztikát is:

set statistics io on
select * from MSreplication_subscriptions 

És ez jött vissza:

(13 row(s) affected)
Table 'MSreplication_subscriptions'. Scan count 1, logical reads 142543, physical reads 1234, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

Ez mellbevágott. 13 sor, 142000 olvasással, miközben nincs LOB a táblában… Pont nem hiányzott egy sérült adatbázis mára… lenyomtam egy DBCC-t a táblára:

DBCC CHECKTABLE ('MSreplication_subscriptions')

Ezt mondta, alig 5 óra 43 perccel később:

DBCC results for 'MSreplication_subscriptions'.
There are 13 rows in 147460 pages for object 'MSreplication_subscriptions'.
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

Itt egy kissé kezdtem zavarba jönni, hiszen erős gyanú ébredt bennem, hogy valami elromlott az adatbázisban – de akkor a DBCC miért nem sikoltozott? Tanácstalanságomban úgy döntöttem, hogy szüneteltetem a hibakeresést, és otthagytam a számítógépet. Az agyam persze járt tovább, és két perc múlva eszembe jutott, hogy esetleg meg kéne nézni a fizikai szerkezetét a táblának, azaz lekérni az index információkat, hiszen a clustered index levélszintjén maguk a rekordok ülnek. Hátha csak nagyon fragmentálódott a tábla (aha, azonnal rájöttem, hogy ez mekkora marhaság, hiszen legrosszabb esetben egy rekord egy egész lapot vinne el – mi van a többi 147447 lappal?).

A gondolatot tett követte, és lehúztam az index információkat:

SELECT * FROM 
sys.dm_db_index_physical_stats(db_id(), object_id('dbo.MSreplication_subscriptions'), 
null, null, 'detailed')
-- SQL 2000-nél a DBCC SHOWCONTIG-ot tudom ajánlani

(Mint látható, ez már nem is DMV, hanem DMF, azaz dynamic management function.) Erre visszakaptam mindent, és még többet is, mint szerettem volna:

Ez elsőre kicsit értelmetlen lehet, de a 0-s, azaz a legelső sorban láthatjuk a rejtély kulcsát. Maga a result set úgy épül fel, hogy minden index minden egyes szintje kap egy sort benne (az indexeket fa struktúrába szerverzi az SQL Server, egész pontosan B-fába). Itt egyetlen clustered indexünk van, ennek láthatjuk a szintjeit. A page_count oszlopban láthatjuk az egyes szintek által használt lapokat, a record_count oszlop pedig a rekordok számát mondja meg. A 0-s szinten a record_count 13, viszont 148303 page van (időközben is nőtt a tábla) hozzá. A record_count után viszont van még két oszlop, ami szintén record count, csak másképpen.

A ghost_record_count azt mondja meg, hogy hány olyan rekord van a táblában, ami már logikailag törölve lett, de még fizikailag létezik. Az ilyen rekordokat a GHOST_CLEANUP nevű rendszerprocessz szépen szorgosan eltünteti, tehát alkalomadtán az is megeshet, hogy hiába törlünk a táblából, mindig nullát látunk, mert marha gyorsan lefut a cleanup. Ezek tehát azok a rekordok, akik már nem kellenek. A version_ghost_record_count oszlop viszont azt mutatja meg, hogy hány olyan rekord van, ami már nem létezik a táblában, de még kell, mivel van olyan tranzakció, amelyik sorverziózást használ a konkurrencia kezelésére (azaz snapshot isolation levelen fut), és a sor azóta megváltozott. Esetünkben látszik, hogy egyetlen törölhető ghost rekordunk mellett van 1608002 sor, ami a sorverziózás miatt kell. Ez egy 13 sorral rendelkező táblánál elég durva, még akkor is, ha a 13 sorhoz tartozik 13 distribution agent, amelyek egyfolytában szaladnak, és legalább percenként írnak egyet. Úgyhogy arra gondoltam, hogy megnézem a legrégebb óta futó nyitott tranzakciót az adatbázisban:

DBCC OPENTRAN

Transaction information for database 'MyDatabase'.

Oldest active transaction:
    SPID (server process ID): 74
    UID (user ID) : -1
    Name          : user_transaction
    LSN           : (21:201:1)
    Start time    : May  13 2009  1:48:22:733PM
    SID           : 0x010500000000000515000000119d203ab2692ec2891a29a8ed030000
DBCC execution completed. If DBCC printed error messages, contact your system administrator.

És a naptár szerint május 28. volt. Megnéztem a processzt, és azt láttam, hogy egy Distribution Agent az, amit egy DISTRIB.EXE tart nyitva, és figyelembe véve a tényt, hogy az SQL Agentet pár órája újraindítottam, illetve a replikációban nem volt lemaradás, nagy bizonyossággal állíthatom, hogy a szóbanforgó agent egyszerűen berohadt valamikor május 13-án délután kettő körül.

Miután megöltem a processzt, hirtelen a ghost_record_count felugrott másfélmillió fölé, majd lassan kisimult, és hirtelen az egész tábla elfért 8 lapon (vannak, akik egy kicsit másképpen emlékeznek, de az már nem sokat változtatna a történeten).

Ez egy kissé hosszúra sikeredett, de remélem hasznos lesz valakinek ez a kis ízelítő a DBA eszköztárából.