Skip to content

Commit 2f086e0

Browse files
author
rhamlett_microsoft
committed
Summary of Changes:
README.md: CPU Stress: Updated the description to clarify it now uses dedicated threads for spin loops (not Parallel.For), which ensures the dashboard remains responsive even under 100% load. API: Updated the CPU trigger example to show the new targetPercentage parameter. azure-monitoring-guide.md & azure-monitoring-guide.html: CPU Code Pattern: Updated to show the new Thread() implementation and explained the reasoning (avoiding dashboard starvation). Slow Request Code Pattern: Updated Scenario 1 to explicitly show Task.Delay().Wait(), reflecting the actual "Sync Over Async" anti-pattern in the code. New Section - Queue Time: Added a generic explanation of the "gap" mechanism you discovered. It explains that a request taking 47s total but only 25s in logs means it spent 22s in the queue due to Thread Pool starvation. Architecture: Added a note about the ETW Heartbeat mechanism (logging every 500ms) which prevents long idle requests from being lost in traces. documentation.html: Warnings: Updated to mention dedicated threads for CPU stress. Tables: Updated the Slow Request scenario table to accurately describe Task.Delay().Wait(). Notes: Added a note about Queue Time vs Execution Time to the Recommended Settings section.
1 parent 00fddb5 commit 2f086e0

4 files changed

Lines changed: 75 additions & 50 deletions

File tree

README.md

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -15,7 +15,7 @@ This application is designed to help developers and DevOps engineers:
1515

1616
**This application intentionally creates performance problems!**
1717

18-
- 🔥 **CPU stress** - Creates parallel spin loops that consume all CPU cores
18+
- 🔥 **CPU stress** - Creates dedicated threads running spin loops to consume all CPU cores
1919
- 📊 **Memory pressure** - Allocates and pins memory blocks to increase working set
2020
- 🧵 **Thread pool starvation** - Uses sync-over-async anti-patterns to block thread pool threads
2121
-**Slow requests** - Generates long-running requests with sync-over-async patterns for CLR Profiler analysis
@@ -99,7 +99,8 @@ The CPU and Memory metric tiles use dynamic color coding based on utilization pe
9999
**Request body:**
100100
```json
101101
{
102-
"durationSeconds": 30
102+
"durationSeconds": 30,
103+
"targetPercentage": 100
103104
}
104105
```
105106

docs/azure-monitoring-guide.md

Lines changed: 35 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -60,15 +60,22 @@ In the profiler trace, you'll see:
6060
### Code Pattern (What's Wrong)
6161

6262
```csharp
63-
// This is the intentional "bad" code in CpuStressService:
64-
Parallel.For(0, Environment.ProcessorCount, _ =>
63+
// The service uses dedicated threads to avoid starving the Thread Pool,
64+
// ensuring the dashboard remains responsive even under 100% load.
65+
var threads = new Thread[Environment.ProcessorCount];
66+
67+
for (int i = 0; i < threads.Length; i++)
6568
{
66-
while (!cancellationToken.IsCancellationRequested)
69+
threads[i] = new Thread(() =>
6770
{
68-
// Intentionally consuming CPU with no useful work
69-
Thread.SpinWait(10000);
70-
}
71-
});
71+
// Tight spin loop to consume 100% of a core
72+
while (Stopwatch.GetTimestamp() < endTime)
73+
{
74+
// Spin
75+
}
76+
});
77+
threads[i].Start();
78+
}
7279
```
7380

7481
---
@@ -259,28 +266,37 @@ Simulated database and HTTP blocking calls:
259266
### Code Pattern (What the Simulation Does)
260267

261268
```csharp
262-
// SCENARIO 1: Direct blocking - most obvious in traces
269+
// SCENARIO 1: Sync-Over-Async (Simple)
263270
public void FetchDataSync_BLOCKING_HERE(int delayMs)
264271
{
265-
// Intentional blocking - will show in profiler as Thread.Sleep
266-
Thread.Sleep(delayMs);
272+
// FATAL FLAW: Calling .Wait() on a Task blocks the thread!
273+
// This is the classic "Sync Over Async" anti-pattern.
274+
Task.Delay(delayMs * 1000).Wait();
267275
}
268276

269277
// SCENARIO 2: Nested blocking inside sync methods
270278
public void ValidateOrderSync_BLOCKS_INTERNALLY(int delayMs)
271279
{
272-
// Each method internally blocks using Thread.Sleep
273-
Thread.Sleep(delayMs);
274-
}
275-
276-
// SCENARIO 3: Simulated database/HTTP pattern
277-
public void GetCustomerFromDatabaseSync_SYNC_BLOCK(int delayMs)
278-
{
279-
// Simulates a blocking database call
280-
Thread.Sleep(delayMs);
280+
// Each method internally blocks using Task.Delay().Wait()
281+
CheckInventorySync_BLOCKS_INTERNALLY(delayMs);
281282
}
282283
```
283284

