Another fix for slow requets

Author: rhamlett_microsoft

src/PerfProblemSimulator/Controllers/SlowRequestController.cs

@@ -173,29 +173,33 @@ public IActionResult GetScenarios()
     /// HTTP endpoint that simulates a slow blocking request.
     /// </summary>
     /// <param name="durationSeconds">How long the request should take (default: 25 seconds).</param>
+    /// <param name="scenario">The scenario name for logging (optional).</param>
     /// <returns>Result after the blocking delay completes.</returns>
     /// <remarks>
     /// <para>
     /// <strong>⚠️ This endpoint intentionally blocks!</strong>
     /// </para>
     /// <para>
     /// This endpoint is designed to be called during slow request simulation so that
-    /// slow requests show up in the Request Latency Monitor chart. It uses sync-over-async
-    /// to block the thread pool thread.
+    /// slow requests show up in the Request Latency Monitor chart. It uses Thread.Sleep
+    /// to block the ASP.NET thread pool thread.
     /// </para>
     /// </remarks>
     /// <response code="200">Request completed after blocking</response>
     [HttpGet("execute-slow")]
     [ProducesResponseType(typeof(SlowRequestResult), StatusCodes.Status200OK)]
-    public IActionResult ExecuteSlowRequest([FromQuery] int durationSeconds = 25)
+    public IActionResult ExecuteSlowRequest(
+        [FromQuery] int durationSeconds = 25,
+        [FromQuery] string? scenario = null)
     {
         var startTime = DateTimeOffset.UtcNow;
 
-        _logger.LogWarning("🐌 HTTP slow request started: {Duration}s", durationSeconds);
+        _logger.LogWarning("🐌 HTTP slow request started: {Duration}s, Scenario: {Scenario}", 
+            durationSeconds, scenario ?? "Direct");
 
-        // BAD: Intentionally blocking with sync-over-async
-        // This makes the request visible in the latency chart
-        Task.Delay(durationSeconds * 1000).Wait();
+        // BAD: Intentionally blocking with Thread.Sleep
+        // This makes the request visible in the latency chart AND shows up clearly in CLR Profiler
+        Thread.Sleep(durationSeconds * 1000);
 
         var elapsed = DateTimeOffset.UtcNow - startTime;
 
@@ -205,6 +209,7 @@ public IActionResult ExecuteSlowRequest([FromQuery] int durationSeconds = 25)
         {
             Message = $"Slow request completed after {elapsed.TotalSeconds:F1} seconds",
             DurationSeconds = elapsed.TotalSeconds,
+            Scenario = scenario ?? "Direct",
             StartedAt = startTime,
             CompletedAt = DateTimeOffset.UtcNow
         });
@@ -218,6 +223,7 @@ public class SlowRequestResult
 {
     public string Message { get; set; } = "";
     public double DurationSeconds { get; set; }
+    public string Scenario { get; set; } = "";
     public DateTimeOffset StartedAt { get; set; }
     public DateTimeOffset CompletedAt { get; set; }
 }

src/PerfProblemSimulator/Hubs/IMetricsClient.cs

@@ -55,4 +55,42 @@ public interface IMetricsClient
     /// </para>
     /// </remarks>
     Task ReceiveLatency(LatencyMeasurement measurement);
+
+    /// <summary>
+    /// Receives slow request latency data from the server.
+    /// </summary>
+    /// <param name="data">The slow request latency data.</param>
+    /// <remarks>
+    /// <para>
+    /// This is used to track actual slow request durations (typically 20-25 seconds)
+    /// separately from the lightweight probe latency.
+    /// </para>
+    /// </remarks>
+    Task ReceiveSlowRequestLatency(SlowRequestLatencyData data);
+}
+
+/// <summary>
+/// Data about a slow request's latency.
+/// </summary>
+public class SlowRequestLatencyData
+{
+    /// <summary>
+    /// The request number in the simulation.
+    /// </summary>
+    public int RequestNumber { get; set; }
+    
+    /// <summary>
+    /// The scenario used for this request.
+    /// </summary>
+    public string Scenario { get; set; } = "";
+    
+    /// <summary>
+    /// The measured latency in milliseconds.
+    /// </summary>
+    public double LatencyMs { get; set; }
+    
+    /// <summary>
+    /// When this measurement was taken.
+    /// </summary>
+    public DateTimeOffset Timestamp { get; set; }
 }

