Czy to objaw przeciążenia serwera?

12

Próbowałem zdiagnozować spowolnienia w aplikacji. W tym celu zarejestrowałem rozszerzone zdarzenia programu SQL Server .

  • Na to pytanie patrzę na jedną konkretną procedurę przechowywaną.
  • Ale istnieje podstawowy zestaw kilkunastu procedur przechowywanych, które równie dobrze mogą być wykorzystane jako dochodzenie od jabłka do jabłka
  • i za każdym razem, gdy ręcznie uruchamiam jedną z procedur przechowywanych, zawsze działa szybko
  • a jeśli użytkownik spróbuje ponownie: będzie działał szybko.

Czasy wykonania procedury przechowywanej różnią się bardzo. Wiele wykonań tej procedury składowanej zwraca się w ciągu <1s:

wprowadź opis zdjęcia tutaj

A dla tego „szybkiego” wiadra jest to znacznie mniej niż 1s. To właściwie około 90 ms:

wprowadź opis zdjęcia tutaj

Ale jest długi ogon użytkowników, którzy muszą czekać 2, 3, 4 sekundy. Niektórzy muszą czekać 12s, 13s, 14s. Są też naprawdę biedne dusze, które muszą czekać 22, 23, 24.

Po 30 latach aplikacja kliencka poddaje się, przerywa zapytanie, a użytkownik musiał czekać 30 sekund .

Korelacja w znalezieniu związku przyczynowego

Próbowałem więc skorelować:

  • czas trwania a odczyty logiczne
  • czas trwania a odczyty fizyczne
  • czas trwania vs czas procesora

I wydaje się, że żaden nie daje żadnej korelacji; żaden nie wydaje się być przyczyną

  • czas trwania a odczyty logiczne : czy to małe, czy odczyty logiczne, czas trwania wciąż zmienia się gwałtownie :

    wprowadź opis zdjęcia tutaj

  • czas trwania a fizyczne odczyty : nawet jeśli zapytanie nie zostało dostarczone z pamięci podręcznej i potrzebnych było wiele fizycznych odczytów, nie wpływa to na czas trwania:

    wprowadź opis zdjęcia tutaj

  • czas trwania vs czas procesora : Niezależnie od tego, czy zapytanie zajęło 0 sekund procesora, czy pełne 2,5 sekundy procesora, czasy trwania mają tę samą zmienność:

    wprowadź opis zdjęcia tutaj

Bonus : Zauważyłem, że czas trwania v Czytanie fizyczne i czas trwania v Czas procesora wyglądają bardzo podobnie. Jest to udowodnione, jeśli próbuję skorelować czas pracy procesora z odczytami fizycznymi:

wprowadź opis zdjęcia tutaj

Okazuje się, że dużo wykorzystania procesora pochodzi z I / O. Kto wiedział!

Więc jeśli nie ma nic w czynności wykonania zapytania, która może uwzględniać różnice w czasie wykonywania, czy to oznacza, że ​​jest to coś niezwiązanego z procesorem lub dyskiem twardym?

Jeśli procesor lub dysk twardy były wąskim gardłem; czy nie byłoby to wąskie gardło?

Jeśli postawimy hipotezę, że wąskim gardłem był procesor; że procesor nie jest zasilany dla tego serwera:

  • to czy wykonanie przy użyciu większej ilości czasu procesora nie potrwa dłużej?
  • skoro muszą uzupełniać z innymi wykorzystującymi przeciążony procesor?

Podobnie w przypadku dysków twardych. Jeśli postawimy hipotezę, że dysk twardy był wąskim gardłem; że dyski twarde nie mają wystarczającej liczby losowych przepustowości dla tego serwera:

  • to czy egzekucje wykorzystujące więcej fizycznych odczytów nie potrwałyby dłużej?
  • skoro muszą uzupełniać z innymi używającymi przeciążonych dysków twardych we / wy?

Sama procedura przechowywana nie wykonuje ani nie wymaga zapisu.

  • Zwykle zwraca 0 wierszy (90%).
  • Czasami zwraca 1 wiersz (7%).
  • Rzadko zwraca 2 wiersze (1,4%).
  • W najgorszych przypadkach zwrócił więcej niż 2 wiersze (jeden raz zwraca 12 wierszy)

Więc to nie tak, że zwraca szaloną ilość danych.

Wykorzystanie procesora serwera

Średnie użycie procesora na serwerze wynosi około 1,8%, z okazjonalnym wzrostem nawet do 18% - więc nie wydaje się, aby obciążenie procesora stanowiło problem:

wprowadź opis zdjęcia tutaj

Więc procesor serwera nie wydaje się przeciążony.

Ale serwer jest wirtualny ...

Coś poza wszechświatem?

Jedyne, co mogę sobie wyobrazić, to coś, co istnieje poza wszechświatem serwera.

  • jeśli to nie jest logiczne czyta
  • i to nie są fizyczne odczyty
  • i to nie jest użycie procesora
  • i to nie jest obciążenie procesora

I to nie tak, że są to parametry procedury składowanej (ponieważ ręczne wykonanie tego samego zapytania i nie zajmuje 27 sekund - zajmuje ~ 0 sekund).

Co jeszcze może spowodować, że serwer potrzebuje 30 sekund, a nie 0 sekund, na uruchomienie tej samej skompilowanej procedury składowanej.

  • punkty kontrolne?

To jest serwer wirtualny

  • host przeciążony?
  • kolejna maszyna wirtualna na tym samym hoście?

Przechodzenie przez rozszerzone zdarzenia serwera; nic innego nie dzieje się szczególnie, gdy zapytanie nagle zajmuje 20 sekund. Działa dobrze, a następnie decyduje się nie działać dobrze:

  • 2 sekundy
  • 1 sekunda
  • 30 sekund
  • 3 sekundy
  • 2 sekundy

I nie mogę znaleźć innych szczególnie uciążliwych przedmiotów. Nie dzieje się to podczas każdej 2-godzinnej kopii zapasowej dziennika transakcji.

Co jeszcze może to być?

Czy jest coś, co mogę powiedzieć poza: „serwerem” ?

Edycja : Skoreluj według pory dnia

Zdałem sobie sprawę, że skorelowałem czasy trwania ze wszystkim:

  • odczyty logiczne
  • odczyty fizyczne
  • użycie procesora

Ale jedyną rzeczą, z którą nie skorelowałem, była pora dnia . Być może problem stanowi kopia zapasowa dziennika transakcji co 2 godziny .

A może spowolnienie ma nastąpić w ciągu uchwytów kontrolnych?

Nie:

wprowadź opis zdjęcia tutaj

Czterordzeniowy Intel Xeon Gold 6142.

Edycja - ludzie hipotetycznie plan wykonania zapytania

Ludzie przypuszczają, że plany wykonania zapytań muszą różnić się między „szybkim” i „wolnym”. Oni nie są.

Widzimy to natychmiast po inspekcji.

Wiemy, że dłuższy czas trwania pytania nie wynika z „złego” planu wykonania:

  • taki, który wymagał bardziej logicznych odczytów
  • taki, który zużywał więcej procesora z większej liczby połączeń i wyszukiwań kluczy

Ponieważ jeśli wzrost odczytów lub wzrost procesora byłby przyczyną wydłużenia czasu trwania zapytania, to widzielibyśmy już to powyżej. Brak korelacji.

Spróbujmy jednak skorelować czas trwania z metryką produktu w obszarze odczytu procesora:

wprowadź opis zdjęcia tutaj

Korelacja staje się jeszcze mniejsza - co jest paradoksem.

Edycja : Zaktualizowano diagramy rozproszenia, aby obejść błąd w wykresach rozproszenia programu Excel z dużą liczbą wartości.

Następne kroki

Moim następnym krokiem będzie nakłonienie kogoś do wygenerowania przez serwer zdarzeń dla zablokowanych zapytań - po 5 sekundach:

EXEC sp_configure 'blocked process threshold', '5';
RECONFIGURE

Nie wyjaśnia, czy zapytania są blokowane przez 4 sekundy. Ale być może wszystko, co blokuje zapytanie na 5 sekund, blokuje również niektóre na 4 sekundy.

Slowplany

Oto powolny plan dwóch wykonywanych procedur przechowywanych:

  • `EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04: 00: 00.000', @EndDate = '20190726 04: 00: 00.000'
  • `EXECUTE FindFrob @CustomerID = 7383, @StartDate = '20190725 04: 00: 00.000', @EndDate = '20190726 04: 00: 00.000'

Ta sama procedura przechowywana, z tymi samymi parametrami, biegnie z powrotem do tyłu:

| Duration (us) | CPU time (us) | Logical reads | Physical reads | 
|---------------|---------------|---------------|----------------|
|    13,984,446 |        47,000 |         5,110 |            771 |
|     4,603,566 |        47,000 |         5,126 |            740 |

Zadzwoń 1:

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

Zadzwoń 2

