06 lipca 2011

Jak zmierzyć wydajność zapytania w MS SQL Server?

Dlaczego w ogóle warto mierzyć wydajność zapytania SQL?


Nie jeden raz zdarzyło mi się porównywać czasy wykonania dwóch różnych zapytań SQL które były rozwiązaniem jednego problemu. Nie zawsze w sposób jednoznaczny można określić, które z zapytań jest bardziej optymanlne.  W przypadku zapytań wykonywanych na instancji SQL Servera interesują nas następujące parametry
  • czas wykonania
  • ilość odczytów stron potrzebnych do wykonania zapytania
  • ilość zapisów (np. w bazie tempdb)
  • użycie czasu procesora 
Bardzo pomocnym zródłem danych do analizy wydajności zapytania będzie też sam plan wykonania zapytania. W tym poście skupię się na jednym zapytaniu do znanej bazy danych AdventureWorks dla MS SQL Server 2008 R2. Skrypty zawarte w tym poście działają na MS SQL Server w wersji 2008 i wyższej, aczkolwiek po małych przeróbkach powinny zadziałać na wersjach 2005 i 2000. Testy wydajności przeprowadzę na przykładowym zapytaniu obliczającym sumę wartości zamówień dla dostępnych kategorii produktów.

SELECT pc.Name Category, SUM(sod.LineTotal) CategoryTotal
   FROM Production.Product p
  INNER JOIN Production.ProductCategory pc
     ON p.ProductSubcategoryID = pc.ProductCategoryID
  INNER JOIN Sales.SalesOrderDetail sod
     ON sod.ProductID =  p.ProductID
  GROUP BY pc.Name
  ORDER BY Category

Pomiar czasu wykonania


Czas wykonania może zmieniać się drastycznie, w zależności od kilku czynników. Istotne jest, aby przed pomiarem czasu wykonania rozważyć kilka z następujących zagadnień:
  • czy jest to pierwsze wykonanie zapytania czy kolejne i dane zostały zaczytane do pamięcie SQL Servera?
  • czy serwer jest w dany momencie obciążony innymi operacjami (CPU, IO)?
  • czy dane uległy znaczącej zmianie i statystyki nie zostały zaktualizowane?
  • czy w cache'u znajduje się nieoptymalny plan wykonania dla danego zapytania?
  • czy zapytanie nie jest blokowane przez inne procesy w dostępie do zasobów (np. tabele)?



Należy podliczyć IO


Jednym z bardziej kluczowych zasobów w SQL Server jest pod-system IO. Może okazać się on wąskim gardłem dla systemów opartych na MS SQL Server, ponieważ operacje odczytu danych są dużo wolniejsze w porównaniu z odczytem danych z pamięci operacyjnej. Kolejnym powodem dla którego należy oszczędnie gospodarować operacjami odczytu IO jest ograniczona ilość pamięci operacyjnej, która jest wykorzystywana jako cache dla danych odczytywanych z dysku. Jeżeli zapytania generują niepotrzebne odczyty stron danych z dysku, może to wymusić usuwanie stron z cache'a które są już załadowane do pamięci. Będzie to negatywnie wpływać na pracę systemu poprzez nieoptymanlne wykorzystywanie cache'a. Podczas wykonania zapytania SQL do pomiaru odczytów i zapisów IO najłatwiej wykorzystać intrukcję SET STATISTICS IO.

SET STATISTICS IO ON
....
--SQL query goes here
...
SET STATISTICS IO OFF

Nie zapominajmy o CPU


Nie zawsze aktywność systemu IO będzie dla nas najistotniejszym współczynnikiem przy ustalaniu wydajności zapytania. Nie można zapomnieć, że każde wykonane zapytanie wiaże się z obciążeniem procesora. Do pomiaru obciążenia CPU możemy wykorzystać instrukcję SET STATISTICS TIME.

SET STATISTICS TIME ON 
....
--SQL query goes here
...
SET STATISTICS TIME OFF

Jak przygotować grunt do pomiarów?


Przed wykonaniem zapytania uruchamiamy sekwencję następujących poleceń aby wyczyścić cache'e SQL Servera:

CHECKPOINT 
DBCC DROPCLEANBUFFERS WITH NO_INFOMSGS
DBCC FREEPROCCACHE WITH NO_INFOMSGS

CHECKPOINT - wymusi zapisanie na dysku wszystkich stron które zostały zmodyfikowane w pamięci (ang. Dirty Pages).

DBCC DROPCLEANBUFFERS - wyczyści cache danych (buffer pool), aby wykonanie zapytania wymusiło odczyt danych z dysku

DBCC FREEPROCCACHE - usuwa plany zapytań z cache'u.


Nie ma lipy - mierzymy wydajność zapytania SQL


