Egy nagyon belassult SQL szerver
(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:
database_id | object_id | index_id | partition_number | index_type_desc | alloc_unit_type_desc | index_depth | index_level | avg_fragmentation_in_percent | fragment_count | avg_fragment_size_in_pages | page_count | avg_page_space_used_in_percent | record_count | ghost_record_count | version_ghost_record_count | min_record_size_in_bytes | max_record_size_in_bytes | avg_record_size_in_bytes | forwarded_record_count |
---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
6 | 2073058421 | 1 | 1 | CLUSTERED INDEX | IN_ROW_DATA | 5 | 0 | 98.1227621828284 | 147942 | 1.00244014546241 | 148303 | 47.3060785767235 | 13 | 1 | 1608002 | 314 | 374 | 347.846 | NULL |
6 | 2073058421 | 1 | 1 | CLUSTERED INDEX | IN_ROW_DATA | 5 | 1 | 99.7432605905006 | 3895 | 1 | 3895 | 48.5910180380529 | 148303 | 0 | 0 | 11 | 118 | 101.346 | NULL |
6 | 2073058421 | 1 | 1 | CLUSTERED INDEX | IN_ROW_DATA | 5 | 2 | 99 | 100 | 1 | 100 | 50.2309117865085 | 3895 | 0 | 0 | 11 | 118 | 102.433 | NULL |
6 | 2073058421 | 1 | 1 | CLUSTERED INDEX | IN_ROW_DATA | 5 | 3 | 0 | 2 | 1 | 2 | 64.6466518408698 | 100 | 0 | 0 | 11 | 118 | 102.69 | NULL |
6 | 2073058421 | 1 | 1 | CLUSTERED INDEX | IN_ROW_DATA | 5 | 4 | 0 | 1 | 1 | 1 | 1.42080553496417 | 2 | 0 | 0 | 11 | 102 | 102.119 | NULL |
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.
Robi:
Üdv!
10 March 2010, 5:32 pmLenne egy kérdésem. Ha blogban említett script-el kiiratom hogy melyik adatbázis mennyi lapot foglal a memóriában, azt honnan tudom megállapítani hogy az hány százaléka a memóriának? Vagy hogy hány MB ténylegesen?
Erik:
Így:
declare @total int
select @total = cntr_value from sys.dm_os_performance_counters
where counter_name = ‘Total Pages’
and object_name like ‘%Buffer Manager%’
SELECT count(*) AS cached_pages_count,
COUNT(*)/128.0 AS memory_MB,
100* COUNT(*)/@total AS memory_percent,
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
Ez az SQL szerver által használt memória százalékát számolja. Veheted a max server memory-t is alapul, azt meg sp_configure-ral tudod kiolvasni.
10 March 2010, 10:07 pm