Это признак перегрузки сервера?

12

Я пытался диагностировать замедления в приложении. Для этого я зарегистрировал расширенные события SQL Server .

  • Для этого вопроса я смотрю на одну конкретную хранимую процедуру.
  • Но есть основной набор из дюжины хранимых процедур, которые в равной степени могут быть использованы в качестве расследования яблоки к яблокам
  • и всякий раз, когда я вручную запускаю одну из хранимых процедур, она всегда работает быстро
  • и если пользователь попытается снова: он будет работать быстро.

Время выполнения хранимой процедуры сильно различается. Многие из выполнений этой хранимой процедуры возвращаются в <1s:

введите описание изображения здесь

И для этого "быстрого" ведра это намного меньше, чем 1 с. Это на самом деле около 90 мс:

введите описание изображения здесь

Но есть длинный хвост пользователей, которые должны ждать 2 секунды, 3 секунды, 4 секунды. Некоторым приходится ждать 12, 13, 14. Тогда есть действительно бедные души, которые должны ждать 22, 23, 24.

И через 30 секунд клиентское приложение сдается, прерывает запрос, и пользователю пришлось ждать 30 секунд .

Корреляция, чтобы найти причинно-следственную связь

Поэтому я попытался соотнести:

  • продолжительность против логического чтения
  • продолжительность против физического чтения
  • продолжительность против времени процессора

И никто, кажется, не дает никакой корреляции; кажется, никто не является причиной

  • Продолжительность и логическое чтение : при небольшом или большом количестве логических операций длительность все еще сильно колеблется :

    введите описание изображения здесь

  • Продолжительность по сравнению с физическим чтением : даже если запрос не был обработан из кэша и потребовалось много физических чтений, это не влияет на продолжительность:

    введите описание изображения здесь

  • Продолжительность по сравнению с временем процессора . Независимо от того, занимал ли запрос 0 с процессорного времени или целых 2.5 с процессорного времени, длительности имеют одинаковую изменчивость:

    введите описание изображения здесь

Бонус : я заметил, что Duration v Physical Reads и Duration v CPU time выглядят очень похоже. Это доказано, если я попытаюсь сопоставить процессорное время с физическими чтениями:

введите описание изображения здесь

Оказывается, что загрузка ЦП происходит из-за ввода-вывода. Кто знал!

Так что, если в процессе выполнения запроса нет ничего, что могло бы объяснить разницу во времени выполнения, означает ли это, что это что-то не связанное с процессором или жестким диском?

Если бы узким местом были процессор или жесткий диск; не будет ли это узким местом?

Если мы предположим, что узким местом было именно процессор; что процессор недостаточно загружен для этого сервера:

  • тогда не потребуются ли для выполнения, использующие больше процессорного времени, больше времени?
  • так как они должны завершить с другими, используя перегруженный процессор?

Аналогично для жестких дисков. Если мы предположим, что жесткий диск был узким местом; что жестким дискам не хватает произвольной пропускной способности для этого сервера:

  • тогда не будет ли выполнение с использованием большего количества физических чтений занимать больше времени?
  • так как они должны завершить с другими, используя перегруженный ввод-вывод жесткого диска?

Сама хранимая процедура не выполняет и не требует никаких записей.

  • Обычно он возвращает 0 строк (90%).
  • Иногда он вернет 1 строку (7%).
  • Редко он вернет 2 строки (1,4%).
  • И в худшем случае он возвратил более 2 строк (один раз возвращая 12 строк)

Так что не похоже, что он возвращает безумный объем данных.

Использование ЦП сервера

Загрузка процессора процессором составляет в среднем около 1,8%, с периодическим всплеском до 18%, поэтому не похоже, что загрузка процессора является проблемой:

введите описание изображения здесь

Таким образом, процессор сервера не перегружен.

Но сервер является виртуальным ...

Что-то за пределами вселенной?

Единственное, что я могу себе представить, это то, что существует вне вселенной сервера.

  • если это не логично читает
  • и это не физическое чтение
  • и это не использование процессора
  • и это не загрузка процессора

И это не похоже на параметры хранимой процедуры (потому что выдает тот же запрос вручную, и это не занимает 27 секунд - это занимает ~ 0 секунд).

Что еще может учитывать сервер, иногда требующий 30 секунд, а не 0 секунд, для запуска той же скомпилированной хранимой процедуры.

  • контрольно-пропускные пункты?

Это виртуальный сервер

  • хост перегружен?
  • другая виртуальная машина на том же хосте?

