Skip to content

Commit 4c8621a

Browse files
verdie-gverdie-g
committed
Update .NET counters
1 parent 013e89a commit 4c8621a

File tree

1 file changed

+76
-54
lines changed

1 file changed

+76
-54
lines changed

‎docs/core/diagnostics/debug-threadpool-starvation.md

Lines changed: 76 additions & 54 deletions
Original file line numberDiff line numberDiff line change
@@ -97,32 +97,45 @@ dotnet-counters monitor -n DiagnosticScenarios
9797
Press p to pause, r to resume, q to quit.
9898
Status: Running
9999
100+
Name Current Value
100101
[System.Runtime]
101-
% Time in GC since last GC (%) 0
102-
Allocation Rate (B / 1 sec) 0
103-
CPU Usage (%) 0
104-
Exception Count (Count / 1 sec) 0
105-
GC Committed Bytes (MB) 0
106-
GC Fragmentation (%) 0
107-
GC Heap Size (MB) 34
108-
Gen 0 GC Count (Count / 1 sec) 0
109-
Gen 0 Size (B) 0
110-
Gen 1 GC Count (Count / 1 sec) 0
111-
Gen 1 Size (B) 0
112-
Gen 2 GC Count (Count / 1 sec) 0
113-
Gen 2 Size (B) 0
114-
IL Bytes Jitted (B) 279,021
115-
LOH Size (B) 0
116-
Monitor Lock Contention Count (Count / 1 sec) 0
117-
Number of Active Timers 0
118-
Number of Assemblies Loaded 121
119-
Number of Methods Jitted 3,223
120-
POH (Pinned Object Heap) Size (B) 0
121-
ThreadPool Completed Work Item Count (Count / 1 sec) 0
122-
ThreadPool Queue Length 0
123-
ThreadPool Thread Count 1
124-
Time spent in JIT (ms / 1 sec) 0.387
125-
Working Set (MB) 87
102+
dotnet.assembly.count ({assembly}) 115
103+
dotnet.gc.collections ({collection})
104+
gc.heap.generation
105+
gen0 2
106+
gen1 1
107+
gen2 1
108+
dotnet.gc.heap.total_allocated (By) 64,329,632
109+
dotnet.gc.last_collection.heap.fragmentation.size (By)
110+
gc.heap.generation
111+
gen0 199,920
112+
gen1 29,208
113+
gen2 0
114+
loh 32
115+
poh 0
116+
dotnet.gc.last_collection.heap.size (By)
117+
gc.heap.generation
118+
gen0 208,712
119+
gen1 3,456,000
120+
gen2 5,065,600
121+
loh 98,384
122+
poh 3,147,488
123+
dotnet.gc.last_collection.memory.committed_size (By) 31,096,832
124+
dotnet.gc.pause.time (s) 0.024
125+
dotnet.jit.compilation.time (s) 1.285
126+
dotnet.jit.compiled_il.size (By) 565,249
127+
dotnet.jit.compiled_methods ({method}) 5,831
128+
dotnet.monitor.lock_contentions ({contention}) 148
129+
dotnet.process.cpu.count ({cpu}) 16
130+
dotnet.process.cpu.time (s)
131+
cpu.mode
132+
system 2.156
133+
user 2.734
134+
dotnet.process.memory.working_set (By) 1.3217e+08
135+
dotnet.thread_pool.queue.length ({work_item}) 0
136+
dotnet.thread_pool.thread.count ({thread}) 0
137+
dotnet.thread_pool.work_item.count ({work_item}) 32,267
138+
dotnet.timer.count ({timer}) 0
126139
```
127140

128141
The counters above are an example while the web server wasn't serving any requests. Run Bombardier again with the `api/diagscenario/tasksleepwait` endpoint and sustained load for 2 minutes so there's plenty of time to observe what happens to the performance counters.
@@ -131,38 +144,47 @@ The counters above are an example while the web server wasn't serving any reques
131144
bombardier-windows-amd64.exe https://localhost:5001/api/diagscenario/tasksleepwait -d 120s
132145
```
133146

