Debugowanie starvation puli wątków
Ten artykuł dotyczy: ✔️ .NET Core 3.1 i nowszych wersji
Z tego samouczka dowiesz się, jak debugować scenariusz głodu threadpool. W przypadku braku dostępnych wątków pula wątków do przetwarzania nowych elementów roboczych często powoduje powolne reagowanie aplikacji. Korzystając z podanego przykładu ASP.NET Core aplikacji internetowej, możesz celowo spowodować zagęszczanie puli ThreadPool i dowiedzieć się, jak ją zdiagnozować.
W tym samouczku wykonasz następujące czynności:
- Badanie aplikacji, która odpowiada na żądania powoli
- Użyj narzędzia dotnet-counters, aby zidentyfikować zagwiazdkę ThreadPool, która prawdopodobnie występuje
- Użyj narzędzia dotnet-stack, aby określić, jaka praca utrzymuje zajęte wątki ThreadPool
Wymagania wstępne
W tym samouczku są używane następujące elementy:
- Zestaw SDK platformy .NET Core 6.0 do kompilowania i uruchamiania przykładowej aplikacji
- Przykładowa aplikacja internetowa do zademonstrowania zachowania zagęszczania puli wątków
- Bombardier w celu wygenerowania obciążenia dla przykładowej aplikacji internetowej
- dotnet-counters do obserwowania liczników wydajności
- dotnet-stack do badania stosów wątków
Uruchamianie przykładowej aplikacji
Pobierz kod przykładowej aplikacji i skompiluj go przy użyciu zestawu SDK platformy .NET:
E:\demo\DiagnosticScenarios>dotnet build Microsoft (R) Build Engine version 17.1.1+a02f73656 for .NET Copyright (C) Microsoft Corporation. All rights reserved. Determining projects to restore... All projects are up-to-date for restore. DiagnosticScenarios -> E:\demo\DiagnosticScenarios\bin\Debug\net6.0\DiagnosticScenarios.dll Build succeeded. 0 Warning(s) 0 Error(s) Time Elapsed 00:00:01.26Uruchom aplikację:
E:\demo\DiagnosticScenarios>bin\Debug\net6.0\DiagnosticScenarios.exe info: Microsoft.Hosting.Lifetime[14] Now listening on: http://localhost:5000 info: Microsoft.Hosting.Lifetime[14] Now listening on: https://localhost:5001 info: Microsoft.Hosting.Lifetime[0] Application started. Press Ctrl+C to shut down. info: Microsoft.Hosting.Lifetime[0] Hosting environment: Production info: Microsoft.Hosting.Lifetime[0] Content root path: E:\demo\DiagnosticScenarios
Jeśli używasz przeglądarki internetowej i wysyłasz żądania do https://localhost:5001/api/diagscenario/taskwaitusługi , powinna zostać wyświetlona odpowiedź success:taskwait zwrócona po około 500 ms. Oznacza to, że serwer internetowy obsługuje ruch zgodnie z oczekiwaniami.
Obserwowanie niskiej wydajności
Demonstracyjny serwer internetowy ma kilka punktów końcowych, które kpią z żądania bazy danych, a następnie zwracają odpowiedź użytkownikowi. Każdy z tych punktów końcowych ma opóźnienie około 500 ms podczas obsługi żądań pojedynczo, ale wydajność jest znacznie gorsza, gdy serwer internetowy jest obciążony. Pobierz narzędzie do testowania obciążenia bombardiera i obserwuj różnicę w opóźnieniu, gdy do każdego punktu końcowego są wysyłane 125 równoczesnych żądań.
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait
Bombarding https://localhost:5001/api/diagscenario/taskwait for 10s using 125 connection(s)
[=============================================================================================] 10s
Done!
Statistics Avg Stdev Max
Reqs/sec 33.06 234.67 3313.54
Latency 3.48s 1.39s 10.79s
HTTP codes:
1xx - 0, 2xx - 454, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 75.37KB/s
Ten drugi punkt końcowy używa wzorca kodu, który działa jeszcze gorzej:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait
Bombarding https://localhost:5001/api/diagscenario/tasksleepwait for 10s using 125 connection(s)
[=============================================================================================] 10s
Done!
Statistics Avg Stdev Max
Reqs/sec 1.61 35.25 788.91
Latency 15.42s 2.18s 18.30s
HTTP codes:
1xx - 0, 2xx - 140, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 36.57KB/s
Oba te punkty końcowe pokazują znacznie więcej niż średnie opóźnienie 500 ms, gdy obciążenie jest wysokie (odpowiednio 3,48 s i 15,42 s). Jeśli uruchomisz ten przykład na starszej wersji platformy .NET Core, prawdopodobnie oba przykłady będą działać równie źle. Platforma .NET 6 zaktualizowała heurystyki threadpool, które zmniejszają wpływ na wydajność złego wzorca kodowania używanego w pierwszym przykładzie.
Wykrywanie zagęszczania puli wątków
Jeśli zaobserwowano powyższe zachowanie w rzeczywistej usłudze, wiesz, że odpowiada powoli pod obciążeniem, ale nie znasz przyczyny. dotnet-counters to narzędzie, które może wyświetlać liczniki wydajności na żywo. Te liczniki mogą dostarczać wskazówek dotyczących niektórych problemów i często są łatwe do uzyskania. W środowiskach produkcyjnych mogą istnieć podobne liczniki udostępniane przez narzędzia do monitorowania zdalnego i internetowe pulpity nawigacyjne. Zainstaluj liczniki dotnet-counter i rozpocznij monitorowanie usługi internetowej:
dotnet-counters monitor -n DiagnosticScenarios
Press p to pause, r to resume, q to quit.
Status: Running
[System.Runtime]
% Time in GC since last GC (%) 0
Allocation Rate (B / 1 sec) 0
CPU Usage (%) 0
Exception Count (Count / 1 sec) 0
GC Committed Bytes (MB) 0
GC Fragmentation (%) 0
GC Heap Size (MB) 34
Gen 0 GC Count (Count / 1 sec) 0
Gen 0 Size (B) 0
Gen 1 GC Count (Count / 1 sec) 0
Gen 1 Size (B) 0
Gen 2 GC Count (Count / 1 sec) 0
Gen 2 Size (B) 0
IL Bytes Jitted (B) 279,021
LOH Size (B) 0
Monitor Lock Contention Count (Count / 1 sec) 0
Number of Active Timers 0
Number of Assemblies Loaded 121
Number of Methods Jitted 3,223
POH (Pinned Object Heap) Size (B) 0
ThreadPool Completed Work Item Count (Count / 1 sec) 0
ThreadPool Queue Length 0
ThreadPool Thread Count 1
Time spent in JIT (ms / 1 sec) 0.387
Working Set (MB) 87
Powyższe liczniki są przykładem, gdy serwer internetowy nie obsługiwał żadnych żądań. Uruchom ponownie bombardier z api/diagscenario/tasksleepwait punktem końcowym i trwałym obciążeniem przez 2 minuty, więc jest mnóstwo czasu, aby obserwować, co się dzieje z licznikami wydajności.
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s
Zagęszczanie puli wątków występuje, gdy nie ma wolnych wątków do obsługi elementów roboczych w kolejce, a środowisko uruchomieniowe reaguje, zwiększając liczbę wątków ThreadPool. Należy obserwować ThreadPool Thread Count szybki wzrost do 2-3x liczby rdzeni procesora na maszynie, a następnie kolejne wątki są dodawane 1-2 na sekundę, aż ostatecznie ustabilizować się gdzieś powyżej 125. Powolny i stały wzrost wątków ThreadPool w połączeniu z użyciem procesora CPU znacznie mniej niż 100% są kluczowymi sygnałami, że głodowanie ThreadPool jest obecnie wąskim gardłem wydajności. Zwiększenie liczby wątków będzie kontynuowane, dopóki pula nie osiągnie maksymalnej liczby wątków, utworzono wystarczającą liczbę wątków, aby spełnić wszystkie przychodzące elementy robocze lub procesor został nasycony. Często, ale nie zawsze, głodowanie ThreadPool będzie również pokazywać duże wartości dla ThreadPool Queue Length i niskie wartości dla ThreadPool Completed Work Item Count, co oznacza, że istnieje duża ilość oczekujących prac i niewiele pracy jest ukończone. Oto przykład liczników, gdy liczba wątków nadal rośnie:
Press p to pause, r to resume, q to quit.
Status: Running
[System.Runtime]
% Time in GC since last GC (%) 0
Allocation Rate (B / 1 sec) 24,480
CPU Usage (%) 0
Exception Count (Count / 1 sec) 0
GC Committed Bytes (MB) 56
GC Fragmentation (%) 40.603
GC Heap Size (MB) 89
Gen 0 GC Count (Count / 1 sec) 0
Gen 0 Size (B) 6,306,160
Gen 1 GC Count (Count / 1 sec) 0
Gen 1 Size (B) 8,061,400
Gen 2 GC Count (Count / 1 sec) 0
Gen 2 Size (B) 192
IL Bytes Jitted (B) 279,263
LOH Size (B) 98,576
Monitor Lock Contention Count (Count / 1 sec) 0
Number of Active Timers 124
Number of Assemblies Loaded 121
Number of Methods Jitted 3,227
POH (Pinned Object Heap) Size (B) 1,197,336
ThreadPool Completed Work Item Count (Count / 1 sec) 2
ThreadPool Queue Length 29
ThreadPool Thread Count 96
Time spent in JIT (ms / 1 sec) 0
Working Set (MB) 152
Gdy liczba wątków ThreadPool zostanie ustabilizowana, pula nie będzie już głodna. Jeśli jednak stabilizuje się na wysokiej wartości (więcej niż trzy razy więcej niż trzy razy więcej rdzeni procesora), zwykle oznacza to, że kod aplikacji blokuje niektóre wątki ThreadPool, a pula ThreadPool jest wyrównująca przez uruchomienie z większą liczbą wątków. Stałe działanie z dużą liczbą wątków nie musi mieć dużego wpływu na opóźnienie żądania, ale jeśli obciążenie znacznie się zmienia w czasie lub aplikacja będzie okresowo uruchamiana ponownie, za każdym razem, gdy pula wątków prawdopodobnie wejdzie w okres głodu, w którym powoli zwiększa liczbę wątków i dostarcza słabe opóźnienie żądań. Każdy wątek zużywa również pamięć, więc zmniejszenie całkowitej liczby potrzebnych wątków zapewnia kolejną korzyść.
Począwszy od platformy .NET 6, heurystyka puli ThreadPool została zmodyfikowana w celu skalowania w górę liczby wątków ThreadPool znacznie szybciej w odpowiedzi na niektóre blokujące interfejsy API zadań. W przypadku tych interfejsów API nadal może wystąpić zagęszczanie puli wątków, ale czas trwania jest znacznie krótszy niż w przypadku starszych wersji platformy .NET, ponieważ środowisko uruchomieniowe reaguje szybciej. Uruchom ponownie bombardier z api/diagscenario/taskwait punktem końcowym:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
Na platformie .NET 6 należy obserwować, jak pula zwiększa liczbę wątków szybciej niż wcześniej, a następnie stabilizuje się na dużej liczbie wątków. W trakcie wspinaczki liczby wątków występuje głodowanie puli wątków.
Rozpoznawanie zagęszczania puli wątków
Aby wyeliminować głód wątków ThreadPool, wątki ThreadPool muszą pozostać odblokowane, aby były dostępne do obsługi przychodzących elementów roboczych. Istnieją dwa sposoby określania, co robi każdy wątek, za pomocą narzędzia dotnet-stack lub przechwytywania zrzutu za pomocą polecenia dotnet-dump , który można wyświetlić w programie Visual Studio. narzędzie dotnet-stack może być szybsze, ponieważ wyświetla stosy wątków natychmiast w konsoli, ale debugowanie zrzutów programu Visual Studio oferuje lepsze wizualizacje mapowane ramki na źródło. Funkcja Just My Code może odfiltrować ramki implementacji środowiska uruchomieniowego, a funkcja Stosy równoległe może pomóc w grupowaniu dużej liczby wątków z podobnymi stosami. W tym samouczku przedstawiono opcję dotnet-stack. Aby zapoznać się z przykładem badania stosów wątków przy użyciu programu Visual Studio, zobacz film z samouczkiem dotyczącym diagnozowania buforu wątków .
Uruchom ponownie serwer Bombardier, aby załadować serwer internetowy:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
Następnie uruchom polecenie dotnet-stack, aby wyświetlić ślady stosu wątku:
dotnet-stack report -n DiagnosticScenarios
Powinny zostać wyświetlone długie dane wyjściowe zawierające dużą liczbę stosów, z których wiele wygląda następująco:
Thread (0x25968):
[Native Frames]
System.Private.CoreLib.il!System.Threading.ManualResetEventSlim.Wait(int32,value class System.Threading.CancellationToken)
System.Private.CoreLib.il!System.Threading.Tasks.Task.SpinThenBlockingWait(int32,value class System.Threading.CancellationToken)
System.Private.CoreLib.il!System.Threading.Tasks.Task.InternalWaitCore(int32,value class System.Threading.CancellationToken)
System.Private.CoreLib.il!System.Threading.Tasks.Task`1[System.__Canon].GetResultCore(bool)
DiagnosticScenarios!testwebapi.Controllers.DiagScenarioController.TaskWait()
Anonymously Hosted DynamicMethods Assembly!dynamicClass.lambda_method1(pMT: 00007FF7A8CBF658,class System.Object,class System.Object[])
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor+SyncObjectResultExecutor.Execute(class Microsoft.AspNetCore.Mvc.Infrastructure.IActionResultTypeMapper,class Microsoft.Extensions.Internal.ObjectMethodExecutor,class System.Object,class System.Object[])
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeActionMethodAsync()
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(value class State&,value class Scope&,class System.Object&,bool&)
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(value class State&,value class Scope&,class System.Object&,bool&)
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeNextActionFilterAsync()
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(value class State&,value class Scope&,class System.Object&,bool&)
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.InvokeInnerFilterAsync()
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(value class State&,value class Scope&,class System.Object&,bool&)
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeFilterPipelineAsync()
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.InvokeAsync()
Microsoft.AspNetCore.Mvc.Core.il!Microsoft.AspNetCore.Mvc.Routing.ControllerRequestDelegateFactory+<>c__DisplayClass10_0.<CreateRequestDelegate>b__0(class Microsoft.AspNetCore.Http.HttpContext)
Microsoft.AspNetCore.Routing.il!Microsoft.AspNetCore.Routing.EndpointMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
Microsoft.AspNetCore.Authorization.Policy.il!Microsoft.AspNetCore.Authorization.AuthorizationMiddleware+<Invoke>d__6.MoveNext()
System.Private.CoreLib.il!System.Runtime.CompilerServices.AsyncMethodBuilderCore.Start(!!0&)
Microsoft.AspNetCore.Authorization.Policy.il!Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
Microsoft.AspNetCore.HttpsPolicy.il!Microsoft.AspNetCore.HttpsPolicy.HttpsRedirectionMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
Microsoft.AspNetCore.HttpsPolicy.il!Microsoft.AspNetCore.HttpsPolicy.HstsMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
Microsoft.AspNetCore.HostFiltering.il!Microsoft.AspNetCore.HostFiltering.HostFilteringMiddleware.Invoke(class Microsoft.AspNetCore.Http.HttpContext)
Microsoft.AspNetCore.Server.Kestrel.Core.il!Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol+<ProcessRequests>d__223`1[System.__Canon].MoveNext()
System.Private.CoreLib.il!System.Threading.ExecutionContext.RunInternal(class System.Threading.ExecutionContext,class System.Threading.ContextCallback,class System.Object)
System.Private.CoreLib.il!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.Threading.Tasks.VoidTaskResult,Microsoft.AspNetCore.Server.Kestrel.Core.Internal.Http.HttpProtocol+<ProcessRequests>d__223`1[System.__Canon]].MoveNext(class System.Threading.Thread)
System.Private.CoreLib.il!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(class System.Runtime.CompilerServices.IAsyncStateMachineBox,bool)
System.Private.CoreLib.il!System.Threading.Tasks.Task.RunContinuations(class System.Object)
System.IO.Pipelines.il!System.IO.Pipelines.StreamPipeReader+<<ReadAsync>g__Core|36_0>d.MoveNext()
System.Private.CoreLib.il!System.Threading.ExecutionContext.RunInternal(class System.Threading.ExecutionContext,class System.Threading.ContextCallback,class System.Object)
System.Private.CoreLib.il!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.IO.Pipelines.ReadResult,System.IO.Pipelines.StreamPipeReader+<<ReadAsync>g__Core|36_0>d].MoveNext(class System.Threading.Thread)
System.Private.CoreLib.il!System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(class System.Runtime.CompilerServices.IAsyncStateMachineBox,bool)
System.Private.CoreLib.il!System.Threading.Tasks.Task.RunContinuations(class System.Object)
System.Private.CoreLib.il!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1[System.Int32].SetExistingTaskResult(class System.Threading.Tasks.Task`1<!0>,!0)
System.Net.Security.il!System.Net.Security.SslStream+<ReadAsyncInternal>d__186`1[System.Net.Security.AsyncReadWriteAdapter].MoveNext()
System.Private.CoreLib.il!System.Threading.ExecutionContext.RunInternal(class System.Threading.ExecutionContext,class System.Threading.ContextCallback,class System.Object)
System.Private.CoreLib.il!System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1+AsyncStateMachineBox`1[System.Int32,System.Net.Security.SslStream+<ReadAsyncInternal>d__186`1[System.Net.Security.AsyncReadWriteAdapter]].MoveNext(class System.Threading.Thread)
Microsoft.AspNetCore.Server.Kestrel.Core.il!Microsoft.AspNetCore.Server.Kestrel.Core.Internal.DuplexPipeStream+<ReadAsyncInternal>d__27.MoveNext()
System.Private.CoreLib.il!System.Threading.ExecutionContext.RunInternal(class System.Threading.ExecutionContext,class System.Threading.ContextCallback,class System.Object)
System.Private.CoreLib.il!System.Threading.ThreadPoolWorkQueue.Dispatch()
System.Private.CoreLib.il!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
Ramki u dołu tych stosów wskazują, że te wątki są wątkami ThreadPool:
System.Private.CoreLib.il!System.Threading.ThreadPoolWorkQueue.Dispatch()
System.Private.CoreLib.il!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
A ramki w górnej części ujawniają, że wątek jest zablokowany w wywołaniu metody GetResultCore(bool) z funkcji DiagnosticScenarioController.TaskWait():
Thread (0x25968):
[Native Frames]
System.Private.CoreLib.il!System.Threading.ManualResetEventSlim.Wait(int32,value class System.Threading.CancellationToken)
System.Private.CoreLib.il!System.Threading.Tasks.Task.SpinThenBlockingWait(int32,value class System.Threading.CancellationToken)
System.Private.CoreLib.il!System.Threading.Tasks.Task.InternalWaitCore(int32,value class System.Threading.CancellationToken)
System.Private.CoreLib.il!System.Threading.Tasks.Task`1[System.__Canon].GetResultCore(bool)
DiagnosticScenarios!testwebapi.Controllers.DiagScenarioController.TaskWait()
Teraz możesz przejść do kodu dla tego kontrolera w pliku Controllers/DiagnosticScenarios.cs przykładowej aplikacji, aby zobaczyć, że wywołuje on asynchroniczny interfejs API bez użycia polecenia await. Jest to wzorzec kodu sync-over-async , który jest znany z blokowania wątków i jest najczęstszą przyczyną głodu threadpool.
public ActionResult<string> TaskWait()
{
// ...
Customer c = PretendQueryCustomerFromDbAsync("Dana").Result;
return "success:taskwait";
}
W takim przypadku kod można łatwo zmienić, aby zamiast tego używać async/await, jak pokazano w punkcie TaskAsyncWait() końcowym. Użycie funkcji await umożliwia bieżącemu wątkowi obsługę innych elementów roboczych, gdy zapytanie bazy danych jest w toku. Po zakończeniu wyszukiwania bazy danych wątek ThreadPool wznowi wykonywanie. W ten sposób żaden wątek nie jest blokowany w kodzie podczas każdego żądania:
public async Task<ActionResult<string>> TaskAsyncWait()
{
// ...
Customer c = await PretendQueryCustomerFromDbAsync("Dana");
return "success:taskasyncwait";
}
Uruchomienie narzędzia Bombadier w celu wysłania obciążenia do punktu końcowego api/diagscenario/taskasyncwait pokazuje, że liczba wątków ThreadPool pozostaje znacznie niższa, a średnie opóźnienie pozostaje w pobliżu 500 ms podczas korzystania z podejścia asynchronicznego/await:
>bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskasyncwait
Bombarding https://localhost:5001/api/diagscenario/taskasyncwait for 10s using 125 connection(s)
[=============================================================================================] 10s
Done!
Statistics Avg Stdev Max
Reqs/sec 227.92 274.27 1263.48
Latency 532.58ms 58.64ms 1.14s
HTTP codes:
1xx - 0, 2xx - 2390, 3xx - 0, 4xx - 0, 5xx - 0
others - 0
Throughput: 98.81KB/s
