11 listopada 2011

SQL Server Profiler dla początkujących

Czy mój system jest zdrowy?


Pewnego słonecznego poranka, z braku laku uruchomiłem SQL Server Profiler'a. Bez konkretnego celu, postanowiłem przejrzeć rodzaj i ilości zapytań SQL które są generowane podczas jednego wejścia na stronę pewnego systemu z którym pracowałem. Ku mojemu zakoczeniu, web'owa aplikacja okazała się bardzo skuteczna w produkcji dużej liczby zapytań do pobrania małej ilości danych. Trace w Profiler'rze wyglądał jak świąteczna lista życzeń.

We wspomnianym przypadku, jednym z powodów nadmiernej ilości zapytań, było nieumiejętne wykorzystanie mechanizmów NHibernate'a (w tym wypadku lazy load). Nie chodziło nawet o niezrozumienie działania użytych narzędzi, raczej była to kwestia braku monitorowania tworzonych dynamicznie zapytań.  Oczywiste jest, że pisząc systemu oparte o silnik baz danych istotne jest aby unikanąć pisania "małpiego" kodu odczytywania i zapisywania danych. Z wielkim entuzjazmem środowisko .NET przyjeło jedynego słusznego OR Mapper'a, który odciążył "statystycznego" programistę formatek od klepania kolejnych linijek kodu w ADO.NET. Niestety, jak z każdą technologią nie można popadać w zbyt wielki optymizm i czasami należy zachować zimną krew. Wszystkim używającym NHib'a polecam przejrzenie listy problemów jakie mogą pojawić się przy pracy z jedynym słusznym OR Mapperem. Koniec dygresji na temat NHib'a, przechodzę do sedna sprawy, czyli monitorowania i analizy zapytań generowanych przez zewnętrzną aplikację.


Szukając winnego


Dla niewtajemniczonych, SQL Server Profiler jest to oprogramowanie, które pozwala przeglądać/filtrować/zapisywać zdarzenia lub zapytania wykonywane na danej instancji MS SQL Server'a. Jest to bardzo przydatne narzędzie, jeżeli pracujemy z SQL Server'em warto spędzić trochę czasu by poznać je lepiej.

W tym poście skupię się na funkcjonalności SQL Server Profiler'a związanej z filtrowaniem zapytań dla danej bazy, zapisywaniem tzw. trace'u w tabeli bazy danych i "analizie" ilościowej zapytań. Analiza powinna pomóc w znalezieniu potencialnych problemów ukrytych za setkami/tysiącami rekordów trace'u.  

Przykładowy kod aplikacji konsolowej będzie odpytywał bazę danych AdwentureWorks dla MS SQL Server 2008 R2. W szczególności tabele Sales.Customer, Sales.SalesOrderHeader i Sales.SalesOrderDetail. Poniżej kod naszej testowej aplikacji. Na uwagę zasługuję atrybut Application Name w connection stringu. Implementacja jest dosyć kulawa, pobiera najpierw wszystkich klientów, później oddzielnie dla każdego klienta pobiera listę zamówień i listę pozycji dla danego zamówienia. Taki kod obrazuje jak można wygenerować dziesiątki zapytań, które równie dobrze można obsłużyć jednym lub dwoma zapytaniami.


using System;
using System.Data.SqlClient;