285+
### Analyzing the Trace: The "Gap" (Queue Time vs Execution Time)
286+
287+
When diagnosing slow requests, you may see a large gap where "No events emitted" appears before the request actually starts.
288+
289+
1. **Queue Time**: If the Thread Pool is starved (by other slow requests), a new request will sit in the queue waiting for a thread. PROFILER will show a gap here.
290+
2. **Execution Time**: Once a thread is assigned, the method runs.
291+
292+
**Example from a Trace:**
293+
* Total Time seen by user: **47 seconds**
294+
* Request Duration in log: **25 seconds**
295+
* **Conclusion**: The request sat in the queue for **22 seconds** before it could even start!
296+
297+
### ETW Flushing (Heartbeats)
298+
The simulator runs a background thread that logs "Generating trace noise..." every 500ms. This ensures that ETW buffers are flushed to the `.diagsession` file, preventing data loss during long idle periods.
299+
284300
### Real-World Equivalents
285301

286302
The Thread.Sleep patterns simulate what you'd see with:

src/PerfProblemSimulator/wwwroot/azure-monitoring-guide.html

Lines changed: 33 additions & 27 deletions
Original file line numberDiff line numberDiff line change
@@ -358,22 +358,29 @@ <h4>3. CPU Profiling (Advanced)</h4>
358358
<h3>What to Look For</h3>
359359
<div class="code-block">
360360
<span class="comment">In the profiler trace, you'll see:</span>
361-
- Parallel.For loops
362-
- SpinWait operations
363-
- High self-time in CpuStressService.RunStressLoop
361+
- Dedicated threads running a while loop
362+
- High self-time in CpuStressService
363+
- Thread names like CpuStress-*
364364
</div>
365365

366366
<h3>Code Pattern (What's Wrong)</h3>
367367
<div class="code-block">
368-
<span class="comment">// This is the intentional "bad" code in CpuStressService:</span>
369-
Parallel.For(<span class="keyword">0</span>, Environment.ProcessorCount, _ =>
368+
<span class="comment">// The service uses dedicated threads to avoid starving the Thread Pool,</span>
369+
<span class="comment">// ensuring the dashboard remains responsive even under 100% load.</span>
370+
<span class="keyword">var</span> threads = <span class="keyword">new</span> Thread[Environment.ProcessorCount];
371+
372+
<span class="keyword">for</span> (<span class="keyword">int</span> i = <span class="keyword">0</span>; i &lt; threads.Length; i++)
370373
{
371-
<span class="keyword">while</span> (!cancellationToken.IsCancellationRequested)
374+
threads[i] = <span class="keyword">new</span> Thread(() =>
372375
{
373-
<span class="comment">// Intentionally consuming CPU with no useful work</span>
374-
Thread.SpinWait(<span class="keyword">10000</span>);
375-
}
376-
});
376+
<span class="comment">// Tight spin loop to consume 100% of a core</span>
377+
<span class="keyword">while</span> (Stopwatch.GetTimestamp() &lt; endTime)
378+
{
379+
<span class="comment">// Spin</span>
380+
}
381+
});
382+
threads[i].Start();
383+
}
377384
</div>
378385
</section>
379386

@@ -589,36 +596,35 @@ <h3>Recommended Settings for CLR Profiler (60s trace)</h3>
589596

