WanPerf: Logging and Pacing (microsoft#1058)

.azure/azure-pipelines.wanperf.yml

@@ -25,6 +25,18 @@ parameters:
   type: string
   displayName: RTT (ms)
   default: '50'
+- name: pacing
+  type: string
+  displayName: Pacing
+  default: '(0,1)'
+- name: logProfile
+  type: string
+  displayName: Logging Profile
+  default: None
+  values:
+  - None
+  - Datapath.Light
+  - Performance.Light
 
 stages:
 
@@ -62,3 +74,5 @@ stages:
       durationMs: ${{ parameters.durationMs }}
       rateMbps: ${{ parameters.rateMbps }}
       rttMs: ${{ parameters.rttMs }}
+      pacing: ${{ parameters.pacing }}
+      logProfile: ${{ parameters.logProfile }}

.azure/templates/run-wanperf.yml

@@ -11,6 +11,8 @@ parameters:
   rateMbps: '(10,50,100)'
   durationMs: '10'
   rttMs: '50'
+  pacing: '(0,1)'
+  logProfile: 'None'
 
 jobs:
 - job: performance_${{ parameters.platform }}_${{ parameters.arch }}_${{ parameters.tls }}
@@ -49,4 +51,13 @@ jobs:
     inputs:
       pwsh: true
       filePath: scripts/emulated-performance.ps1
-      arguments: -NumIterations ${{ parameters.iterations }} -BottleneckMbps ${{ parameters.rateMbps }} -DurationMs ${{ parameters.durationMs }} -RttMs ${{ parameters.rttMs }} -Config ${{ parameters.config }} -Arch ${{ parameters.arch }} -Tls ${{ parameters.tls }}
+      arguments: -NumIterations ${{ parameters.iterations }} -BottleneckMbps ${{ parameters.rateMbps }} -DurationMs ${{ parameters.durationMs }} -RttMs ${{ parameters.rttMs }} -Pacing ${{ parameters.pacing }} -LogProfile ${{ parameters.logProfile }} -Config ${{ parameters.config }} -Arch ${{ parameters.arch }} -Tls ${{ parameters.tls }}
+
+  - ${{ if ne(parameters.logProfile, 'None') }}:
+    - template: ./upload-test-artifacts.yml
+      parameters:
+        platform: ${{ parameters.platform }}
+        config: ${{ parameters.config }}
+        arch: ${{ parameters.arch }}
+        tls: ${{ parameters.tls }}
+        publishTest: false

.azure/templates/upload-test-artifacts.yml

@@ -5,6 +5,7 @@ parameters:
   config: ''
   arch: ''
   tls: ''
+  publishTest: true
   codeCoverage: false
 
 steps:
@@ -32,12 +33,13 @@ steps:
         contents: '**/!(*-results.xml)'
         targetFolder: $(Build.ArtifactStagingDirectory)/${{ parameters.platform }}/${{ parameters.arch }}_${{ parameters.config }}_${{ parameters.tls }}
 
-  - task: PublishTestResults@2
-    displayName: 'Publish Test Results'
-    inputs:
-      testResultsFormat: 'JUnit'
-      testResultsFiles: '**/*-results.xml'
-      failTaskOnFailedTests: true
+  - ${{ if eq(parameters.publishTest, true) }}:
+    - task: PublishTestResults@2
+      displayName: 'Publish Test Results'
+      inputs:
+        testResultsFormat: 'JUnit'
+        testResultsFiles: '**/*-results.xml'
+        failTaskOnFailedTests: true
 
   - task: DeleteFiles@1
     displayName: Clear Artifacts
@@ -47,7 +49,8 @@ steps:
   - ${{ if eq(parameters.codeCoverage, false) }}:
     - task: PublishBuildArtifacts@1
       displayName: Publish Test Output
-      condition: failed()
+      ${{ if eq(parameters.publishTest, true) }}:
+        condition: failed()
       inputs:
         artifactName: logs
         pathToPublish: $(Build.ArtifactStagingDirectory)

scripts/emulated-performance.ps1

@@ -83,7 +83,11 @@ param (
     [Int32[]]$Pacing = (0, 1),
 
     [Parameter(Mandatory = $false)]
-    [Int32]$NumIterations = 1
+    [Int32]$NumIterations = 1,
+
+    [Parameter(Mandatory = $false)]
+    [ValidateSet("None", "Datapath.Light", "Datapath.Verbose", "Performance.Light", "Performance.Verbose")]
+    [string]$LogProfile = "None"
 )
 
 Set-StrictMode -Version 'Latest'
@@ -101,6 +105,21 @@ if ("" -eq $Tls) {
 # Root directory of the project.
 $RootDir = Split-Path $PSScriptRoot -Parent
 
+# Script for controlling loggings.
+$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(':','.')
+if ($LogProfile -ne "None") {
+    try {
+        Write-Debug "Canceling any already running logs"
+        & $LogScript -Cancel
+    } catch {
+    }
+    New-Item -Path $LogDir -ItemType Directory -Force | Write-Debug
+    dir $LogScript | Write-Debug
+}
+
 # Path to the quicperf exectuable.
 $QuicPerf = $null
 if ($IsWindows) {
@@ -168,16 +187,39 @@ foreach ($ThisReorderDelayDeltaMs in $ReorderDelayDeltaMs) {
         Write-Debug "Run upload test: Duration=$ThisDurationMs ms, Pacing=$ThisPacing"
         for ($i = 0; $i -lt $NumIterations; $i++) {
 
+            if ($LogProfile -ne "None") {
+                try {
+                    & $LogScript -Start -Profile $LogProfile | Out-Null
+                } catch {
+                    Write-Debug "Logging exception"
+                }
+            }
+
             # Run the throughput upload test with the current configuration.
+            Write-Debug "Run upload test: Iteration=$($i + 1)"
             $Output = iex "$QuicPerf -test:tput -bind:192.168.1.12 -target:192.168.1.11 -sendbuf:0 -upload:$ThisDurationMs -timed:1 -pacing:$ThisPacing"
             if (!$Output.Contains("App Main returning status 0") -or $Output.Contains("Error:")) {
+                if ($LogProfile -ne "None") {
+                    & $LogScript -Cancel | Out-Null
+                }
                 Write-Error $Output
             }
 
-            # Grab the result output text.
+            # Grab the result from the output text.
             $Result = $Output.Split([Environment]::NewLine)[-2]
             Write-Debug $Result
-            $Results.Add([int]$Result.Split(" ")[4]) | Out-Null
+            $Rate = [int]$Result.Split(" ")[4]
+            $Results.Add($Rate) | Out-Null
+
+            if ($LogProfile -ne "None") {
+                $TestLogDir = Join-Path $LogDir "$ThisRttMs.$ThisBottleneckMbps.$ThisBottleneckBufferPackets.$ThisRandomLossDenominator.$ThisRandomReorderDenominator.$ThisReorderDelayDeltaMs.$ThisDurationMs.$ThisPacing.$i.$Rate"
+                mkdir $TestLogDir | Out-Null
+                try {
+                    & $LogScript -Stop -OutputDirectory $TestLogDir -RawLogOnly | Out-Null
+                } catch {
+                    Write-Debug "Logging exception"
+                }
+            }
         }
 
         # Grab the average result and write the CSV output.

scripts/log.ps1

@@ -43,7 +43,7 @@ param (
     [switch]$Stream = $false,
 
     [Parameter(Mandatory = $false, ParameterSetName='Start')]
-    [ValidateSet("Basic.Light", "Basic.Verbose", "Full.Light", "Full.Verbose", "SpinQuic.Light")]
+    [ValidateSet("Basic.Light", "Datapath.Light", "Datapath.Verbose", "Performance.Light", "Basic.Verbose", "Performance.Light", "Performance.Verbose", "Full.Light", "Full.Verbose", "SpinQuic.Light")]
     [string]$Profile = "Full.Light",
 
     [Parameter(Mandatory = $false, ParameterSetName='Cancel')]

src/manifest/MsQuic.wprp

@@ -47,6 +47,11 @@
         <Keyword Value="0x80000800"/>
       </Keywords>
     </EventProvider>
+    <EventProvider Id="EP_MsQuicEtw_NoLogs" Name="ff15e657-4f26-570e-88ab-0796b258d11c" NonPagedMemory="true">
+      <Keywords>
+        <Keyword Value="0xE0000800"/>
+      </Keywords>
+    </EventProvider>
 
     <EventProvider Id="EP_TcpIpEtw" Name="Microsoft-Windows-TCPIP" NonPagedMemory="true" />
     <EventProvider Id="EP_WinSockEtw" Name="Microsoft-Windows-Winsock-AFD" NonPagedMemory="true" />
@@ -75,7 +80,7 @@
       <Collectors>
         <EventCollectorId Value="EC_HighVolume">
           <EventProviders>
-            <EventProviderId Value="EP_MsQuicEtw" />
+            <EventProviderId Value="EP_MsQuicEtw_NoLogs" />
           </EventProviders>
         </EventCollectorId>
       </Collectors>
@@ -89,7 +94,7 @@
         </SystemCollectorId>
         <EventCollectorId Value="EC_HighVolume">
           <EventProviders>
-            <EventProviderId Value="EP_MsQuicEtw" />
+            <EventProviderId Value="EP_MsQuicEtw_NoLogs" />
           </EventProviders>
         </EventCollectorId>
       </Collectors>