Using Powershell to Automate VSPerfCmd.exe (Visual Studio Performance Profiling)

Question

Because this question is an attempt at troubleshooting a larger effort on my part I have included significant background and investigation history in the post below. As such, I have broken the post into 3 sections: "Background", "Investigation So Far", and "Problem". As I did some more investigation on my own I also added an "Additional Investigation" section to expand my findings. This eventually led me to solve the problem on my own and I have included the original post as a guide for any dev attempting to do the same thing. The issue ultimately ended up being a return of control issue VSPerfCmd.exe has in Powershell versions after v1.

1. Background

As part of my TFS Build (which includes auto-deployment to my development web server DEV), I would like to kick off and run a performance test of my code so that I can see when new changes negatively impact the speed of my API. To that end, I have installed a test-runner (SoapUI) and VS Team Tools on DEV and written a Powershell script that, when run locally on DEV, produces the reports I want. However, I have yet to be able to trigger that script and have it work from any other location. By that I mean that, only by logging onto the server, finding the .ps1 file and running it in Powershell does it work. Here is that script:

#script location+name \\DEV\C$\PerformanceTest\profile-tracing-SoapUI.ps1
$startPath = Get-Location
$siteUrl = "http://api.dev.com"
$sleepTime = 5
$logLocation = "C:\reports\api"
$websiteLocation = "W:\Sites\API\Code\API\_PublishedWebsites\API\bin"

try
{
    #Instrument the API dlls
    Write-Host "Instrumenting DLLs..."
    Get-ChildItem $websiteLocation "API*.dll" | ForEach-Object {
        Set-Location -Path $websiteLocation
        & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSInstr.exe" $_.Name
    }

    #set location back to start
    Set-Location -Path $startPath

    & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCLREnv.cmd" /GlobalTraceOn
    & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCLREnv.cmd" /GlobalInteractionOn

    #launch the profiler on the site
    Write-Host "Starting the trace..."

    #start:Trace - in tracing mode so we get timing data
    #output - the output vsp file
    #cs - cross session mode because we are profiling an IIS session
    #user - give permissions to profile to everyone
    #globaloff - start with capturing off so we don't get start up data.
    & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCmd.exe" /start:Trace /output:$logLocation"\API.vsp" /cs /User:Everyone /globaloff

    #restart IIS so the tracer can detect it
    Write-Host "Resetting IIS..."
    IISReset t80w103 /noforce
    IISReset t80w103 /status

    #output the status
    & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCmd.exe" /status

    #set up request for triggering api start up
    Write-Host "Starting app via untraced request..."
    $request = [System.Net.WebRequest]::Create("$siteUrl/api/v1/foo/1")
    $request.ContentType = "application/json"
    $request.Method = "GET" 

    #run an initial request to trigger api start up
    $response = $request.GetResponse()
    Write-Host $response.StatusCode

    #enable capturing
    Write-Host "Enabling capturing..."
    & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCmd.exe" /globalon

    #wait so everything can catch up
    Write-Host "Pausing for $sleepTime seconds to let processes catch up..."
    Start-Sleep -s $sleepTime

    #run the load tester
    Write-Host "Running SOAP UI load test"
    #e - the site to test against
    #s - the test suite name
    #c - the test cases
    #l - the loadtest to run
    #r - log reports
    #f - log location
    #<soap ui test suite location>
    $loadtestName = "LoadTest All API Methods"
    & "C:\Program Files (x86)\SmartBear\SoapUI-5.1.3\bin\loadtestrunner.bat" -e $siteUrl -s "Load Test" -c "Load Test Cases" -l $loadtestName -r -f $logLocation "Api Profiler Load Test.xml"


    #wait so everything can catch up
    Write-Host "Pausing for $sleepTime seconds to let processes catch up..."
    Start-Sleep -s $sleepTime

    #disable capturing
    Write-Host "Disabling capturing..."
    & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCmd.exe" /globaloff

    #shut down the profiler
    Write-Host "Shutting down profiler. This may take some time..." 

    #shut down IIS so the /shutdown command works
    IISReset t80w103 /noforce
    IISReset t80w103 /status
    & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCmd.exe" /shutdown
    & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCLREnv.cmd" /off /globaloff

    #generate report summary
    $date = Get-Date -format "yyyy-dd-M--HH-mm-ss"
    $summaryReportLocation = "$logLocation\API $date"
    & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\VSPerfReport.exe" "$logLocation\Api.vsp" /SummaryFile /Output:"$summaryReportLocation"

    #move items to shared location
    $reportFolder = "\\shareDrive\API\Performance Reports\$date"
    $profilerReport = get-childitem "$summaryReportLocation.vsps"
    New-Item $reportFolder -type directory
    Copy-Item $profilerReport.FullName  $reportFolder

    #log success
    $logDate = Get-Date -format "yyyy-dd-mm HH-mm-ss"
    $output = "[$logDate]" + [System.Environment]::NewLine + "Completed successfully."
    $output | out-file "profiler-log.log" -append

    Write-Host "Completed successfully."
}
catch{
    #log error
    Write-Host $_
    $logDate = Get-Date -format "yyyy-dd-mm HH-mm-ss"
    $output = "[$logDate]" + [System.Environment]::NewLine + $_ + [System.Environment]::NewLine
    $output | out-file "profiler-log.log" -append
}
finally{
    Write-Output "Done"
}

As I said, the above works fine if I run it manually on DEV myself but I have tried to trigger it and it doesn't work right.

Enter-PSSession DEV
Invoke-Command -ComputerName DEV -FilePath "C:\PerformanceTest\profile-tracing-SoapUI.ps1"
Exit-PSSession

2. The Investigation So Far