134-
ThreadPool starvation occurs when there are no free threads to handle the queued work items and the runtime responds by increasing the number of ThreadPool threads. You should observe the `ThreadPool Thread Count` rapidly increase to 2-3x the number of processor cores on your machine and then further threads are added 1-2 per second until eventually stabilizing somewhere above 125. The slow and steady increase of ThreadPool threads combined with CPU Usage much less than 100% are the key signals that ThreadPool starvation is currently a performance bottleneck. The thread count increase will continue until either the pool hits the maximum number of threads, enough threads have been created to satisfy all the incoming work items, or the CPU has been saturated. Often, but not always, ThreadPool starvation will also show large values for `ThreadPool Queue Length` and low values for `ThreadPool Completed Work Item Count`, meaning that there's a large amount of pending work and little work being completed. Here's an example of the counters while the thread count is still rising:
147+
ThreadPool starvation occurs when there are no free threads to handle the queued work items and the runtime responds by increasing the number of ThreadPool threads. You should observe the `dotnet.thread_pool.thread.count` rapidly increase to 2-3x the number of processor cores on your machine and then further threads are added 1-2 per second until eventually stabilizing somewhere above 125. The slow and steady increase of ThreadPool threads combined with CPU Usage much less than 100% are the key signals that ThreadPool starvation is currently a performance bottleneck. The thread count increase will continue until either the pool hits the maximum number of threads, enough threads have been created to satisfy all the incoming work items, or the CPU has been saturated. Often, but not always, ThreadPool starvation will also show large values for `dotnet.thread_pool.queue.length` and low values for `dotnet.thread_pool.work_item.count`, meaning that there's a large amount of pending work and little work being completed. Here's an example of the counters while the thread count is still rising:
135148

136149
```dotnetcli
137-
Press p to pause, r to resume, q to quit.
138-
Status: Running
139-
140150
[System.Runtime]
141-
% Time in GC since last GC (%) 0
142-
Allocation Rate (B / 1 sec) 24,480
143-
CPU Usage (%) 0
144-
Exception Count (Count / 1 sec) 0
145-
GC Committed Bytes (MB) 56
146-
GC Fragmentation (%) 40.603
147-
GC Heap Size (MB) 89
148-
Gen 0 GC Count (Count / 1 sec) 0
149-
Gen 0 Size (B) 6,306,160
150-
Gen 1 GC Count (Count / 1 sec) 0
151-
Gen 1 Size (B) 8,061,400
152-
Gen 2 GC Count (Count / 1 sec) 0
153-
Gen 2 Size (B) 192
154-
IL Bytes Jitted (B) 279,263
155-
LOH Size (B) 98,576
156-
Monitor Lock Contention Count (Count / 1 sec) 0
157-
Number of Active Timers 124
158-
Number of Assemblies Loaded 121
159-
Number of Methods Jitted 3,227
160-
POH (Pinned Object Heap) Size (B) 1,197,336
161-
ThreadPool Completed Work Item Count (Count / 1 sec) 2
162-
ThreadPool Queue Length 29
163-
ThreadPool Thread Count 96
164-
Time spent in JIT (ms / 1 sec) 0
165-
Working Set (MB) 152
151+
dotnet.assembly.count ({assembly}) 115
152+
dotnet.gc.collections ({collection})
153+
gc.heap.generation
154+
gen0 5
155+
gen1 1
156+
gen2 1
157+
dotnet.gc.heap.total_allocated (By) 1.6947e+08
158+
dotnet.gc.last_collection.heap.fragmentation.size (By)
159+
gc.heap.generation
160+
gen0 0
161+
gen1 348,248
162+
gen2 0
163+
loh 32
164+
poh 0
165+
dotnet.gc.last_collection.heap.size (By)
166+
gc.heap.generation
167+
gen0 0
168+
gen1 18,010,920
169+
gen2 5,065,600
170+
loh 98,384
171+
poh 3,407,048
172+
dotnet.gc.last_collection.memory.committed_size (By) 66,842,624
173+
dotnet.gc.pause.time (s) 0.05
174+
dotnet.jit.compilation.time (s) 1.317
175+
dotnet.jit.compiled_il.size (By) 574,886
176+
dotnet.jit.compiled_methods ({method}) 6,008
177+
dotnet.monitor.lock_contentions ({contention}) 194
178+
dotnet.process.cpu.count ({cpu}) 16
179+
dotnet.process.cpu.time (s)
180+
cpu.mode
181+
system 4.953
182+
user 6.266
183+
dotnet.process.memory.working_set (By) 1.3217e+08
184+
dotnet.thread_pool.queue.length ({work_item}) 0
185+
dotnet.thread_pool.thread.count ({thread}) 133
186+
dotnet.thread_pool.work_item.count ({work_item}) 71,188
187+
dotnet.timer.count ({timer}) 124
166188
```
167189

168190
Once the count of ThreadPool threads stabilizes, the pool is no longer starving. But if it stabilizes at a high value (more than about three times the number of processor cores), that usually indicates the application code is blocking some ThreadPool threads and the ThreadPool is compensating by running with more threads. Running steady at high thread counts won't necessarily have large impacts on request latency, but if load varies dramatically over time or the app will be periodically restarted, then each time the ThreadPool is likely to enter a period of starvation where it's slowly increasing threads and delivering poor request latency. Each thread also consumes memory, so reducing the total number of threads needed provides another benefit.

0 commit comments

Comments
 (0)