Windows Backup Performance Testing with PowerShell

While developing our new Windows file services infrastructure, we wanted to test our pre-production platform to see if there are any file server-side bottlenecks that will cause unacceptable delays in backup processing. Here are UVM we still are using EMC Networker for Enterprise backup (no comments on our satisfaction with EMC will be provided at this time). EMC provides a tool “uasm.exe” that is used at the core of the “save.exe” and “recover.exe” commands on the backup client. If we use “uasm.exe” to backup all of the file server data to “null”, it is possible that we will be able to detect disk, HBA, and other local I/O bottlenecks before they bite us in production.

Since Networker will break up our file server into multiple “save sets”, and run a user-definable number of save set backup processes in parallel, it also is important for us to determine the required number of parallel backup processes required to complete backup in a timely fashion. Thus, we want to run several parallel “uasm.exe” processes in our tests.

PowerShell, with the assistance of “cmd.exe”, and some finesses, can get this job done. Hurdles I ran into while scripting this test follow:

  1. During development, PowerShell consumed huge amounts of CPU while redirecting uasm.exe output to the PowerShell $null object. Interestingly, previous tests using uasm.exe with cmd.exe did not show this problem. To fix this, each uasm job is spawned from a one-line cmd.exe “bat” script, which is included below.
  2. Remember that PowerShell uses the null object “$null”, but that cmd.exe uses the handle “nul” (with one “L”). If you redirect to “null”, you will soon fill up your disk with a file named “null”.
  3. When wanted to examine running jobs, it was difficult to determine which directory a jobs was working on. This was because I initially created a scriptblock object and passed parameters to it when starting a job. For example:
    [scriptblock] $sb = {
    $uasmBlock = {
    	param ([string]$sPath)
    	[string[]] $argList = '/c','c:\local\scripts\uasm_cmd.bat',$sPath
    	& cmd.exe $argList
    $jobs += start-job -Name $myJob -ScriptBlock $sb -ArgumentList $dir1

    However, when inspecting the job object’s “command” property, we see “$sPath” in the output. We want the variable expanded. How to do this? Create the scriptblock object in-line when starting the job:

    [string] $cmd = '& cmd.exe "/c","c:\local\scripts\uasm_cmd.bat",' + $dir
    $jobs += Start-Job -Name $jobName `
    	-ScriptBlock ([scriptblock]::create($cmd))

    This makes for more compact code, too.

  4. To check on jobs that have completed, I create an array named “$djs” (Done Jobs), populated by piping the $jobs array and filtering for “completed” jobs. I inspect $djs to see if jobs are present. In my first pass, I used the check:
    if ($djs.count -gt 0)

    Meaning, continue if there is anything in the array $djs. However, this check did not work well because output from the $jobs object would put a null item in $djs on creation, meaning that if there were no running jobs, $djs would still have a count of one! I fixed this by changing the test:

    if ($djs[0] -ne $null)

    Meaning, if the first entry in $djs is not a null object, then proceed.

The full script follows:

#uasm_jobQueue.ps1, 2011-09-30, author: J. Greg Mackinnon
#Tests performance of disk when accessed by Networker backup commands.
#   Creates a queue of directories to test ($q), then uses external command 
#   "uasm.exe" to backup these directories to null.
#Change the "$wp" variable to set the number of uasm 'worker processes' to be 
#   used during the test.
#Note: PowerShell $null object causes very high CPU utilization when used for
#   this purpose.  Instead, we call "uasm_cmd.bat" which uses the CMD.exe 'nul'
#   re-director.  'nul' does not have the same problems as $null.

set-psdebug -strict

[int] $wp = 4

# Initialize the log file:
[string] $logfile = "s:\uasm_test.log"
remove-item $logfile -Force
[datetime] $startTime = Get-Date
[string] "Start Time: " + $startTime | Out-File $logfile -Append

##Create work queue array:
# Add shared directories:
[String[]] $q = gci S:\shared | ? {$_.Attributes.tostring() -match "Directory"}`
	| sort-object -Property Name | % {$_.FullName}
# Add remaining targets to queue:
$q += 'H:\','I:\','J:\','K:\','L:\','M:\','S:\sis\','S:\software\','s:\r25\'
[int] $dc = 0			#Count of completed (done) jobs.
[int] $qc = $q.Count	#Initial count of jobs in the queue
[int] $qi = 0			#Queue Index - current location in queue
[int] $jc = 0			#Job count - number of running jobs
$jobs = @()				#Jobs array - intended to contain running PS jobs.
while ($dc -lt $qc) { # Completed jobs is less than total jobs in queue
	# Keep running jobs until completed jobs is less than total jobs in queue, 
	#  and our queue count is less than the current queue index.
	while (($jobs.count -lt $wp) -and ($qc -gt $qi)) { 
		[string] $jobName = 'qJob_' + $qi + '_';
		[string] $dir = '"' + $q[$qi] + '"'
		[string] $cmd = '& cmd.exe "/c","c:\local\scripts\uasm_cmd.bat",' + $dir
		#Start the job defined in $cmd string.  Use this rather than a pre-
		#  defined scriptblock object because this allows us to see the expanded
		#  job command string when debugging. (i.e. $jobs[0].command)
		$jobs += Start-Job -Name $jobName `
			-ScriptBlock ([scriptblock]::create($cmd))
		$qi++ #Increment the queue index.
	$djs = @(); #Completed jobs array
	$djs += $jobs | ? {$_.State -eq "Completed"} ;
	# $djs array will always have a count of at least 1.  However, if the 
	#    first entry is not empty (null), then there must be completed jobs to
	#    be retrieved.
	if ($djs[0] -ne $null) { 
		$dc += $djs.count;
		$djs | Receive-Job | Out-File $logfile -Append; #Log completed jobs
		$djs | Remove-Job -Force;
		Remove-Variable djs;
		$jobs = @($jobs | ? {$_.State -eq "Running"}); #rebuild jobs array.
	Start-Sleep -Seconds 3

# Complete logging:
[datetime] $endTime = Get-Date
[string] "End Time: " + $endTime | Out-File $logfile -Append 
$elapsedTime = $endTime - $startTime
[string] $outstr =  "Elapsed Time: " + [math]::floor($elapsedTime.TotalHours)`
	+ " hours, " + $elapsedTime.minutes + " minutes, " + $elapsedTime.seconds`
	+ " seconds."
$outstr | out-file -Append $logfile

The “uasm_cmd.bat” file called in the above code block contains the following one line:

"c:\program files\legato\nsr\bin\uasm.exe" -s %1 > nul