The above does seem to trigger the script but I ran into some weird issues. First, the script is called on the machine I execute the script on (mine for testing, TFS Build Server for the auto-deploy) not on DEV as I would expect. This is likely my misunderstanding of powershell and an easy enough fix - all this means is, unless I copy the script over to the network machine I am testing from (either my own or the TFS Build Server) powershell just barfs a directory not found error before even hitting the script. Second, even if I have the script in place on the machine I'm trying to trigger it from (which does find the script and start the execution) it only ever gets to the output "Starting the trace..." followed by some information about vsperfcmd.

Starting the trace...
Microsoft (R) VSPerf Command Version 12.0.30723 x64
Copyright (C) Microsoft Corp. All rights reserved.


Global logging control
------------------------------------------------------------
Setting global profile state to OFF.

It hangs there and I assume the call is not fully executed as I have to break out of it. I have left it running for a significant period of time (20+ minutes, locally it takes seconds to move past this point) but it has never continued past this point. Running locally the output for the script at that location looks like:

Starting the trace...
Microsoft (R) VSPerf Command Version 12.0.30723 x64
Copyright (C) Microsoft Corp. All rights reserved.


Global logging control
------------------------------------------------------------
Setting global profile state to OFF.

Resetting IIS...

3. The Problem

This leads me to believe that the problem line is

& "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCmd.exe" /start:Trace /output:$logLocation"\API.vsp" /cs /User:Everyone /globaloff

And indeed when I run a much shortened script to test this hypothesis I was able to verify that control is never returned to the shell after executing that command - below is the script I ran to confirm this AND its output:

Enter-PSSession t80w103
Invoke-Command -ComputerName t80w103 -ScriptBlock{
    try{
        & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCmd.exe" /start:Trace /output:$logLocation"\API.vsp" /cs /User:Everyone /globaloff
        Write-Host "No Error and Control Returned"
    }
    catch{
        Write-Host "Error!"
    }
    finally{
        Write-Output "Done.."
    }
}
Exit-PSSession

OUTPUT:
Microsoft (R) VSPerf Command Version 12.0.30723 x64
Copyright (C) Microsoft Corp. All rights reserved.


Global logging control
------------------------------------------------------------
Setting global profile state to OFF.

Nothing is ever printed after that command. For a while I thought this must mean that something was wrong with the application or DEV server that was preventing it from accessing vsperfcmd properly but I checked on the DEV task manager and was able to find that VSPerfMon.exe does appear in the process list when I run the command and stops when I ctrl+break out of it. So it seems the command is working, at least in part, it just doesn't return control so that the next part of the script can be executed.

So, my question is, how can I get this to work? Why doesn't control return after the command to start the profile monitor is executed? And is this the best way to do performance profiling after auto-deploying a build from TFS? (see below for updates)

4. Additional Investigation

I have continued to investigate this on my own since posting and have learned some interesting things. First, I should note that the version of powershell on the DEV server was out of date (which I didn't realize) and so I updated it to version 3. Once I tried to run the script locally on powershellV3 in the powershell ISE I realized that it was hanging in the exact same way as when I tried to run the script remotely. Only when I run the script via the right click command "run with powershell" does the script work which I realize invokes powershellV1. There seems to be distinct difference in how different versions of powershell are handling my script.

Revised questions: Why does the script work in powershellV1 but not V3? Why does V3 hang after the \start:trace while V1 doesn't? And how do I get a networked execution to run the script using V1 when powershell sessions weren't introduced until V2?

Answer 1

Answering the revised question allowed me to solve this issue. It turns out (although I don't know WHY since I can't see the source code) that VSPerfCMD.exe does not return control to the shell in versions of Powershell after V1 when it is started. This means that calling

VSPerfCmd.exe /Start

must be done in a separate shell or the script will hang. Control is only returned once another shell calls the shutdown command. To solve this problem I use the following code to start the profiler and then wait my script until it is running before proceeding:

Write-Host "Starting the trace..."

#start:Trace - in tracing mode so we get timing data
#output - the output vsp file
#cs - cross session mode because we are profiling an IIS session
#user - give permissions to profile to everyone
#globaloff - start with capturing off so we don't get start up data. > is this the problem?

start powershell -ArgumentList "-ExecutionPolicy Bypass -command & 'C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCmd.exe' /start:Trace /output:$logLocation\CatalogAPI.vsp /cs /User:Everyone /GlobalOff"

#wait for VSPerfCmd to start up
Write-Host "Waiting 15s for VSPerfCmd to start up..."
Start-Sleep -s 15

$counter = 0
while($counter -lt 6)
{
    $e = & "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCmd.exe" /status
    if ($LASTEXITCODE -eq 0){
        Write-Host $e
        break       
    }

    if ($LASTEXITCODE -eq 1 -and $counter -lt 5){
        Write-Host "Still waiting. Give it 10s more ($counter)..."
        Start-Sleep -s 10
        $counter++
        continue
    }

    throw "VSPerfCmd Error: $e"                 
}

Using the above code in place of the original trace start in the initial script should allow you to run automatic performance profiling with a powershell script but I cannot guarantee results as the script has changed a bit since I originally posted this (due to various investigation and code improvement). To get it working just use the above in place of

#enable capturing
Write-Host "Enabling capturing..."
& "C:\Program Files (x86)\Microsoft Visual Studio 12.0\Team Tools\Performance Tools\x64\VSPerfCmd.exe" /globalon

tl;dr VSPerfCmd.exe /Start does not return control to the shell that called the command until the profiling service is stopped in versions of powershell after powershell v1. If you wish to automate performance profiling you will need to start the performance profiler in another shell and then wait until the profiler status indicates it is active before proceeding.