src/PerfProblemSimulator/Program.cs

@@ -117,6 +117,12 @@
 // Educational Note: Singleton lifetime is required because the service maintains
 // state about running simulations and spawns background threads. This service
 // is designed to be used with CLR Profiler to demonstrate sync-over-async patterns.
+builder.Services.AddHttpClient("SlowRequest")
+    .ConfigurePrimaryHttpMessageHandler(() => new SocketsHttpHandler
+    {
+        // Long timeout for slow requests
+        ConnectTimeout = TimeSpan.FromSeconds(60)
+    });
 builder.Services.AddSingleton<ISlowRequestService, SlowRequestService>();
 
 // MetricsCollector - Singleton service for collecting system metrics

src/PerfProblemSimulator/Services/SlowRequestService.cs

@@ -1,4 +1,9 @@
+using Microsoft.AspNetCore.Hosting.Server;
+using Microsoft.AspNetCore.Hosting.Server.Features;
+using Microsoft.AspNetCore.SignalR;
+using PerfProblemSimulator.Hubs;
 using PerfProblemSimulator.Models;
+using System.Diagnostics;
 using System.Runtime.CompilerServices;
 
 namespace PerfProblemSimulator.Services;
@@ -37,6 +42,9 @@ public class SlowRequestService : ISlowRequestService, IDisposable
 {
     private readonly ISimulationTracker _simulationTracker;
     private readonly ILogger<SlowRequestService> _logger;
+    private readonly IHttpClientFactory _httpClientFactory;
+    private readonly IHubContext<MetricsHub, IMetricsClient> _hubContext;
+    private readonly IServer _server;
     private readonly Random _random = new();
 
     private CancellationTokenSource? _cts;
@@ -52,15 +60,22 @@ public class SlowRequestService : ISlowRequestService, IDisposable
     private Guid _simulationId;
     private readonly Dictionary<string, int> _scenarioCounts = new();
     private readonly object _lock = new();
+    private string? _baseUrl;
 
     public bool IsRunning => _isRunning;
 
     public SlowRequestService(
         ISimulationTracker simulationTracker,
-        ILogger<SlowRequestService> logger)
+        ILogger<SlowRequestService> logger,
+        IHttpClientFactory httpClientFactory,
+        IHubContext<MetricsHub, IMetricsClient> hubContext,
+        IServer server)
     {
         _simulationTracker = simulationTracker ?? throw new ArgumentNullException(nameof(simulationTracker));
         _logger = logger ?? throw new ArgumentNullException(nameof(logger));
+        _httpClientFactory = httpClientFactory ?? throw new ArgumentNullException(nameof(httpClientFactory));
+        _hubContext = hubContext ?? throw new ArgumentNullException(nameof(hubContext));
+        _server = server ?? throw new ArgumentNullException(nameof(server));
     }
 
     public SimulationResult Start(SlowRequestRequest request)
@@ -81,12 +96,15 @@ public SimulationResult Start(SlowRequestRequest request)
         _requestsSent = 0;
         _requestsCompleted = 0;
         _requestsInProgress = 0;
-        _intervalSeconds = Math.Max(5, request.IntervalSeconds);
-        _requestDurationSeconds = Math.Max(10, request.RequestDurationSeconds);
+        _intervalSeconds = Math.Max(1, request.IntervalSeconds);  // Allow 1 second minimum
+        _requestDurationSeconds = Math.Max(5, request.RequestDurationSeconds);  // Allow 5 second minimum
         _maxRequests = request.MaxRequests;
         _startedAt = DateTimeOffset.UtcNow;
         _scenarioCounts.Clear();
         _isRunning = true;