Проходя через расширенные события сервера; больше ничего не происходит, когда запрос внезапно занимает 20 секунд. Он работает нормально, а затем решает не работать нормально:

  • 2 секунды
  • 1 секунда
  • 30 секунд
  • 3 секунды
  • 2 секунды

И нет других особенно напряженных предметов, которые я могу найти. Это не во время каждого 2-часового резервного копирования журнала транзакций.

Что еще это может быть?

Есть ли что-нибудь, что я могу сказать, кроме: "сервер" ?

Изменить : коррелировать по времени суток

Я понял, что я связал продолжительность со всем:

  • логическое чтение
  • физическое чтение
  • использование процессора

Но единственное, с чем я не соотносил это, было время суток . Возможно, проблема заключается в резервном копировании журнала транзакций каждые 2 часа .

Или , возможно, замедление этого происходит в патронах во время контрольно - пропускных пунктов?

Нет:

введите описание изображения здесь

Intel Xeon Gold Quad-core 6142.

Редактировать - люди предполагают план выполнения запроса

Люди предполагают, что планы выполнения запросов должны различаться между «быстрым» и «медленным». Они не.

И мы можем увидеть это сразу после осмотра.

Мы знаем, что большая продолжительность вопроса не из-за «плохого» плана выполнения:

  • тот, который взял более логичные чтения
  • тот, который потреблял больше процессора из-за большего количества соединений и поиска ключей

Поскольку, если увеличение чтения или увеличение ЦП было причиной увеличения длительности запроса, то мы уже видели это выше. Там нет корреляции.

Но давайте попробуем сопоставить длительность с метрикой продукта области чтения ЦП:

введите описание изображения здесь

Корреляции становится еще меньше - это парадокс.

Изменить : Обновлены диаграммы разброса, чтобы обойти ошибку в точечных диаграммах Excel с большим количеством значений.

Следующие шаги

Следующие мои шаги будут заключаться в том, чтобы заставить кого-то на сервере генерировать события для заблокированных запросов - через 5 секунд:

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

Не будет объяснено, заблокированы ли запросы на 4 секунды. Но, возможно, все, что блокирует запрос на 5 секунд, также блокирует некоторые на 4 секунды.

Медленные планы

Вот медленный план двух хранимых процедур:

  • `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'

Одна и та же хранимая процедура с теми же параметрами запускается вплотную:

| 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 |

Звоните 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

Звонок 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

Имеет смысл, чтобы планы были идентичными; он выполняет ту же хранимую процедуру с теми же параметрами.

sql-server sql-server-2012 Ян Бойд
источник
2
Можете ли вы опубликовать планы запросов - хороший запуск или плохой запуск?
Кин Шах
4
Моим первым предположением будет блокировка ...
Тибор Караси
3
Кто это проголосовал? Это очень детальный, тщательно изученный вопрос, хотя в нем отсутствуют планы запросов! +1 от меня!
Верас
4
Как вы пришли к выводу, что планы запросов "идентичны"? Вы просто имеете в виду, что они имеют одинаковую форму? Опубликуйте их где-нибудь, чтобы мы тоже могли их сравнить. Просто сказать нам, что они идентичны, не значит, что они идентичны.
Аарон Бертран
3
Добавление точных планов выполнения с использованием PasteThePlan может дать нам представление о том, что ожидает запрос.
Рэнди Вертонген

Ответы:

2

Посмотрите на wait_stats, и он покажет, какие самые узкие места существуют на вашем SQL-сервере.

Недавно я столкнулся с проблемой, когда внешнее приложение было медленным. Хотя запуск хранимых процедур на самом сервере всегда был быстрым.

Мониторинг производительности показал, что вообще не стоит беспокоиться о кешах SQL или использовании оперативной памяти и ввода-вывода на сервере.

Что помогло сузить расследование, так это запрос статистики ожидания, собираемой SQL в sys.dm_os_wait_stats

Отличный сценарий на веб-сайте SQLSkills покажет вам те, которые вы испытываете больше всего. Затем вы можете сузить область поиска, чтобы определить причины.

Как только вы узнаете, какие ожидания являются большими проблемами, этот скрипт поможет сузить, какой сеанс / база данных испытывает ожидания:

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);

Вышеуказанный запрос и дополнительная информация с веб-сайта MSSQLTips .

sp_BlitzFirstСценарий от Brent Ozar в сайте также покажет вам , что вызывает замедление.

KevH
источник