Mamy konkretne zapytanie, chcemy zmierzyć jego wydajność. Proponuję ustalenie kilku metryk które chcemy zmierzyć:

  • Czas pierwszego wykonania (bez cache'u, na zimno)
  • aktywność podsystemu IO 
  • CPU
  • średni, najdłuższy i najkrótszy czas wykonania zapytania
  • szacowany koszt (Estimated Subtree cost) wykonania zapytania  z planu wykonania (execution plan)
Dysponując już tymi informacjami, będziemy mogli wypowiedzieć się bardziej naukowo na temat  danego zapytania i jego charakterystyki wydajnościowej. Zajmijmy się ustaleniem trzech pierwszych metryk czyli "SQL na zimno", IO i CPU.

DECLARE @coldRunStart Datetime2,
@coldRunFinish Datetime2

CHECKPOINT 
DBCC DROPCLEANBUFFERS WITH NO_INFOMSGS
DBCC FREEPROCCACHE WITH NO_INFOMSGS

SET @coldRunStart = SYSDATETIME()

SET STATISTICS IO ON
SET STATISTICS TIME ON 

 SELECT pc.Name Category, SUM(sod.LineTotal) CategoryTotal
   FROM Production.Product p
  INNER JOIN Production.ProductCategory pc
     ON p.ProductSubcategoryID = pc.ProductCategoryID
  INNER JOIN Sales.SalesOrderDetail sod
     ON sod.ProductID =  p.ProductID
  GROUP BY pc.Name
  ORDER BY Category

SET STATISTICS TIME OFF  
SET STATISTICS IO OFF

SET @coldRunFinish = SYSDATETIME()

SELECT DATEDIFF(MILLISECOND, @coldRunStart, @coldRunFinish)

Otrzymujemy następujące wyniki w zakładce "Results":



a w zakładce "Messages" widzmy efekty ustawienia SET STATISTICS IO oraz SET STATISTICS TIME na wartość ON.


(4 row(s) affected)
Table 'Worktable'. Scan count 0, logical reads 0, physical reads 0, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'SalesOrderDetail'. Scan count 1, logical reads 1240, physical reads 2, read-ahead reads 1242, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'Product'. Scan count 1, logical reads 60, physical reads 3, read-ahead reads 16, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.
Table 'ProductCategory'. Scan count 1, logical reads 2, physical reads 1, read-ahead reads 0, lob logical reads 0, lob physical reads 0, lob read-ahead reads 0.

SQL Server Execution Times:
CPU time = 203 ms, elapsed time = 600 ms.


Przy analizie IO najważniejsze są logical reads i physical reads, których suma dla danej tabeli wyznacza liczbę odczytanych stron danych (8 KB). Licznik logical reads wskazuje liczbę stron danych które zostały odczytane z pamięci, aczkolwiek czyściliśmy przecież cache przed wykonaniem zapytania. Należy zwrócić uwagę na inną wartość read-ahead reads,  który pokazuje, że podsystem IO SQL Servera nie zawsze czyta tylko pojedyńcze extenty (8 stron na raz), ale stara się być proaktywny i czasem czyta wiele extentów na raz aby ewentualnie wyprzedzić zapotrzebowanie na dane strony danych.

Elapsed time  określa ile czasu (milisekund) wykonywało się dane zapytanie, CPU time określa ile czasu procesora zużyliśmy.

Następnie, obliczamy średni, najdłuższy i najkrótszy czas wykonania zapytania ze 100 kolejnych prób.

SET NOCOUNT ON

IF OBJECT_ID('tempdb..#ExecutionSession') IS NOT NULL DROP TABLE #ExecutionSession

CREATE TABLE #ExecutionSession(TimeInMiliSec Int)

DECLARE @execCount Int = 0
WHILE @execCount < 100
BEGIN

IF OBJECT_ID('tempdb..#Test') IS NOT NULL DROP TABLE #Test

DECLARE @datetime Datetime2 = SYSDATETIME() 

SELECT pc.Name Category, SUM(sod.LineTotal) CategoryTotal
   INTO #Test
   FROM Production.Product p
  INNER JOIN Production.ProductCategory pc
     ON p.ProductSubcategoryID = pc.ProductCategoryID
  INNER JOIN Sales.SalesOrderDetail sod
     ON sod.ProductID =  p.ProductID
  GROUP BY pc.Name
  ORDER BY Category 
 

INSERT INTO #ExecutionSession(TimeInMiliSec)
SELECT DATEDIFF(MILLISECOND, @datetime, SYSDATETIME())

SET @execCount += 1

END

SELECT MIN(TimeInMiliSec) MinimumExecTime
,  MAX(TimeInMiliSec) MaximumExecTime
,  AVG(TimeInMiliSec) AvgExecTime
,  COUNT(*) ExecCount
FROM #ExecutionSession

Wyniki zapytania są następujące:



Pozostał nam plan wykonia i ustalenie szacowanego kosztu zapytania (Estimated Subtree cost)   wyliczonego na podstawie "magicznych" heurystyk optymalizatora. Oczywiście plan wykonania jest w sam sobie bardzo użyteczną wizualizacją wydajnościowej charakterystyki naszego zapytania (np. rozróżnia Seek od Scanu indeksu, czego IO Statistics nie potrafią)



Zestawienie, decyzja należy do ciebie


Czas pierwszego wykonania (bez cache'u, na zimno): 600 ms
IO:
  • tabela SalesOrderDetail - 1242 odczyty stron
  • tabela Product - 63 odczyty stron
  • tabela ProductCategory - 3 odczyty stron
CPU:  203 ms
Średni czas wykonania zapytania: 108 ms
Najdłuższy czas wykonania zapytania: 141 ms
Najkrótszy czas wykonania zapytania: 103 ms
Szacowany koszt wykonania zapytania: 1.71699

4 komentarze:

  1. Dzieki za wpis, z pewnoscią przetestuje

    OdpowiedzUsuń
  2. A istnieje jakiś sprytny sposób albo programik do przetestowania bazy pod dużym obciążeniem (wiele zapytań naraz?)

    OdpowiedzUsuń
  3. Spróbowałbym mechanizmu Reply w SQL Profiler (http://msdn.microsoft.com/en-us/library/ms189604.aspx). SQL Reply umożliwi Ci uruchamianie zapisancyh traców(domyślnie na 4 wątkach). Możesz też sprawdzić RML Utilities for SQL Server, którymi też można odtwarzać trace'y.

    OdpowiedzUsuń
  4. Jest jeszcze SQLSTRESS ;)

    OdpowiedzUsuń

Uwaga: tylko uczestnik tego bloga może przesyłać komentarze.