+        
+        // Get the base URL for HTTP calls
+        _baseUrl = GetBaseUrl();
 
         var parameters = new Dictionary<string, object>
         {
@@ -108,8 +126,8 @@ public SimulationResult Start(SlowRequestRequest request)
         _logger.LogWarning(
             "🐌 Slow request simulation started: {SimulationId}. " +
             "Duration={Duration}s, Interval={Interval}s. " +
-            "Requests will use random sync-over-async scenarios.",
-            _simulationId, _requestDurationSeconds, _intervalSeconds);
+            "Making HTTP calls to {BaseUrl}/api/slowrequest/execute-slow",
+            _simulationId, _requestDurationSeconds, _intervalSeconds, _baseUrl);
 
         return new SimulationResult
         {
@@ -190,7 +208,7 @@ private void SpawnRequestsLoop(int maxRequests, CancellationToken ct)
             Interlocked.Increment(ref _requestsSent);
             Interlocked.Increment(ref _requestsInProgress);
 
-            // Randomly select a scenario
+            // Randomly select a scenario for logging purposes
             var scenario = (SlowRequestScenario)_random.Next(1, 4); // 1, 2, or 3 (skip Random=0)
 
             lock (_lock)
@@ -201,11 +219,12 @@ private void SpawnRequestsLoop(int maxRequests, CancellationToken ct)
             }
 
             _logger.LogInformation(
-                "🐌 Spawning slow request #{Number} using scenario: {Scenario}",
-                requestNumber, scenario);
+                "🐌 Spawning slow HTTP request #{Number} to {BaseUrl}/api/slowrequest/execute-slow?durationSeconds={Duration}",
+                requestNumber, _baseUrl, _requestDurationSeconds);
 
-            // Spawn the slow request on a new thread (simulating incoming HTTP request)
-            var requestThread = new Thread(() => ExecuteSlowRequest(scenario, requestNumber, _requestDurationSeconds, ct))
+            // Spawn the slow request on a new thread - this will make an HTTP call
+            var reqNum = requestNumber;
+            var requestThread = new Thread(() => ExecuteSlowHttpRequest(scenario, reqNum, _requestDurationSeconds, ct))
             {
                 Name = $"SlowRequest-{requestNumber}-{scenario}",
                 IsBackground = true
@@ -226,36 +245,47 @@ private void SpawnRequestsLoop(int maxRequests, CancellationToken ct)
         _logger.LogInformation("Slow request spawner loop ended");
     }
 