|--Nested Loops(Left Semi Join, OUTER REFERENCES:([Contoso2].[dbo].[Frobs].[FrobGUID]) OPTIMIZED)
    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]))
    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([Contoso2].[dbo].[FrobTransactions].[RowNumber]) OPTIMIZED)
    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |--Nested Loops(Inner Join, OUTER REFERENCES:([tpi].[TransactionGUID]) OPTIMIZED)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[TransactionPatronInfo].[IX_TransactionPatronInfo_CustomerID_TransactionGUID] AS [tpi]), SEEK:([tpi].[CustomerID]=[@CustomerID]) ORDERED FORWARD)
    |    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[Transactions].[IX_Transactions_TransactionGUIDTransactionDate]), SEEK:([Contoso2].[dbo].[Transactions].[TransactionGUID]=[Contoso2].[dbo
    |    |    |    |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions2_MoneyAppearsOncePerTransaction]), SEEK:([Contoso2].[dbo].[FrobTransactions].[TransactionGUID]=[Contos
    |    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactions_RowNumber]), SEEK:([Contoso2].[dbo].[FrobTransactions].[RowNumber]=[Contoso2].[dbo].[Fin
    |    |--Clustered Index Seek(OBJECT:([Contoso2].[dbo].[Frobs].[PK_Frobs_FrobGUID]), SEEK:([Contoso2].[dbo].[Frobs].[FrobGUID]=[Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]),  WHERE:([Contos
    |--Filter(WHERE:([Expr1009]>(1)))
     |--Compute Scalar(DEFINE:([Expr1009]=CONVERT_IMPLICIT(int,[Expr1012],0)))
          |--Stream Aggregate(DEFINE:([Expr1012]=Count(*)))
           |--Index Seek(OBJECT:([Contoso2].[dbo].[FrobTransactions].[IX_FrobTransactins_OnFrobGUID]), SEEK:([Contoso2].[dbo].[FrobTransactions].[OnFrobGUID]=[Contoso2].[dbo].[Frobs].[LC

Sensowne jest, aby plany były identyczne; wykonuje tę samą procedurę przechowywaną z tymi samymi parametrami.

sql-server sql-server-2012 Ian Boyd
źródło
2
Czy możesz opublikować plany zapytań - dobry bieg vs zły bieg?
Kin Shah,
4
Moim pierwszym przypuszczeniem byłoby zablokowanie ...
Tibor Karaszi
3
Kto to ocenił? To bardzo szczegółowe, dokładnie zbadane pytanie, mimo że brakuje w nim planów zapytań! +1 ode mnie!
Vérace
4
Jak doszedłeś do wniosku, że plany zapytań są „identyczne”? Chcesz powiedzieć, że mają ten sam kształt? Opublikuj je gdzieś, abyśmy też mogli porównać. Samo powiedzenie nam, że są identyczne, nie oznacza, że ​​są identyczne.
Aaron Bertrand
3
Dodanie planów wykonania automatycznego przy użyciu PasteThePlan może dać nam pojęcie, na co czekało zapytanie.
Randi Vertongen

Odpowiedzi:

2

Spójrz na wait_stats, a pokaże, jakie są największe wąskie gardła na twoim serwerze SQL.

Niedawno wystąpił problem polegający na tym, że aplikacja zewnętrzna działała sporadycznie powoli. Uruchamianie procedur przechowywanych na samym serwerze było jednak zawsze szybkie.

Monitorowanie wydajności wykazało, że nie ma się czym przejmować buforami SQL ani wykorzystaniem pamięci RAM i operacji wejścia / wyjścia na serwerze.

Tym, co pomogło zawęzić dochodzenie, było zapytanie statystyk oczekiwania, które są gromadzone przez SQL w sys.dm_os_wait_stats

Doskonały skrypt na stronie SQLSkills pokaże te, których najczęściej doświadczasz. Następnie możesz zawęzić wyszukiwanie w celu zidentyfikowania przyczyn.

Gdy dowiesz się, jakie są najważniejsze problemy, ten skrypt pomoże zawęzić oczekiwania dotyczące sesji / bazy danych:

SELECT OSW.session_id,
       OSW.wait_duration_ms,
       OSW.wait_type,
       DB_NAME(EXR.database_id) AS DatabaseName
FROM sys.dm_os_waiting_tasks OSW
INNER JOIN sys.dm_exec_sessions EXS ON OSW.session_id = EXS.session_id
INNER JOIN sys.dm_exec_requests EXR ON EXR.session_id = OSW.session_id
OPTION(Recompile);

Powyższe zapytanie i dalsze szczegóły pochodzą ze strony MSSQLTips .

sp_BlitzFirstSkrypt od Brent Ozar na stronie będą również pokazać, co powoduje spowolnienie.

KevH
źródło