Upload linux perf command results (#3349)

* generate .perf trace

* change order

* tmp

* check

* ooo

* specify file

* check

* aaa

* install perf

* add

* install perf

* add to log.ps1

* add

* odebug print

* print output

* add loop to wait collection

* small sampling rate

* print info

* gen svg

* fix typo

* fix perf install trigger

* chmod to flamegraph scripts and add debug output

* fix count variable access. use @ instead of $

* try catch perf

* debug print

* print from remote

* more debug

* add -ErrorAction Continue

* error oput

* use original

* wrap

* DebugPreference Continue

* stop server side PerfGraph

* explicitly install flamegraph tools

* set path for flamegraaph tools

* fix file existence check

* gset perf paranoid

* setup flamegraph tools just before using

* add sudo

* sudo for perf

* add sudo for all perf

* check permissions

* pass environment variables

* set explicit library path

* enable server perf tracing

* output details for remote exe

* stop server perf trace

* remove original LD_LIBRARY_PATH

* show out of memory

* remove comment, enable server

* fix directory name

* commenting

* oops

* Fix tar error

* remove Write-Debug as it is critical issue

* fix SmbDir for linux

* stop debug print

* add throw for Perf function

* Use max sampling frequency for perf with workaround

* upload perf txt file for WPA visualization

* add documents

* add images

* fix data extension

* smaller freq

* cleanup before perf run

* add Path check

* delete file for each type

* reduce sampling freq. addpending work

* use safer file name based operation

* parallelize client perf post processing

* reduce freq and parallelize server/client post proccessing

* increase timeout for perf measurement

* add cancel func

* change timeout to 90min

* fix tab

* Fix Loopback server side warning

* adjust for throughput tests
This commit is contained in:
Daiki AMINAKA 2023-02-03 20:22:13 -08:00 коммит произвёл GitHub
Родитель feccf650c2
Коммит 82e65c7e36
Не найден ключ, соответствующий данной подписи
Идентификатор ключа GPG: 4AEE18F83AFDEB23
7 изменённых файлов: 214 добавлений и 35 удалений

Просмотреть файл

@ -15,6 +15,7 @@ On Windows, MsQuic leverages manifested [ETW](https://docs.microsoft.com/en-us/w
### Linux
#### LTTng
On Linux, MsQuic leverages [LTTng](https://lttng.org/features/) for its logging. Some dependencies, such as babeltrace, lttng, and clog2text_lttng are required. The simplest way to install all dependencies is by running `./scripts/prepare-machine.ps1 -ForTest`, but if you only want to collect the traces on the machine, the **minimal dependencies** are:
```
@ -23,6 +24,9 @@ sudo apt-get update
sudo apt-get install -y lttng-tools
```
#### Perf
For general tracing, refer [Stacks and CPU usage](../src/plugins/trace/README.md#linux)
### macOS
Tracing is currently unsupported on macOS.

Просмотреть файл

@ -15,6 +15,21 @@ This script provides helpers for starting, stopping and canceling log collection
.PARAMETER Stop
Stops the logs from being collected and saves them to the -Output location.
.PARAMETER PerfRun
Use perf command to wrap exe
.PARAMETER Command
Command to be wrapped by PerfRun
.PARAMETER Iteration
Current test iteration from client
.PARAMETER PerfGraph
Use perf command to generate flamegraph
.PARAMETER NumIterations
The number of test iterations from client
.PARAMETER Output
The output file name or directory for the logs.
@ -27,6 +42,9 @@ This script provides helpers for starting, stopping and canceling log collection
.PARAMETER ProfileInScriptDirectory
Flag for if the MsQuic wprp file is in the same directory as the script.
.PARAMETER Remote
Flag for if the logging is for Local/Remote
.EXAMPLE
logs.ps1 -Start -Profile Basic.Light
@ -55,7 +73,23 @@ param (
[Parameter(Mandatory = $false, ParameterSetName='Stop')]
[switch]$Stop = $false,
[Parameter(Mandatory = $false, ParameterSetName='PerfRun')]
[switch]$PerfRun = $false,
[Parameter(Mandatory = $false, ParameterSetName='PerfRun')]
[string]$Command = "",
[Parameter(Mandatory = $false, ParameterSetName='PerfRun')]
[int]$Iteration = 1,
[Parameter(Mandatory = $false, ParameterSetName='PerfGraph')]
[switch]$PerfGraph = $false,
[Parameter(Mandatory = $false, ParameterSetName='PerfGraph')]
[int]$NumIterations = 1,
[Parameter(Mandatory = $true, ParameterSetName='Stop')]
[Parameter(Mandatory = $true, ParameterSetName='PerfGraph')]
[string]$OutputPath = "",
[Parameter(Mandatory = $false, ParameterSetName='Stop')]
@ -73,11 +107,14 @@ param (
[Parameter(Mandatory = $true, ParameterSetName='Decode')]
[string]$WorkingDirectory,
[Parameter(Mandatory = $false)]
[switch]$ProfileInScriptDirectory = $false,
[Parameter(Mandatory = $false)]
[string]$InstanceName = "msquic",
[Parameter(Mandatory = $false)]
[switch]$ProfileInScriptDirectory = $false
[switch]$Remote = $false
)
Set-StrictMode -Version 'Latest'
@ -95,10 +132,13 @@ $SideCar = Join-Path $RootDir "src/manifest/clog.sidecar"
$Clog2Text_lttng = "$HOME/.dotnet/tools/clog2text_lttng"
$TempDir = $null
$TempLTTngDir = $null
$TempPerfDir = $null
if ($IsLinux) {
$InstanceName = $InstanceName.Replace(".", "_")
$TempDir = Join-Path $HOME "QUICLogs" $InstanceName
$TempDir = Join-Path $HOME "QUICLogs"
$TempLTTngDir = Join-Path $TempDir $InstanceName
$TempPerfDir = Join-Path $TempDir "Perf"
try { lttng version | Out-Null }
catch {
Write-Host "Installing lttng"
@ -107,6 +147,79 @@ if ($IsLinux) {
sudo apt-get install -y lttng-tools
sudo apt-get install -y liblttng-ust-dev
}
try { perf version | Out-Null }
catch {
Write-Debug "Installing perf"
sudo apt-get install -y linux-tools-$(uname -r)
sudo wget https://raw.githubusercontent.com/brendangregg/FlameGraph/master/stackcollapse-perf.pl -O /usr/bin/stackcollapse-perf.pl
sudo chmod +x /usr/bin/stackcollapse-perf.pl
sudo wget https://raw.githubusercontent.com/brendangregg/FlameGraph/master/flamegraph.pl -O /usr/bin/flamegraph.pl
sudo chmod +x /usr/bin/flamegraph.pl
}
}
function Perf-Run {
if (!$IsLinux) {
throw "perf command wrapper is only for Linux"
} else {
New-Item -Path $TempPerfDir -ItemType Directory -Force
$CommandSplit = $Command.Split(" ")
$OutFile = "server.perf.data"
if (!$Remote) {
$OutFile = "client_$Iteration.perf.data"
}
$BasePath = Split-Path $CommandSplit[0] -Parent
# FIXME: When to run Remote case and command bellow generates stderr, server side stop its operation
# e.g. - `-F max`'s warning
# - `perf`'s graceful stop generates two lines of stderr. the first line stops the operation (no essential effect)
# FIXME: Small frequency for now. Higher (e.g. max) freq (with -a) generates big data which causes host machine to be overloaded,
# cause timeout and/or WPA becomes too slow to load/convert trace
# FIXME: Make WPA to load trace which is collected without -a option. this is PerfView design.
# https://github.com/microsoft/perfview/issues/1793
# FIXME: Run only single `perf` in case of using -a option for Loopback test as it collects trace from entire system
#
# WARN: If all test cases runs, timeout need to be more than 90 min with Freq of 99.
# Especially HPS/RPS tests are heavy
# WARN: Must not redirect output to Out-Debug and Out-Null as client watches server's stdout
$Freq = 399
sudo LD_LIBRARY_PATH=$BasePath perf record -F $Freq -g -o $(Join-Path $TempPerfDir $OutFile) $CommandSplit[0] $CommandSplit[1..$($CommandSplit.count-1)]
}
}
function Perf-Cancel {
if (!$IsLinux) {
throw "perf command wapper is only for Linux"
} else {
sudo pkill perf
try { Remove-Item -Path $TempPerfDir -Recurse -Force | Out-Null } catch { }
}
}
function Perf-Graph {
if (!$IsLinux) {
throw "perf command wapper is only for Linux"
} else {
New-Item -ItemType Directory $OutputPath -Force | Out-Null
if ($Remote) {
$InputPath = $(Join-Path $TempPerfDir "server.perf.data")
sudo -E perf script -i $InputPath > $(Join-Path $OutputPath "server.perf.data.txt")
cat $(Join-Path $OutputPath "server.perf.data.txt") | stackcollapse-perf.pl | flamegraph.pl > $(Join-Path $OutputPath "server.svg")
Remove-Item -Path $InputPath -Force | Out-Null
} else {
1..$NumIterations | ForEach {
Start-Job -ScriptBlock {
$FileName = "client_$using:_.perf.data"
$InputPath = $(Join-Path $using:TempPerfDir $FileName)
sudo -E perf script -i $InputPath > $(Join-Path $using:OutputPath ($FileName.Split(".")[0] + ".perf.data.txt"))
cat $(Join-Path $using:OutputPath ($FileName.Split(".")[0] + ".perf.data.txt")) | stackcollapse-perf.pl | flamegraph.pl > $(Join-Path $using:OutputPath ($FileName.Split(".")[0] + ".svg"))
Remove-Item -Path $InputPath -Force | Out-Null
}
} | Wait-Job | Receive-Job -ErrorAction Continue
}
if (@(Get-ChildItem $TempPerfDir).count -eq 0) {
Remove-Item -Path $TempPerfDir -Recurse -Force | Out-Null
}
}
}
# Start log collection.
@ -115,16 +228,16 @@ function Log-Start {
wpr.exe -start "$($WprpFile)!$($Profile)" -filemode -instancename $InstanceName 2>&1
} elseif ($IsMacOS) {
} else {
if (Test-Path $TempDir) {
Write-Error "LTTng session ($InstanceName) already running! ($TempDir)"
if (Test-Path $TempLTTngDir) {
Write-Error "LTTng session ($InstanceName) already running! ($TempLTTngDir)"
}
try {
if ($Stream) {
lttng -q create msquiclive --live
} else {
New-Item -Path $TempDir -ItemType Directory -Force | Out-Null
$Command = "lttng create $InstanceName -o=$TempDir"
New-Item -Path $TempLTTngDir -ItemType Directory -Force | Out-Null
$Command = "lttng create $InstanceName -o=$TempLTTngDir"
Invoke-Expression $Command | Write-Debug
}
lttng enable-event --userspace CLOG_* | Write-Debug
@ -154,13 +267,14 @@ function Log-Cancel {
try { wpr.exe -cancel -instancename $InstanceName 2>&1 } catch { }
} elseif ($IsMacOS) {
} else {
if (!(Test-Path $TempDir)) {
if (!(Test-Path $TempLTTngDir)) {
Write-Debug "LTTng session ($InstanceName) not currently running"
} else {
try { Invoke-Expression "lttng destroy -n $InstanceName" | Write-Debug } catch { }
try { Remove-Item -Path $TempDir -Recurse -Force | Out-Null } catch { }
Write-Debug "Destroyed LTTng session ($InstanceName) and deleted $TempDir"
try { Remove-Item -Path $TempLTTngDir -Recurse -Force | Out-Null } catch { }
Write-Debug "Destroyed LTTng session ($InstanceName) and deleted $TempLTTngDir"
}
Perf-Cancel
}
$global:LASTEXITCODE = 0
}
@ -186,7 +300,7 @@ function Log-Stop {
New-Item -Path $OutputPath -ItemType Directory -Force | Out-Null
}
if (!(Test-Path $TempDir)) {
if (!(Test-Path $TempLTTngDir)) {
Write-Error "LTTng session ($InstanceName) not currently running!"
}
@ -196,11 +310,11 @@ function Log-Stop {
$BableTraceFile = $OutputPath + ".babel.txt"
Write-Host "tar/gzip LTTng log files: $LTTNGTarFile"
tar -cvzf $LTTNGTarFile $TempDir | Write-Debug
tar -cvzf $LTTNGTarFile -P $TempLTTngDir | Write-Debug
if (!$RawLogOnly) {
Write-Debug "Decoding LTTng into BabelTrace format ($BableTraceFile)"
babeltrace --names all $TempDir/* > $BableTraceFile
babeltrace --names all $TempLTTngDir/* > $BableTraceFile
Write-Host "Decoding into human-readable text: $ClogOutputDecodeFile"
$Command = "$Clog2Text_lttng -i $BableTraceFile -s $SideCar -o $ClogOutputDecodeFile --showTimestamp --showCpuInfo"
Write-Host $Command
@ -217,8 +331,8 @@ function Log-Stop {
}
Invoke-Expression "lttng destroy $InstanceName" | Write-Debug
Remove-Item -Path $TempDir -Recurse -Force | Out-Null
Write-Debug "Destroyed LTTng session ($InstanceName) and deleted $TempDir"
Remove-Item -Path $TempLTTngDir -Recurse -Force | Out-Null
Write-Debug "Destroyed LTTng session ($InstanceName) and deleted $TempLTTngDir"
}
}
# Decodes a log file.
@ -270,3 +384,5 @@ if ($Start) { Log-Start }
if ($Cancel) { Log-Cancel }
if ($Stop) { Log-Stop }
if ($Decode) { Log-Decode }
if ($PerfRun) { Perf-Run }
if ($PerfGraph) { Perf-Graph }

Просмотреть файл

@ -143,7 +143,7 @@ function Wait-ForRemoteReady {
param ($Job, $Matcher)
$StopWatch = [system.diagnostics.stopwatch]::StartNew()
while ($StopWatch.ElapsedMilliseconds -lt 20000) {
$CurrentResults = Receive-Job -Job $Job -Keep
$CurrentResults = Receive-Job -Job $Job -Keep -ErrorAction Continue
if (![string]::IsNullOrWhiteSpace($CurrentResults)) {
$DidMatch = $CurrentResults -match $Matcher
if ($DidMatch) {
@ -156,7 +156,7 @@ function Wait-ForRemoteReady {
}
function Wait-ForRemote {
param ($Job)
param ($Job, $ErrorAction = "Stop")
# Ping sidechannel socket on 9999 to tell the app to die
$Socket = New-Object System.Net.Sockets.UDPClient
$BytesToSend = @(
@ -172,7 +172,7 @@ function Wait-ForRemote {
}
Stop-Job -Job $Job | Out-Null
$RetVal = Receive-Job -Job $Job
$RetVal = Receive-Job -Job $Job -ErrorAction $ErrorAction
return $RetVal -join "`n"
}
@ -376,7 +376,11 @@ function Invoke-RemoteExe {
}
try {
& $Exe ($RunArgs).Split(" ")
if ($IsLinux -and $Record) {
& $LogScript -PerfRun -Command "$Exe $RunArgs" -Remote
} else {
& $Exe ($RunArgs).Split(" ")
}
} finally {
# Uninstall the kernel mode test drivers.
if ($Kernel) {
@ -386,7 +390,6 @@ function Invoke-RemoteExe {
sc.exe delete msquicpriv | Out-Null
}
}
} -AsJob -ArgumentList $Exe, $RunArgs, $BasePath, $Record, $LogProfile, $Kernel, $RemoteDirectory
}
@ -403,13 +406,16 @@ function Cancel-RemoteLogs {
function Stop-RemoteLogs {
param ($RemoteDirectory)
Invoke-TestCommand -Session $Session -ScriptBlock {
return Invoke-TestCommand -AsJob -Session $Session -ScriptBlock {
param ($Record, $RemoteDirectory)
$LogScript = Join-Path $RemoteDirectory log.ps1
if ($Record) {
& $LogScript -Stop -OutputPath (Join-Path $RemoteDirectory serverlogs server) -RawLogOnly -ProfileInScriptDirectory -InstanceName msquicperf | Out-Null
if ($IsLinux) {
& $LogScript -PerfGraph -OutputPath (Join-Path $RemoteDirectory serverlogs) -Remote | Write-Debug
}
}
} -ArgumentList $Record, $RemoteDirectory
}
@ -485,10 +491,15 @@ function Cancel-LocalTracing {
}
function Stop-Tracing {
param($LocalDirectory, $OutputDir, $Test)
if ($Record -and !$Local) {
$LogScript = Join-Path $LocalDirectory log.ps1
& $LogScript -Stop -OutputPath (Join-Path $OutputDir $Test.ToString() client) -RawLogOnly -ProfileInScriptDirectory -InstanceName msquicperf | Out-Null
param($LocalDirectory, $OutputDir, $Test, $NumIterations)
$LogScript = Join-Path $LocalDirectory log.ps1
if ($Record) {
if (!$Local) {
& $LogScript -Stop -OutputPath (Join-Path $OutputDir $Test.ToString() client) -RawLogOnly -ProfileInScriptDirectory -InstanceName msquicperf | Out-Null
}
if ($IsLinux) {
& $LogScript -PerfGraph -OutputPath (Join-Path $OutputDir $Test.ToString()) -NumIterations $NumIterations | Write-Debug
}
}
}
@ -522,7 +533,7 @@ function Log($msg) {
function Invoke-LocalExe {
[Diagnostics.CodeAnalysis.SuppressMessageAttribute('PSAvoidUsingInvokeExpression', '')]
param ($Exe, $RunArgs, $Timeout, $OutputDir, $HistogramFileName)
param ($Exe, $RunArgs, $Timeout, $OutputDir, $HistogramFileName, $Iteration)
$BasePath = Split-Path $Exe -Parent
if (!$IsWindows) {
$env:LD_LIBRARY_PATH = $BasePath
@ -534,6 +545,10 @@ function Invoke-LocalExe {
}
$HistogramFilePath = Join-Path $HistogramDir $HistogramFileName
$RunArgs = """--extraOutputFile:$HistogramFilePath"" $RunArgs"
if ($IsLinux -and $Record) {
# `perf record -F max` generates too big data to finish within default Timeout (120s)
$Timeout = 2000
}
$TimeoutMs = ($Timeout - 5) * 1000;
$RunArgs = "-watchdog:$TimeoutMs $RunArgs"
@ -561,7 +576,12 @@ function Invoke-LocalExe {
$LocalJob = $null
try {
$LocalJob = Start-Job -ScriptBlock { & $Using:Exe ($Using:RunArgs).Split(" ") }
if ($IsLinux -and $Record) {
$LogScript = Join-Path $LocalDirectory log.ps1
$LocalJob = Start-Job -ScriptBlock { & $Using:LogScript -PerfRun -Command $Using:FullCommand -Iteration $Using:Iteration }
} else {
$LocalJob = Start-Job -ScriptBlock { & $Using:Exe ($Using:RunArgs).Split(" ") }
}
} finally {
if ($null -ne $LocalJob) {
# Wait for the job to finish
@ -570,8 +590,8 @@ function Invoke-LocalExe {
}
}
$RetVal = Receive-Job -Job $LocalJob
# -ErrorAction Continue for "perf" to return error when stop
$RetVal = Receive-Job -Job $LocalJob -ErrorAction Continue
$Stopwatch.Stop()
if ($IsWindows) {

Просмотреть файл

@ -482,7 +482,7 @@ function Invoke-Test {
try {
1..$NumIterations | ForEach-Object {
Write-LogAndDebug "Running Local: $LocalExe Args: $LocalArguments"
$LocalResults = Invoke-LocalExe -Exe $LocalExe -RunArgs $LocalArguments -Timeout $Timeout -OutputDir $OutputDir -HistogramFileName "$($Test)_run$($_).txt"
$LocalResults = Invoke-LocalExe -Exe $LocalExe -RunArgs $LocalArguments -Timeout $Timeout -OutputDir $OutputDir -HistogramFileName "$($Test)_run$($_).txt" -Iteration $_
Write-LogAndDebug $LocalResults
$AllLocalParsedResults = Get-TestResult -Results $LocalResults -Matcher $Test.ResultsMatcher -FailureDefault $Test.FailureDefault
$AllRunsResults += $AllLocalParsedResults
@ -506,10 +506,12 @@ function Invoke-Test {
$LocalResults | Write-LogAndDebug
}
} finally {
$RemoteResults = Wait-ForRemote -Job $RemoteJob
# -ErrorAction Continue for "perf" to return error when stop
$RemoteResults = Wait-ForRemote -Job $RemoteJob -ErrorAction Continue
Write-LogAndDebug $RemoteResults.ToString()
Stop-RemoteLogs -RemoteDirectory $RemoteDirectory
# parallelize post processing with client
$StoppingRemoteJob = Stop-RemoteLogs -RemoteDirectory $RemoteDirectory
if ($Kernel) {
net.exe stop secnetperfdrvpriv /y | Out-Null
@ -518,7 +520,9 @@ function Invoke-Test {
sc.exe delete msquicpriv | Out-Null
}
Stop-Tracing -LocalDirectory $LocalDirectory -OutputDir $OutputDir -Test $Test
# FIXME: Using Start-Job in this func cause program hang for some reason
Stop-Tracing -LocalDirectory $LocalDirectory -OutputDir $OutputDir -Test $Test -NumIterations $NumIterations
$StoppingRemoteJob | Wait-Job | Receive-Job -ErrorAction Continue
if ($Record) {
if ($Local) {
@ -532,7 +536,11 @@ function Invoke-Test {
}
} else {
try {
Get-RemoteLogDirectory -Local (Join-Path $OutputDir $Test.ToString()) -Remote (Join-Path $RemoteDirectory serverlogs) -SmbDir (Join-Path $RemoteDirectorySMB serverlogs) -Cleanup
$SmbDir = ""
if ($IsWindows) {
$SmbDir = (Join-Path $RemoteDirectorySMB serverlogs)
}
Get-RemoteLogDirectory -Local (Join-Path $OutputDir $Test.ToString()) -Remote (Join-Path $RemoteDirectory serverlogs) -SmbDir $SmbDir -Cleanup
} catch {
Write-Host "Failed to get remote logs"
}

Просмотреть файл

@ -37,12 +37,43 @@ Select and Open .etl file
3. Select the .ctf file
## Stacks CPU Usage
## Call stacks and CPU Usage
### Windows
![](images/flame.png)
One of the built-in capabilities of WPA is the ability to analyze CPU trace information to see the CPU usage of the various call stacks in the code. For instance, in the above Flame Graph you can easily see that the most expensive function (58% of total CPU usage!) is `CxPlatEncrypt`.
### Linux
Linux perf command is one of the way to collect such information.
```sh
# on Linux
sudo apt-get install -y linux-tools-`uname -r`
# use your own options
perf record -a -g -F 10 -o out.perf.data
# ".perf.data.txt" extension is required for later visualize on WPA
perf script -i out.perf.data > out.perf.data.txt
```
#### Visualize perf artifact on WPA
The perf command's artifact can be visualized on Windows through WPA.
Follow steps below to load perf extension on WPA.
```pwsh
# on Windows
cd ${WORKDIR}
git clone https://github.com/microsoft/Microsoft-Performance-Tools-Linux-Android
cd .\Microsoft-Performance-Tools-Linux-Android\PerfDataExtensions
dotnet build
# use absolute path
wpa.exe -addsearchdir ${WORKDIR}\Microsoft-Performance-Tools-Linux-Android\PerfDataExtensions\bin\Debug\netstandard2.1\
# Open out.perf.data.txt on WPA. You might need to open multiple time if you see error at opening (known issue?)
```
Change visualization type by drop down menu as shown in image below. Also you can filter in data for each CPU etc.
![](images/wpa_perf_line.png)
![](images/wpa_perf_flamegraph.png)
**TODO** - Add more details/instructions.
## QUIC Charts and Tables

Двоичные данные
src/plugins/trace/images/wpa_perf_flamegraph.png Normal file

Двоичный файл не отображается.

После

Ширина:  |  Высота:  |  Размер: 230 KiB

Двоичные данные
src/plugins/trace/images/wpa_perf_line.png Normal file

Двоичный файл не отображается.

После

Ширина:  |  Высота:  |  Размер: 404 KiB