ThreadPool éhezés hibakeresése
Ez a cikk a következő verziókra vonatkozik: ✔️ .NET Core 3.1 és újabb verziók
Ebben az oktatóanyagban megtudhatja, hogyan végezhet hibakeresést a ThreadPool éhezési forgatókönyvében. A ThreadPool éhezése akkor fordul elő, ha a készletben nincsenek olyan szálak, amelyek feldolgozzák az új munkaelemeket, és gyakran az alkalmazások lassan válaszolnak. A megadott példa ASP.NET Core webalkalmazással szándékosan okozhat éhezést a ThreadPoolban, és megtudhatja, hogyan diagnosztizálhatja.
Az oktatóanyagban a következőket végezheti el:
- Olyan alkalmazás vizsgálata, amely lassan válaszol a kérelmekre
- Használja a dotnet-counters eszközt a ThreadPool éhezés valószínű előfordulásának azonosításához
- A dotnet-stack eszköz használatával állapítsa meg, hogy a ThreadPool-szálak milyen munka miatt lesznek elfoglaltak
Előfeltételek
Az oktatóanyag a következőket használja:
- .NET Core 6.0 SDK a mintaalkalmazás létrehozásához és futtatásához
- Minta webalkalmazás a ThreadPool éhezési viselkedésének bemutatásához
- Bombardier a minta webalkalmazás terhelésének létrehozásához
- dotnet-counters a teljesítményszámlálók megfigyeléséhez
- dotnet-stack a szálveremek vizsgálatához
A mintaalkalmazás futtatása
Töltse le a mintaalkalmazás kódját, és hozza létre a .NET SDK használatával:
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.26Futtassa az alkalmazást:
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
Ha webböngészőt használ, és kéréseket https://localhost:5001/api/diagscenario/taskwaitküld a címre, a válasznak success:taskwait körülbelül 500 ms után kell megjelennie. Ez azt mutatja, hogy a webkiszolgáló a várt módon szolgálja a forgalmat.
Lassú teljesítmény megfigyelése
A bemutató webkiszolgáló több végpontot is tartalmaz, amelyek egy adatbázis-kérést szimulálnak, majd választ ad vissza a felhasználónak. Ezen végpontok mindegyike körülbelül 500 ms késéssel szolgál ki kéréseket egyenként, de a teljesítmény sokkal rosszabb, ha a webkiszolgáló terhelésnek van kitéve. Töltse le a Bombardier terheléstesztelő eszközt, és figyelje meg a késés különbségét, amikor 125 egyidejű kérést küldenek az egyes végpontoknak.
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
Ez a második végpont olyan kódmintát használ, amely még rosszabbul teljesít:
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
Mindkét végpont jelentősen meghaladja az 500 ms átlagos késést, ha a terhelés magas (3,48 s és 15,42 s). Ha ezt a példát a .NET Core egy régebbi verzióján futtatja, valószínűleg mindkét példa ugyanolyan rosszul teljesít. A .NET 6 frissítette a ThreadPool heurisztikus adatait, amelyek csökkentik az első példában használt rossz kódolási minta teljesítményre gyakorolt hatását.
ThreadPool-éhezés észlelése
Ha megfigyelte a fenti viselkedést egy valós szolgáltatásban, akkor tudja, hogy lassan reagál terhelés alatt, de nem tudja az okot. A dotnet-counters egy olyan eszköz, amely élő teljesítményszámlálókat jeleníthet meg. Ezek a számlálók bizonyos problémákra utalhatnak, és gyakran könnyen beszerezhetők. Éles környezetben előfordulhat, hogy a távoli monitorozási eszközök és webes irányítópultok hasonló számlálókat biztosítanak. Telepítse a dotnet-counterst, és kezdje meg a webszolgáltatás figyelését:
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
A fenti számlálók példaként szolgálnak, miközben a webkiszolgáló nem szolgálta ki a kéréseket. Futtassa újra a Bombardier-t a api/diagscenario/tasksleepwait végponttal és 2 percig tartó terheléssel, így rengeteg ideje van megfigyelni, hogy mi történik a teljesítményszámlálókkal.
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s
A ThreadPool éhezése akkor fordul elő, ha nincsenek ingyenes szálak az üzenetsorba helyezett munkaelemek kezelésére, és a futtatókörnyezet a ThreadPool-szálak számának növelésével válaszol. Megfigyelheti, hogy a ThreadPool Thread Count gép processzormagjainak száma 2-3-ra nő, majd a további szálak másodpercenként 1-2-et adnak hozzá, amíg végül stabilizálódnak valahol 125 felett. A ThreadPool-szálak lassú és folyamatos növekedése a cpu-használattal együtt sokkal kevesebb, mint 100%, a fő jelek arra utalnak, hogy a ThreadPool éhezése jelenleg teljesítménybeli szűk keresztmetszet. A szálszám növekedése addig folytatódik, amíg a készlet nem éri el a szálak maximális számát, elegendő szál lett létrehozva az összes bejövő munkaelem kielégítéséhez, vagy a processzor telített. Gyakran, de nem mindig, a ThreadPool éhezése is nagy értékeket és alacsony értékeket ThreadPool Queue Length fog mutatni a ThreadPool Completed Work Item Countszámára, ami azt jelenti, hogy nagy mennyiségű függőben lévő munka van folyamatban, és kevés a befejezett munka. Íme egy példa a számlálókra, miközben a szálak száma még mindig növekszik:
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
Miután a ThreadPool szálak száma stabilizálódott, a készlet már nem éhezik. De ha magas értéken stabilizálódik (a processzormagok számának több mint háromszorosa), az általában azt jelzi, hogy az alkalmazáskód blokkolja néhány ThreadPool-szálat, és a ThreadPool kompenzálja a több szál futtatásával. A magas szálszámon történő folyamatos futtatás nem feltétlenül befolyásolja a kérések késését, de ha a terhelés az idő múlásával jelentősen változik, vagy az alkalmazást rendszeres időközönként újraindítják, akkor minden alkalommal, amikor a ThreadPool valószínűleg éhezés időszakába kerül, ahol lassan növekszik a szálak száma, és gyenge kéréskésést eredményez. Minden szál memóriát is használ, így a szükséges szálak számának csökkentése további előnyökkel jár.
A .NET 6-tól kezdődően a ThreadPool heurisztikus funkciói úgy lettek módosítva, hogy a ThreadPool-szálak száma sokkal gyorsabban felskálázható legyen bizonyos blokkolt feladat API-kra reagálva. A ThreadPool éhezése továbbra is előfordulhat ezekkel az API-kkal, de az időtartam sokkal rövidebb, mint a régebbi .NET-verziók esetében, mert a futtatókörnyezet gyorsabban válaszol. Futtassa újra a Bombardier parancsot a api/diagscenario/taskwait végponttal:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
A .NET 6-on megfigyelheti, hogy a készlet gyorsabban növeli a szálak számát, mint korábban, majd nagy számú szálon stabilizálódik. A ThreadPool éhezése a szálszám emelkedése közben következik be.
A ThreadPool éhezés feloldása
A ThreadPool-beli éhezés kiküszöböléséhez a ThreadPool-szálaknak feloldva kell maradniuk, hogy elérhetők legyenek a bejövő munkaelemek kezeléséhez. Kétféleképpen állapítható meg, hogy az egyes szálak mit csináltak, vagy a dotnet-stack eszközzel, vagy a Visual Studióban megtekinthető dotnet-dump memóriakép rögzítésével. A dotnet-stack gyorsabb lehet, mert azonnal megjeleníti a szálvermeket a konzolon, de a Visual Studio memóriakép-hibakeresése jobb vizualizációkat kínál, amelyek leképezik a kereteket a forrásra, a Just My Code képes kiszűrni a futtatókörnyezeti megvalósítási kereteket, a Párhuzamos veremek funkció pedig nagy számú hasonló vermet tartalmazó szál csoportosításában segíthet. Ez az oktatóanyag a dotnet-stack lehetőséget mutatja be. Tekintse meg a ThreadPool éhezés diagnosztizálását bemutató oktatóvideót , amely egy példát mutat be a szálvermek Visual Studióval történő vizsgálatára.
Futtassa újra a Bombardier parancsot a webkiszolgáló terhelés alá helyezéséhez:
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/taskwait -d 120s
Ezután futtassa a dotnet-stack parancsot a szálverem nyomkövetéseinek megtekintéséhez:
dotnet-stack report -n DiagnosticScenarios
Hosszú kimenetnek kell megjelennie, amely nagy számú vermet tartalmaz, amelyek közül sok a következőképpen néz ki:
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()
A verem alján lévő keretek azt jelzik, hogy ezek a szálak ThreadPool-szálak:
System.Private.CoreLib.il!System.Threading.ThreadPoolWorkQueue.Dispatch()
System.Private.CoreLib.il!System.Threading.PortableThreadPool+WorkerThread.WorkerThreadStart()
A felső képkockák pedig azt mutatják, hogy a szál le van tiltva a DiagnosticScenarioController.TaskWait() függvény hívása GetResultCore(bool) során:
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()
Most a mintaalkalmazás Controllers/DiagnosticScenarios.cs fájljában navigálhat a vezérlő kódjához, és láthatja, hogy az aszinkron API-t hív meg a használata awaitnélkül. Ez az aszinkron kódminta , amelyről ismert, hogy blokkolja a szálakat, és ez a ThreadPool éhezésének leggyakoribb oka.
public ActionResult<string> TaskWait()
{
// ...
Customer c = PretendQueryCustomerFromDbAsync("Dana").Result;
return "success:taskwait";
}
Ebben az esetben a kód könnyen módosítható úgy, hogy az async/await helyett a végponton TaskAsyncWait() látható módon jelenjen meg. A várakozás használata lehetővé teszi, hogy az aktuális szál más munkaelemeket is kiszolgáljon, amíg az adatbázis-lekérdezés folyamatban van. Ha az adatbázis-keresés befejeződött, egy ThreadPool-szál folytatja a végrehajtást. Így az egyes kérések során a kód nem tiltja le a szálat:
public async Task<ActionResult<string>> TaskAsyncWait()
{
// ...
Customer c = await PretendQueryCustomerFromDbAsync("Dana");
return "success:taskasyncwait";
}
Ha a Bombadiert futtatja a terhelés végpontra api/diagscenario/taskasyncwait való küldéséhez, az azt mutatja, hogy a ThreadPool-szál száma sokkal alacsonyabb marad, és az átlagos késés 500 ms közelében marad az async/await megközelítés használatakor:
>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
Visszajelzés
Hamarosan elérhető: 2024-ben fokozatosan kivezetjük a GitHub-problémákat a tartalom visszajelzési mechanizmusaként, és lecseréljük egy új visszajelzési rendszerre. További információ: https://aka.ms/ContentUserFeedback.
Visszajelzés küldése és megtekintése a következőhöz: