Ladění hladovění fondu vláken
Tento článek se týká.NET ✔️ Core 3.1 a novějších verzí.
V tomto kurzu se dozvíte, jak ladit scénář hladovění Fondu vláken. K hladovění fondu vláken dochází v případě, že fond nemá žádná dostupná vlákna pro zpracování nových pracovních položek a aplikace často reagují pomalu. Pomocí uvedeného příkladu ASP.NET Core webové aplikace můžete způsobit úmyslné hladovění fondu ThreadPool a zjistit, jak ho diagnostikovat.
V tomto kurzu:
- Prozkoumání aplikace, která pomalu reaguje na požadavky
- Pomocí nástroje dotnet-counters zjistěte, že pravděpodobně dochází k hladovění fondu vláken.
- Pomocí nástroje dotnet-stack zjistěte, jaká práce udržuje vlákna ThreadPool zaneprázdněná.
Požadavky
Kurz používá:
- Sada .NET Core 6.0 SDK pro sestavení a spuštění ukázkové aplikace
- Ukázková webová aplikace , která demonstruje chování hladovění fondu vláken
- Bombardier pro generování zatížení pro ukázkovou webovou aplikaci
- dotnet-counters pro sledování čítačů výkonu
- dotnet-stack pro prozkoumání zásobníků vláken
Spuštění ukázkové aplikace
Stáhněte si kód pro ukázkovou aplikaci a sestavte ho pomocí sady .NET SDK:
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.26Spuštění aplikace:
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
Pokud používáte webový prohlížeč a odesíláte požadavky na https://localhost:5001/api/diagscenario/taskwaitadresu , měla by se odpověď success:taskwait vrátit přibližně po 500 ms. To ukazuje, že webový server obsluhuje provoz podle očekávání.
Dochází k nízkému výkonu
Ukázkový webový server má několik koncových bodů, které napodobení provedení databázového požadavku a následného vrácení odpovědi uživateli. Každý z těchto koncových bodů má při obsluhování požadavků po jednom zpoždění přibližně 500 ms, ale výkon je mnohem horší, když je webový server zatížen určitým zatížením. Stáhněte si nástroj pro zátěžové testování Bombardier a sledujte rozdíl v latenci, když se do každého koncového bodu odešle 125 souběžných požadavků.
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
Tento druhý koncový bod používá vzor kódu, který funguje ještě hůř:
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 tyto koncové body vykazují výrazně vyšší latenci, než je průměrná latence 500 ms, pokud je zatížení vysoké (3,48 s a 15,42 s). Pokud tento příklad spustíte ve starší verzi .NET Core, pravděpodobně oba příklady fungují stejně špatně. .NET 6 má aktualizovanou heuristiku ThreadPool, která snižuje dopad špatného vzoru kódování použitého v prvním příkladu na výkon.
Zjištění hladovění fondu vláken
Pokud byste zaznamenali výše uvedené chování u služby z reálného světa, věděli byste, že při zatížení reaguje pomalu, ale neznáte příčinu. dotnet-counters je nástroj, který může zobrazit živé čítače výkonu. Tyto čítače můžou poskytnout vodítka k určitým problémům a často se dají snadno získat. V produkčních prostředích můžete mít podobné čítače poskytované nástroji pro vzdálené monitorování a webovými řídicími panely. Nainstalujte dotnet-counters a začněte monitorovat webovou službu:
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
Výše uvedené čítače jsou příkladem, když webový server nevysílá žádné požadavky. Spusťte Bombardier znovu s koncovým bodem a trvalým zatížením po dobu 2 minut, abyste mohli sledovat, co se stane s api/diagscenario/tasksleepwait čítači výkonu.
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s
Nedostatek fondu vláken nastane, když neexistují žádná volná vlákna pro zpracování pracovních položek ve frontě a modul runtime reaguje zvýšením počtu vláken ThreadPool. Měli byste pozorovat ThreadPool Thread Count rychlý nárůst až 2 až 3x počet jader procesoru na vašem počítači a pak se přidávají další vlákna 1–2 za sekundu, dokud se nakonec nestabilují někam nad 125. Pomalý a stálý nárůst vláken ThreadPool v kombinaci s využitím procesoru mnohem méně než 100 % jsou klíčovými signály, že hladovění ThreadPoolu je v současné době kritickým bodem výkonu. Zvýšení počtu vláken bude pokračovat, dokud fond nenasáhne maximální počet vláken, nebyl vytvořen dostatečný počet vláken pro uspokojení všech příchozích pracovních položek, nebo dokud nedojde k nasycení procesoru. Často, ale ne vždy, bude nedostatek fondu vláken také zobrazovat velké hodnoty pro ThreadPool Queue Length a nízké hodnoty pro ThreadPool Completed Work Item Count, což znamená, že existuje velké množství čekající práce a málo dokončené práce. Tady je příklad čítačů, zatímco počet vláken stále roste:
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
Jakmile se počet vláken ThreadPool stabilizuje, fond přestane hladovět. Pokud se ale stabilizuje na vysoké hodnotě (více než přibližně trojnásobek počtu jader procesoru), obvykle to značí, že kód aplikace blokuje některá vlákna ThreadPool a ThreadPool je kompenzován spuštěním s více vlákny. Stabilní běh při vysokém počtu vláken nemusí mít nutně velký dopad na latenci požadavků, ale pokud se zatížení v průběhu času výrazně mění nebo se aplikace bude pravidelně restartovat, pak pokaždé, když ThreadPool pravděpodobně přejde do období hladovění, kdy pomalu roste počet vláken a poskytuje nízkou latenci požadavků. Každé vlákno také spotřebovává paměť, takže snížení celkového počtu potřebných vláken přináší další výhodu.
Od verze .NET 6 byla heuristika ThreadPool upravena tak, aby se v reakci na určitá blokující rozhraní API úloh vertikálně navyšoval počet vláken ThreadPool mnohem rychleji. U těchto rozhraní API může stále docházet k nedostatku fondu vláken, ale doba trvání je mnohem kratší než u starších verzí .NET, protože modul runtime reaguje rychleji. Spusťte znovu Bombardier s api/diagscenario/taskwait koncovým bodem:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
V .NET 6 byste měli sledovat, že fond zvyšuje počet vláken rychleji než dříve a pak se stabilizuje na vysokém počtu vláken. V době, kdy počet vláken stoupá, dochází k hladovění fondu vláken.
Řešení potíží s hladověním fondu vláken
Aby se zabránilo omezení fondu vláken, musí vlákna fondu vláken zůstat odblokovaná, aby byla k dispozici pro zpracování příchozích pracovních položek. Existují dva způsoby, jak zjistit, co jednotlivá vlákna prováděla, a to buď pomocí nástroje dotnet-stack , nebo zachycením výpisu paměti pomocí příkazu dotnet-dump , který lze zobrazit v sadě Visual Studio. dotnet-stack může být rychlejší, protože v konzole zobrazí zásobníky vláken okamžitě, ale ladění výpisu stavu systému Visual Studio nabízí lepší vizualizace, které mapují rámce na zdroj, Just My Code může filtrovat rámce implementace modulu runtime a funkce Paralelní zásobníky může pomoct seskupit velký počet vláken s podobnými zásobníky. Tento kurz ukazuje možnost dotnet-stack. Příklad zkoumání zásobníků vláken pomocí sady Visual Studio najdete ve videu o diagnostice vyhladovění fondu vláken .
Spusťte znovu Bombardier, aby se webový server zatížil:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
Potom spusťte dotnet-stack a zobrazte trasování zásobníku vláken:
dotnet-stack report -n DiagnosticScenarios
Měl by se zobrazit dlouhý výstup obsahující velký počet zásobníků, z nichž mnohé vypadají takto:
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()
Rámce v dolní části těchto zásobníků označují, že tato vlákna jsou vlákna ThreadPool:
System.Private.CoreLib.il!System.Threading.ThreadPoolWorkQueue.Dispatch()
System.Private.CoreLib.il!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
Snímky v horní části ukazují, že vlákno je blokováno při volání GetResultCore(bool) z funkce 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()
Teď můžete přejít na kód tohoto kontroleru v souboru Controllers/DiagnosticScenarios.cs ukázkové aplikace a zjistit, že volá asynchronní rozhraní API bez použití awaitpříkazu . Toto je vzor kódu sync-over-async , o kterém je známo, že blokuje vlákna a je nejčastější příčinou hladovění Fondu vláken.
public ActionResult<string> TaskWait()
{
// ...
Customer c = PretendQueryCustomerFromDbAsync("Dana").Result;
return "success:taskwait";
}
V takovém případě je možné kód snadno změnit tak, aby místo toho používal async/await, jak je znázorněno v koncovém TaskAsyncWait() bodu. Použití příkazu await umožňuje aktuálnímu vláknu obsluhovat jiné pracovní položky, zatímco probíhá dotaz na databázi. Po dokončení vyhledávání v databázi bude vlákno ThreadPool pokračovat v provádění. Tímto způsobem se během každého požadavku nezablokuje žádné vlákno v kódu:
public async Task<ActionResult<string>> TaskAsyncWait()
{
// ...
Customer c = await PretendQueryCustomerFromDbAsync("Dana");
return "success:taskasyncwait";
}
Spuštění Bombadieru pro odeslání zatížení do koncového api/diagscenario/taskasyncwait bodu ukazuje, že počet vláken ThreadPool zůstává mnohem nižší a průměrná latence se při použití přístupu async/await stále blíží 500ms:
>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