class Program
{
    static void Main(string[] args)
    {
        using (var conn = new SqlConnection(@"Server=HOME\SQL2008R2;
                    Database=AdventureWorks2008R2;
                    Application Name=MyTestConsoleApp;
                    MultipleActiveResultSets=true;
                    Trusted_Connection=true"))
        {
            conn.Open();
            using(var cmd = new SqlCommand(
                    @"SELECT TOP 10 cust.CustomerID, p.LastName 
                        FROM Sales.Customer cust
                        JOIN Person.Person p
                        ON cust.PersonID = p.BusinessEntityID
                    WHERE p.LastName LIKE 'A%'", conn))
            using (var customerReader = cmd.ExecuteReader())
            {
                while (customerReader.Read())
                {
                    Console.WriteLine(customerReader["LastName"]);

                    GetSalesOrders(conn, customerReader);
                }
            }
        }

    }

    private static void GetSalesOrders(SqlConnection conn, SqlDataReader customerReader)
    {
        using (var cmdSalesOrder = new SqlCommand(
            @"SELECT sod.SalesOrderID, sod.OrderDate, sod.CustomerID
                FROM Sales.SalesOrderHeader sod
                WHERE sod.CustomerID = @customerId", conn))
        {
            cmdSalesOrder.Parameters.AddWithValue("@customerId", customerReader["CustomerID"]);
            using (var sodReader = cmdSalesOrder.ExecuteReader())
            {
                while (sodReader.Read())
                {
                    Console.WriteLine(sodReader["OrderDate"]);
                    GetSalesOrderDetails(conn, sodReader);
                }
            }
        }
    }

    private static void GetSalesOrderDetails(SqlConnection conn, SqlDataReader sodReader)
    {
        using (var cmdSalesOD = new SqlCommand(
            @"SELECT SalesOrderID
                ,SalesOrderDetailID
                ,OrderQty
                ,ProductID
                ,LineTotal
            FROM Sales.SalesOrderDetail
            WHERE SalesOrderID = @SalesOrderID", conn))
        {
            cmdSalesOD.Parameters.AddWithValue("@SalesOrderID", sodReader["SalesOrderID"]);
            using (var deatailReader = cmdSalesOD.ExecuteReader())
            {
                while (deatailReader.Read())
                {
                    Console.WriteLine(deatailReader["ProductID"] + " " + deatailReader["LineTotal"]);


                }
            }
        }
    }
}



Filtry i kolumny


Uruchamiamy SQL Server Profiler i podłączamy się do instancji. Możemy podłączyć się zdalnie do instancji serwera jeżeli nasze konto ma uprawnienia ALTER TRACE. SQL Server Profiler możemy odpalić z SSMS lub przez Menu Start (aka Perłę od Windows Vista).





Jednym z bardziej istotnym aspektem korzystania z SQL Profiler jest ogracznienie zbioru danych jakie będziemy otrzymywać.Do przechowywania trace'u zakładamy bazę danych TraceStore na lokalnym serwerze.

CREATE DATABASE TraceStore;

Podłączam się do instancji MS SQL Server'a.Na zakładce General dla nowego trace'u konfiguruję opcje 'Save to table', wybieram rodzaj template'u i wpisuję nazwę sesji.



Przełączam się na zakłądkę 'Events Selection'. W pierwszym kroku wybieram kolumny, które zapełnią się danymi ze zdarzeń:
  • TextData - zapytanie
  • ApplicationName - nazwa aplikacji, można ja podać w connection string'u aplikacji (atrybut Application Name)
  • CPU - czas CPU w milisekundach wykorzystany przez dane zdarzenie
  • Reads - liczba odczytów stron danych przez zdarzenie
  • Writes -   liczba zapisów stron danych przez zdarzenie
  • Duration - czas w microsekundach potrzebny na wykonanie zdarzenia
  • SPID - Server Process Identifier
  • EndTime - czas zakończenia wykonywania zdarzenia

Wybieram następujące zdarzenia:

  • RPC:Completed - procedura wywołana zdalnie zakończyła swoje działanie
  • SQL:BatchCompleted -batch zakończył swoje działanie



Na zakładce 'Events Selection' wybieram przycisk 'Column Filters'. Ustawiam filtr na nazwę aplikacji (Application Name), ponieważ tylko zdarzenia z mojej konsolowej aplikacji są w kręgu moich zainteresowań.


Filtrujemy po Application Name, jeżeli korzystamy z tej opcji w connection string'u. Może to być przydatne, jeżeli inne aplikacje korzystają z tej samej bazy danych, lub baza jest np. subskrybentem replikacji. Zapobiega to zaśmiecaniu trace'a zapytaniami, które mnie w tym momencie nie interesują.

Wybieramy 'Run' i zaczynamy śledzenie trace'a, który jest zapisywany również w tabeli TraceStore.dbo.AdwentureWorks_2011Nov10. Uruchamiamy testową aplikację DemoProfiler (kod podany powyżej) i czekamy na pojawienie się wpisów w tabeli. W oknie SQL Profiler'a wygląda to następująco.


Sprawdzam teraz jak przedstawiają się wyniki dla najbardziej popularnego zapytania w zgromadzonym trace'ie.

SELECT  SPID, SUBSTRING(CAST(TextData AS NVarchar(max)), 1, 150),COUNT(*) QueryCount
FROM TraceStore.dbo.AdwentureWorks_2011Nov10
 GROUP BY  SPID, SUBSTRING(CAST(TextData AS NVarchar(max)), 1, 150)
 ORDER BY SPID, QueryCount DESC

Powyższe zapytanie daje następujące rezultaty.


Widać, że zapytanie o listę pozycji w zamówieniu było najczęściej wykonywane. Nie zawsze musi oznaczać to problemy, ale warto sprawdzić kilka zapytań z górnej części listy.

exec sp_executesql N'SELECT SalesOrderID
                  ,SalesOrderDetailID
                  ,OrderQty
                  ,ProductID
                  ,LineTotal
                FROM Sales.SalesOrderDetail
                WHERE SalesOrderID = @SalesOrderID',N'@SalesOrderID int',@SalesOrderID

Jak to można stosować?


Zachęcam wszystkich do uruchomienia SQL Profiler'a na swoim systemie (oczywiście nie na produkcji, bo to obciąży znacząco i niepotrzebnie SQL Server'a). Może się okazać, że to co zobaczymy przerośnie nasze najśmielsze oczekiwania. W moim zespole używamy namiętnie NHibernate'a, kiedyś zaproponowałem, żeby używać SQL Profiler'a jako część code review, ale zostałem wyśmiany :). Zapewne byłaby to strata czasu, ale osobiście zawsze darzyłem sympatią SQL Profiler'a. Tylko ten program prawdę ci powie, nie jakaś tam cyganka.

Hope this helps.

3 komentarze:

  1. Witam,
    dzieki za swietny przepis. w wyniku selecta wyszlo, ze najwiecej mam zdarzen: "exec sp_reset_connection"
    Napisales "ale warto sprawdzić kilka zapytań z górnej części listy"
    Co moge zrobic z tym co mi wyszlo ?
    pozdrawiam
    Andrzej

    OdpowiedzUsuń
  2. Cześć Andrzej,

    Wywołanie "exec sp_reset_connection" jest związane z SQL connection pooling, i SQL Client wywołuje to przed ponownym użyciu danego połączenia do bazy danych.

    Tutaj możesz znaleźć trochę informacji o tym jak to wszystko funkcjonuje:
    http://stackoverflow.com/questions/596365/what-does-sp-reset-connection-do

    Pozdrawiam, Maks

    OdpowiedzUsuń

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