Высокая загрузка ЦП с ASP.NET
Недавно мы столкнулись с регулярными скачками загрузки ЦП на нашем производственном сервере, особенно по вечерам во вторник (а иногда и вечером в понедельник), с 15-20-минутными интервалами (а иногда и реже). w3wp.exe (ASP.NET), но не смогли определить точную причину скачков.
Мы пробовали инструменты онлайн-мониторинга, но они не дали многообещающих результатов.
Ближайший результат, который я нашел, - это использование WinDbg и просмотр дампа процессов при скачках ЦП.
При запуске команды "! Syncblk", чтобы определить, какие потоки имеют блокировки, я получаю следующий результат, который не содержит идентификатора потока, который я мог бы исследовать дальше.
!syncblk Index SyncBlock MonitorHeld Recursion Owning Thread
Info SyncBlock Owner 163 00000000119712e8 410 0
0000000000000000 none 00000004bff6b488
System.Threading.TimerQueue
Я также попытался проанализировать некоторые из более длительных потоков, и единственное сходство, которое я вижу, - это следующее в трассировке стека.
000000002863ba28 000000007712c2ea [GCFrame: 000000002863ba28]
000000002863baf8 000000007712c2ea [HelperMethodFrame_1OBJ: 000000002863baf8] System.Threading.Monitor.ObjWait(Boolean, Int32, System.Object)
000000002863bc10 000007fe9cdfaadd System.Threading.ManualResetEventSlim.Wait(Int32, System.Threading.CancellationToken) [f:\dd\ndp\clr\src\BCL\System\Threading\ManualResetEventSlim.cs @ 670]
000000002863bcd0 000007fe9cdf9ceb System.Threading.Tasks.Task.SpinThenBlockingWait(Int32, System.Threading.CancellationToken) [f:\dd\ndp\clr\src\BCL\System\Threading\Tasks\Task.cs @ 3356]
000000002863bd60 000007fe9cdf946a System.Threading.Tasks.Task.InternalWait(Int32, System.Threading.CancellationToken) [f:\dd\ndp\clr\src\BCL\System\Threading\Tasks\Task.cs @ 3295]
000000002863be60 000007fe9cdf91d5 System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(System.Threading.Tasks.Task) [f:\dd\ndp\clr\src\BCL\System\Runtime\CompilerServices\TaskAwaiter.cs @ 167]
000000002863be90 000007fe9cd776f1 System.Runtime.CompilerServices.TaskAwaiter`1[[Microsoft.AspNet.Identity.Owin.SignInStatus, Microsoft.AspNet.Identity.Owin]].GetResult() [f:\dd\ndp\clr\src\BCL\System\Runtime\CompilerServices\TaskAwaiter.cs @ 373]
000000002863bec0 000007fe9cd774ab Microsoft.AspNet.Identity.AsyncHelper.RunSync[[Microsoft.AspNet.Identity.Owin.SignInStatus, Microsoft.AspNet.Identity.Owin]](System.Func`1>)
Похоже, что в классах AspNet.Identity есть какая-то проблема с блокировкой при попытке аутентифицировать пользователя. Это конкретно происходит в реализации класса «AuthorizeAttribute» в веб-API ASP.NET, где мы используем OWIN для аутентификации пользователя.
Кроме того, некоторые из наших других потоков, которые кажутся заблокированными, имеют следующий вывод WinDbg, но я не уверен, связано это или нет.
00000000048ddc28 000000007712c2ea [GCFrame: 00000000048ddc28]
00000000048dde20 000000007712c2ea [GCFrame: 00000000048dde20]
00000000048dde58 000000007712c2ea [HelperMethodFrame: 00000000048dde58] System.Threading.Monitor.Enter(System.Object)
00000000048ddf50 000007fe9c6403d5 System.Threading.TimerQueueTimer.Fire() [f:\dd\ndp\clr\src\BCL\System\Threading\Timer.cs @ 658]
00000000048ddfc0 000007fe9a98ccf3 System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem() [f:\dd\ndp\clr\src\BCL\System\Threading\ThreadPool.cs @ 1260]
00000000048de010 000007fe9a98b143 System.Threading.ThreadPoolWorkQueue.Dispatch() [f:\dd\ndp\clr\src\BCL\System\Threading\ThreadPool.cs @ 830]
00000000048de578 000007fef8e1afb3 [DebuggerU2MCatchHandlerFrame: 00000000048de578]
00000000048de708 000007fef8e1afb3 [ContextTransitionFrame: 00000000048de708]
00000000048de928 000007fef8e1afb3 [DebuggerU2MCatchHandlerFrame: 00000000048de928]
Любая помощь в этом определенно приветствуется.
ОБНОВИТЬ... После некоторого дополнительного исследования я, кажется, обнаружил два разных паттерна:
Во-первых, у нас есть несколько долго работающих потоков, которые, похоже, ждут возврата неуспешного ответа API (скорее всего, через токен отмены).
Во-вторых, когда я смотрю на потоки, которые блокируют другие потоки, я часто вижу, что он ожидает, пока таймеры истекут для элементов из объекта MemoryCache.
Я не уверен, помогает ли то, на что я смотрю, определить причину.
Вы пишете какой-нибудь асинхронный код? Вызов конкретно метода .Wait? Известно, что это вызывает взаимоблокировки в ASP.NET.
используйте ETW (WPR; / WPA) для анализа высокой загрузки ЦП
Что-то ожидающее, вероятно, не является причиной резкого скачка нагрузки на ЦП. Чтобы проанализировать проблему с производительностью, вам потребуется несколько аварийных дампов и построить статистику для стеков вызовов. Хотя procdump может создавать такие аварийные дампы, их очень сложно анализировать. По возможности используйте другие инструменты.
Спасибо за ответы. Мы не находимся в среде с балансировкой нагрузки, и это один сервер (хотя мы рассматриваем возможность использования балансировки нагрузки)
Кроме того, на основе анализа журналов запросов IIS я смог определить следующее: у нас есть некоторые запросы (которые обычно занимают менее 1 секунды), выполняемые за несколько минут, и когда это происходит, все они кажутся результатом в коде «sc-win32-status» либо 121 (что, как я полагаю, означает «Истек срок ожидания семафора»). Стоит отметить, что в другие дни недели на сайте почти такое же использование, и нет скачков ЦП как по вторникам, и нет автоматизированных заданий, выполняемых иначе в этот день недели, которые могли бы вызвать помехи
Еще я пытаюсь определить, вызвана ли проблема одним запросом (который блокирует другие запросы) или кульминацией нагрузки (то есть множеством одновременных запросов меньшего размера, которые приводят к скачку загрузки ЦП. Есть ли инструмент или процесс рекомендуется, чтобы помочь определить это?
«Я также попытался проанализировать некоторые из более длительных потоков». Если у вас есть только один дамп - вы действительно не знаете, какие потоки больше всего потребляли ЦП в проблемный период, и из-за этого вы можете прийти к неверным выводам. ! runaway покажет, сколько потоков ЦП потребляет с момента запуска процесса. Могу предположить, что вверху вы увидите пул потоков. TPL выполняется с пулом потоков, и это соответствует тому, что вы видите в стеке.
Сначала я бы собирал счетчики производительности для каждого потока «Поток \% загруженности процессора», «Поток \ ID потока», «Поток \ ID процесса» для процесса w3wp. И счетчики из ".NET CLR Memory" тоже. И попробуйте найти схему загрузки - высокий процессор из одного потока, пара потоков, много разных потоков или, может быть, из GC (% времени в счетчике GC). Обладая этими знаниями, вы можете глубже изучить дампы и проверить, какие потоки вызывают высокую загрузку процессора.
Кроме того, я бы порекомендовал бесплатный инструмент DebugDiag от Microsoft (debugdiag.com), с помощью которого вы можете легко создавать серии дампов вручную, а также используя правила и условия. Он также содержит функцию отчетов, которая может помочь вам решить вашу проблему или, по крайней мере, упростить первые шаги во время диагностики проблемы.
Поэтому я изначально использовал DebugDiag и выполнил некоторые отчеты, но они не дали значимых результатов. Я в основном видел, что были потоки в состязании, но было не очевидно, какие объекты они заблокированы / ожидают. Кроме того, я запускал процесс WinDbg несколько раз, и каждый раз анализ показывает, что поток с идентификатором «0» в основном блокирует System.Threading.TimerQueue. Я не думаю, что мы используем это где-нибудь в нашем приложении, поэтому я не уверен, что делать с этой информацией.
способ ETW также фиксирует данные о зависании. Также используйте WPA для анализа зависания
Какая у вас настройка IIS? Вы используете веб-сады?