590597
<h3>Code Pattern (What's Wrong)</h3>
591598
<div class="code-block">
592-
<span class="comment">// SCENARIO 1: Direct blocking - most obvious in traces</span>
599+
<span class="comment">// SCENARIO 1: Sync-Over-Async (Simple)</span>
593600
<span class="keyword">public void</span> ProcessRequest()
594601
{
595-
<span class="comment">// BAD: Blocking on async - thread is blocked for 25 seconds!</span>
596-
FetchDataAsync().Wait();
602+
<span class="comment">// FATAL FLAW: Calling .Wait() on a Task blocks the thread!</span>
603+
<span class="comment">// This is the classic "Sync Over Async" anti-pattern.</span>
604+
Task.Delay(<span class="keyword">25000</span>).Wait();
597605
}
598606

599607
<span class="comment">// SCENARIO 2: Hidden blocking inside sync methods</span>
600608
<span class="keyword">public void</span> ValidateOrderSync_BLOCKS_INTERNALLY()
601609
{
602-
<span class="comment">// BAD: Looks like a sync method but blocks internally</span>
603-
ValidateOrderAsync().Wait();
604-
}
605-
606-
<span class="comment">// SCENARIO 3: Common legacy migration pattern</span>
607-
<span class="keyword">public</span> Customer GetCustomer(<span class="keyword">int</span> id)
608-
{
609-
<span class="comment">// BAD: GetAwaiter().GetResult() still blocks!</span>
610-
<span class="keyword">return</span> GetCustomerAsync(id).GetAwaiter().GetResult();
610+
<span class="comment">// Each method internally blocks using Task.Delay().Wait()</span>
611+
ValidateOrderAsync_BLOCKS().Wait();
611612
}
612613
</div>
613614

614615
<div class="info-box">
615-
<h4>💡 Key Insight</h4>
616-
<p>The slow request simulator makes sync-over-async <strong>visible in profiler call stacks</strong> because:</p>
616+
<h4>💡 Key Insight: Queue Time vs Execution Time</h4>
617+
<p>If you see a large gap where "No events emitted" appears before the request starts:</p>
617618
<ul>
618-
<li>Requests are long enough (25s) to be captured during any reasonable trace period</li>
619-
<li>Method names explicitly indicate where blocking occurs</li>
620-
<li>Multiple scenarios show different blocking patterns commonly found in production code</li>
619+
<li><strong>Queue Time:</strong> The Thread Pool is starved, so your request sat in the queue waiting for a thread (e.g., 20+ seconds).</li>
620+
<li><strong>Execution Time:</strong> Once a thread was assigned, the method finally ran.</li>
621621
</ul>
622+
<p><strong>Example:</strong> User waits 47s, but log shows only 25s duration. The missing 22s was spent in the queue!</p>
623+
</div>
624+
625+
<div class="info-box">
626+
<h4>💡 ETW Heartbeats</h4>
627+
<p>The simulator logs "Generating trace noise..." every 500ms to flush ETW buffers, ensuring long requests are not lost in traces.</p>
622628
</div>
623629
</section>
624630

src/PerfProblemSimulator/wwwroot/documentation.html

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -339,7 +339,7 @@ <h3>Purpose</h3>
339339
<div class="warning-box">
340340
<h4>⚠️ Warning - This application intentionally creates performance problems!</h4>
341341
<ul>
342-
<li>🔥 <strong>CPU stress</strong> - Creates parallel spin loops that consume all CPU cores</li>
342+
<li>🔥 <strong>CPU stress</strong> - Creates dedicated threads running spin loops to consume all CPU cores</li>
343343
<li>📊 <strong>Memory pressure</strong> - Allocates and pins memory blocks to increase working set</li>
344344
<li>🧵 <strong>Thread pool starvation</strong> - Uses sync-over-async anti-patterns to block thread pool threads</li>
345345
<li><strong>Slow requests</strong> - Generates long-running requests with sync-over-async patterns for CLR Profiler analysis</li>
@@ -499,7 +499,7 @@ <h3>Three Sync-Over-Async Scenarios</h3>
499499
<tr>
500500
<td><strong>Simple</strong></td>
501501
<td><code>_BLOCKING_HERE</code></td>
502-
<td>Direct <code>.Wait()</code> blocking</td>
502+
<td><code>Task.Delay().Wait()</code> causing blocking</td>
503503
</tr>
504504
<tr>
505505
<td><strong>Nested</strong></td>
@@ -522,6 +522,8 @@ <h3>Recommended Settings</h3>
522522
<li><strong>Max Requests:</strong> 6 (doesn't overwhelm)</li>
523523
</ul>
524524

525+
<p><strong>Note on Queue Time:</strong> If the thread pool is starved, you may see a large gap in the trace before the request starts. This is "Queue Time" (waiting for a thread) vs "Execution Time" (running the code).</p>
526+
525527
<h3>Using with CLR Profiler</h3>
526528
<ol>
527529
<li>Start a CPU Profiler trace (60-120 seconds)</li>

0 commit comments

Comments
 (0)