Collect WAN Perf Logs and Fix Issues Found with them (#2270)

.github/workflows/wan-perf.yml

@@ -89,11 +89,17 @@ jobs:
         path: artifacts/bin
     - name: Run WAN Perf
       shell: pwsh
-      run: scripts/emulated-performance.ps1 -Protocol quic -NumIterations ${{ env.iterations }} -DurationMs ${{ env.duration }} -Pacing ${{ env.pacing }} -BottleneckMbps ${{ matrix.rate }} -RttMs ${{ matrix.rtt }} -BottleneckQueueRatio ${{ matrix.queueRatio }} -RandomLossDenominator ${{ env.loss }} -RandomReorderDenominator ${{ env.reorder }} -ReorderDelayDeltaMs ${{ env.delay }} -BaseRandomSeed ${{ env.seed }}
-    - uses: actions/upload-artifact@v2
+      run: scripts/emulated-performance.ps1 -Debug -Protocol quic -LogProfile Performance.Light -NoDateLogDir -NumIterations ${{ env.iterations }} -DurationMs ${{ env.duration }} -Pacing ${{ env.pacing }} -BottleneckMbps ${{ matrix.rate }} -RttMs ${{ matrix.rtt }} -BottleneckQueueRatio ${{ matrix.queueRatio }} -RandomLossDenominator ${{ env.loss }} -RandomReorderDenominator ${{ env.reorder }} -ReorderDelayDeltaMs ${{ env.delay }} -BaseRandomSeed ${{ env.seed }}
+    - name: Upload Results
+      uses: actions/upload-artifact@v2
       with:
         name: data
         path: artifacts/PerfDataResults/windows/x64_Release_schannel/WAN/*.json
+    - name: Upload Logs
+      uses: actions/upload-artifact@v2
+      with:
+        name: ${{ format('logs.{0}mbps.{1}ms', matrix.rate, matrix.rtt) }}
+        path: artifacts/logs/wanperf/*.etl
   merge-data:
     name: Merge Results
     runs-on: windows-2022

docs/tat/default.tat

@@ -27,5 +27,6 @@
     <filter enabled="y" excluding="y" type="matches_text" case_sensitive="n" regex="n" text="Send Blocked Flags:" />
     <filter enabled="y" excluding="y" type="matches_text" case_sensitive="n" regex="n" text="QUIC_STREAM_EVENT_SEND_COMPLETE" />
     <filter enabled="y" excluding="y" type="matches_text" case_sensitive="n" regex="n" text="QUIC_CONNECTION_EVENT_IDEAL_SEND_BUFFER" />
+    <filter enabled="y" excluding="y" type="matches_text" case_sensitive="n" regex="n" text="Queueing send flush" />
   </filters>
 </TextAnalysisTool.NET>

scripts/emulated-performance.ps1

@@ -46,6 +46,9 @@ be in the current directory.
 .PARAMETER NumIterations
     The number(s) of iterations to run of each test over the emulated network.
 
+.PARAMETER NoDateLogDir
+    Doesn't include the Date/Time in the log directory path.
+
 #>
 
 param (
@@ -105,7 +108,10 @@ param (
     [string]$ForceBranchName = $null,
 
     [Parameter(Mandatory = $false)]
-    [switch]$MergeDataFiles = $false
+    [switch]$MergeDataFiles = $false,
+
+    [Parameter(Mandatory = $false)]
+    [switch]$NoDateLogDir = $false
 )
 
 Set-StrictMode -Version 'Latest'
@@ -380,7 +386,10 @@ if ($MergeDataFiles) {
         }
     }
 
+    # First sort by usage to show bad cases.
     $MergedResults | Sort-Object -Property Usage | Format-Table -AutoSize
+    # Then sort by rate for easy comparison to previous.
+    $MergedResults | Sort-Object -Property NetMbps | Format-Table -AutoSize
     return
 }
 
@@ -388,15 +397,19 @@ if ($MergeDataFiles) {
 $LogScript = Join-Path $RootDir "scripts" "log.ps1"
 
 # Folder for log files.
-$LogDir = Join-Path $RootDir "artifacts" "logs" "wanperf" (Get-Date -UFormat "%m.%d.%Y.%T").Replace(':','.')
+$LogDir = Join-Path $RootDir "artifacts" "logs" "wanperf"
+if (!$NoDateLogDir) {
+    $LogDir = Join-Path $LogDir (Get-Date -UFormat "%m.%d.%Y.%T").Replace(':','.')
+}
 if ($LogProfile -ne "None") {
     try {
         Write-Debug "Canceling any already running logs"
-        & $LogScript -Cancel
+        & $LogScript -Cancel | Out-Null
     } catch {
     }
     New-Item -Path $LogDir -ItemType Directory -Force | Write-Debug
     Get-ChildItem $LogScript | Write-Debug
+    Write-Host "Logging to $LogDir"
 }
 
 if ($BaseRandomSeed -eq "") {
@@ -504,6 +517,10 @@ foreach ($ThisReorderDelayDeltaMs in $ReorderDelayDeltaMs) {
             $RandomSeed = $BaseRandomSeed + $i.ToString('x2').Substring(0,2)
             Set-NetAdapterAdvancedProperty duo? -DisplayName RandomSeed -RegistryValue $RandomSeed -NoRestart
 
+            Write-Debug "Restarting NIC"
+            Restart-NetAdapter duo?
+            Start-Sleep 5 # (wait for duonic to restart)
+
             if ($LogProfile -ne "None") {
                 try {
                     & $LogScript -Start -Profile $LogProfile | Out-Null
@@ -512,10 +529,6 @@ foreach ($ThisReorderDelayDeltaMs in $ReorderDelayDeltaMs) {
                 }
             }
 
-            Write-Debug "Restarting NIC"
-            Restart-NetAdapter duo?
-            Start-Sleep 5 # (wait for duonic to restart)
-
             # Run the throughput upload test with the current configuration.
             Write-Debug "Run upload test: Iteration=$($i + 1)"
 

src/core/congestion_control.h

@@ -78,7 +78,7 @@ typedef struct QUIC_CONGESTION_CONTROL {
         _In_ const QUIC_LOSS_EVENT* LossEvent
         );
 
-    void (*QuicCongestionControlOnSpuriousCongestionEvent)(
+    BOOLEAN (*QuicCongestionControlOnSpuriousCongestionEvent)(
         _In_ struct QUIC_CONGESTION_CONTROL* Cc
         );
 
@@ -225,12 +225,12 @@ QuicCongestionControlOnDataLost(
 //
 _IRQL_requires_max_(DISPATCH_LEVEL)
 inline
-void
+BOOLEAN
 QuicCongestionControlOnSpuriousCongestionEvent(
     _In_ QUIC_CONGESTION_CONTROL* Cc
     )
 {
-    Cc->QuicCongestionControlOnSpuriousCongestionEvent(Cc);
+    return Cc->QuicCongestionControlOnSpuriousCongestionEvent(Cc);
 }
 
 _IRQL_requires_max_(DISPATCH_LEVEL)

src/core/cubic.c

@@ -560,7 +560,7 @@ CubicCongestionControlOnDataLost(
 }
 
 _IRQL_requires_max_(DISPATCH_LEVEL)
-void
+BOOLEAN
 CubicCongestionControlOnSpuriousCongestionEvent(
     _In_ QUIC_CONGESTION_CONTROL* Cc
     )
@@ -568,7 +568,7 @@ CubicCongestionControlOnSpuriousCongestionEvent(
     QUIC_CONGESTION_CONTROL_CUBIC* Cubic = &Cc->Cubic;
 
     if (!Cubic->IsInRecovery) {
-        return;
+        return FALSE;
     }
 
     QUIC_CONNECTION* Connection = QuicCongestionControlGetConnection(Cc);
@@ -591,8 +591,9 @@ CubicCongestionControlOnSpuriousCongestionEvent(
     Cubic->IsInRecovery = FALSE;
     Cubic->HasHadCongestionEvent = FALSE;
 
-    CubicCongestionControlUpdateBlockedState(Cc, PreviousCanSendState);
+    BOOLEAN Result = CubicCongestionControlUpdateBlockedState(Cc, PreviousCanSendState);
     QuicConnLogCubic(Connection);
+    return Result;
 }
 
 void

src/core/inline.c

@@ -354,7 +354,7 @@ QuicCongestionControlOnDataLost(
     );
 
 _IRQL_requires_max_(DISPATCH_LEVEL)
-void
+BOOLEAN
 QuicCongestionControlOnSpuriousCongestionEvent(
     _In_ QUIC_CONGESTION_CONTROL* Cc
     );

src/core/loss_detection.c

@@ -1305,8 +1305,13 @@ QuicLossDetectionProcessAckBlocks(
                 // All previously considered lost packets were found to be
                 // spuriously lost. Inform congestion control.
                 //
-                QuicCongestionControlOnSpuriousCongestionEvent(
-                    &Connection->CongestionControl);
+                if (QuicCongestionControlOnSpuriousCongestionEvent(
+                        &Connection->CongestionControl)) {
+                    //
+                    // We were previously blocked and are now unblocked.
+                    //
+                    QuicSendQueueFlush(&Connection->Send, REASON_CONGESTION_CONTROL);
+                }
             }
         }
 

src/perf/bin/appmain.cpp

@@ -159,8 +159,8 @@ QuicUserMain(
         Status = QuicHandleRpsClient(Buffer.get(), Metadata.ExtraDataLength, FileName);
     }
 
-    printf("App Main returning status %d\n", Status);
     QuicMainFree();
+    printf("App Main returning status %d\n", Status);
     return Status;
 }
 

src/perf/lib/ThroughputClient.cpp

@@ -473,22 +473,21 @@ ThroughputClient::OnStreamShutdownComplete(
     uint64_t ElapsedMicroseconds = StrmContext->EndTime - StrmContext->StartTime;
     uint32_t SendRate = (uint32_t)((StrmContext->BytesCompleted * 1000 * 1000 * 8) / (1000 * ElapsedMicroseconds));
 
-    if (StrmContext->Complete) {
+    if (!StrmContext->Complete && StrmContext->BytesCompleted == 0) {
+        WriteOutput("Error: Did not complete any bytes! Failed to connect?\n");
+    } else {
         WriteOutput(
             "Result: %llu bytes @ %u kbps (%u.%03u ms).\n",
             (unsigned long long)StrmContext->BytesCompleted,
             SendRate,
             (uint32_t)(ElapsedMicroseconds / 1000),
             (uint32_t)(ElapsedMicroseconds % 1000));
-    } else if (StrmContext->BytesCompleted) {
-        WriteOutput(
-            "Error: Did not complete all bytes! %llu bytes @ %u kbps (%u.%03u ms).\n",
-            (unsigned long long)StrmContext->BytesCompleted,
-            SendRate,
-            (uint32_t)(ElapsedMicroseconds / 1000),
-            (uint32_t)(ElapsedMicroseconds % 1000));
-    } else {
-        WriteOutput("Error: Did not complete any bytes! Failed to connect?\n");
+        if (!StrmContext->Complete) {
+            WriteOutput(
+                "Warning: Did not complete all bytes (sent: %llu, completed: %llu).\n",
+                (unsigned long long)StrmContext->BytesSent,
+                (unsigned long long)StrmContext->BytesCompleted);
+        }
     }
 
     StreamContextAllocator.Free(StrmContext);