-    private void ExecuteSlowRequest(SlowRequestScenario scenario, int requestNumber, int durationSeconds, CancellationToken ct)
+    /// <summary>
+    /// Makes an HTTP call to the slow request endpoint - this goes through the ASP.NET pipeline
+    /// and will show up in the Request Latency Monitor.
+    /// </summary>
+    private void ExecuteSlowHttpRequest(SlowRequestScenario scenario, int requestNumber, int durationSeconds, CancellationToken ct)
     {
+        var sw = Stopwatch.StartNew();
         try
         {
-            // Execute the blocking scenario - uses Thread.Sleep so it shows up in CLR Profiler
-            switch (scenario)
+            if (string.IsNullOrEmpty(_baseUrl))
             {
-                case SlowRequestScenario.SimpleSyncOverAsync:
-                    ExecuteSimpleSyncOverAsyncRequest(durationSeconds, ct);
-                    break;
-
-                case SlowRequestScenario.NestedSyncOverAsync:
-                    ExecuteNestedSyncOverAsyncRequest(durationSeconds, ct);
-                    break;
-
-                case SlowRequestScenario.DatabasePattern:
-                    ExecuteDatabasePatternRequest(durationSeconds, ct);
-                    break;
+                _logger.LogError("Base URL not configured for slow request HTTP calls");
+                return;
             }
 
-            _logger.LogInformation("🐌 Slow request #{Number} ({Scenario}) completed after {Duration}s", 
-                requestNumber, scenario, durationSeconds);
+            var client = _httpClientFactory.CreateClient("SlowRequest");
+            client.Timeout = TimeSpan.FromSeconds(durationSeconds + 30); // Extra buffer for network overhead
+            
+            var url = $"{_baseUrl}/api/slowrequest/execute-slow?durationSeconds={durationSeconds}&scenario={scenario}";
+            
+            // Make HTTP call - this blocks the thread and goes through ASP.NET pipeline
+            var response = client.GetAsync(url, ct).GetAwaiter().GetResult();
+            
+            sw.Stop();
+            var latencyMs = sw.Elapsed.TotalMilliseconds;
+            
+            _logger.LogInformation(
+                "🐌 Slow HTTP request #{Number} ({Scenario}) completed in {Latency:F0}ms (expected ~{Expected}s)", 
+                requestNumber, scenario, latencyMs, durationSeconds);
+
+            // Broadcast the slow request latency to the dashboard
+            BroadcastSlowRequestLatency(requestNumber, scenario, latencyMs);
         }
         catch (OperationCanceledException)
         {
             _logger.LogDebug("Slow request #{Number} cancelled", requestNumber);
         }
         catch (Exception ex)
         {
-            _logger.LogError(ex, "Slow request #{Number} failed", requestNumber);
+            sw.Stop();
+            _logger.LogError(ex, "Slow HTTP request #{Number} failed after {Elapsed}ms", requestNumber, sw.ElapsedMilliseconds);
         }
         finally
         {
@@ -266,6 +296,53 @@ private void ExecuteSlowRequest(SlowRequestScenario scenario, int requestNumber,
             CheckAndCompleteSimulation();
         }
     }
+    
+    /// <summary>
+    /// Broadcasts slow request latency to connected dashboard clients.
+    /// </summary>
+    private void BroadcastSlowRequestLatency(int requestNumber, SlowRequestScenario scenario, double latencyMs)
+    {
+        try
+        {
+            _hubContext.Clients.All.ReceiveSlowRequestLatency(new SlowRequestLatencyData
+            {
+                RequestNumber = requestNumber,
+                Scenario = scenario.ToString(),
+                LatencyMs = latencyMs,
+                Timestamp = DateTimeOffset.UtcNow
+            }).GetAwaiter().GetResult();
+        }
+        catch (Exception ex)
+        {
+            _logger.LogDebug(ex, "Failed to broadcast slow request latency");
+        }
+    }
+    
+    /// <summary>
+    /// Gets the base URL for making HTTP calls to ourselves.
+    /// </summary>
+    private string? GetBaseUrl()
+    {
+        try
+        {
+            var addresses = _server.Features.Get<IServerAddressesFeature>();
+            if (addresses != null && addresses.Addresses.Count > 0)
+            {
+                var address = addresses.Addresses.First();
+                // Replace wildcard addresses
+                address = address.Replace("[::]", "localhost").Replace("0.0.0.0", "localhost");
+                _logger.LogDebug("Detected server address for slow requests: {Address}", address);
+                return address;
+            }
+        }
+        catch (Exception ex)
+        {
+            _logger.LogWarning(ex, "Could not detect server address");
+        }
+        
+        // Fallback for Azure/production environments - use relative URL
+        return "http://localhost:5021";
+    }
 
     /// <summary>
     /// Checks if all requests have completed and marks the simulation as done.

src/PerfProblemSimulator/wwwroot/js/dashboard.js

@@ -36,6 +36,11 @@ const state = {
         isTimeout: [],
         isError: []
     },
+    slowRequestHistory: {
+        timestamps: [],
+        values: [],
+        scenarios: []
+    },
     latencyStats: {
         timeoutCount: 0
     },
@@ -114,6 +119,8 @@ async function initializeSignalR() {
     state.connection.on('simulationCompleted', handleSimulationCompleted);
     state.connection.on('ReceiveLatency', handleLatencyUpdate);
     state.connection.on('receiveLatency', handleLatencyUpdate);
+    state.connection.on('ReceiveSlowRequestLatency', handleSlowRequestLatency);
+    state.connection.on('receiveSlowRequestLatency', handleSlowRequestLatency);
 
     // Start connection
     try {
@@ -492,6 +499,40 @@ function handleLatencyUpdate(measurement) {
     updateLatencyChart();
 }
 
+/**
+ * Handle incoming slow request latency from server.
+ * This shows the actual duration of slow requests (20+ seconds).
+ */
+function handleSlowRequestLatency(data) {
+    console.log('🐌 Slow request latency:', data);
+    
+    const timestamp = new Date(data.timestamp);
+    const latencyMs = data.latencyMs;
+    const scenario = data.scenario;
+    
+    // Add to slow request history
+    const history = state.slowRequestHistory;
+    history.timestamps.push(timestamp);
+    history.values.push(latencyMs);
+    history.scenarios.push(scenario);
+    
+    // Trim to max data points
+    while (history.timestamps.length > 100) {
+        history.timestamps.shift();
+        history.values.shift();
+        history.scenarios.shift();
+    }
+    
+    // Add as a special latency point on the chart (it will show as a large spike)
+    addLatencyToHistory(timestamp, latencyMs, false, false);
+    updateLatencyDisplay(latencyMs, false, false);
+    updateLatencyChart();
+    
+    // Log the slow request completion
+    const durationSec = (latencyMs / 1000).toFixed(1);
+    logEvent('warning', `🐌 Slow request #${data.requestNumber} completed: ${durationSec}s (${scenario})`);
+}
+
 /**
  * Add latency measurement to history.
  */