Multithreading with runspaces: Method calls cause unexpected behavior

Question

Following the articles Concurrency in PowerShell: Multi-threading with Runspaces and Multithreading PowerShell Scripts, I've been experimenting with multithreading using runspaces, and noticed some behavior that I don't understand.

In the script below, the script block $compute_block simulates an expensive computation by sleeping for a second before returning. Ten threads with this computation are spawned, after which the script waits for all of them to complete and prints the results.

The script can be run with either -Case 1 or -Case 2. In case 1, AddScript is called directly with $compute_block. In case 2, an object is created with a method equivalent to $compute_block, and AddScript is given a script block that calls this method.

threading.ps1

Param([Int] $Case)

Set-StrictMode -Version 2

$start_date = Get-Date

Function Get-Timestamp() {
    Return ("{0:N3}" -f ((Get-Date) - $start_date).TotalSeconds)
}

Function Write-Timed([String] $str) {
    Write-Host "[$(Get-Timestamp)] $str"
}

$count = 10

$runspace_pool = [RunspaceFactory]::CreateRunspacePool(1, $count)
$runspace_pool.Open()

$compute_block = {
    Param($x)
    Start-Sleep 1
    Return $x
}

# Spawn jobs
$jobs = @()
ForEach($i In 0..($count-1)) {
    Write-Timed "Creating job #$i"
    $ps = [PowerShell]::Create()
    Switch($Case) {
        1 {
            $job = $ps.AddScript($compute_block).AddArgument($i)
        }

        2 {
            $object = New-Object PSObject `
                | Add-Member ScriptMethod Compute $compute_block -PassThru

            $job = $ps.AddScript({
                Param($o, $x)
                Return $o.Compute($x)
            }).AddArgument($object).AddArgument($i)
        }
    }
    $job.RunspacePool = $runspace_pool

    Write-Timed "Starting job #$i"
    $result = $job.BeginInvoke()

    Write-Timed "Creating record for job #$i"
    $record = New-Object PSObject -Property @{
        "Job" = $job;
        "Result" = $result;
    }

    Write-Timed "Adding record for job #$i to list"
    $jobs += $record
}

# Wait for all jobs to complete
While($true) {
    $running_count = @($jobs | Where-Object { -not $_.Result.IsCompleted }).Count
    Write-Timed "Waiting for $running_count/$count jobs"
    If(0 -eq $running_count) {
        Break
    }
    Start-Sleep 1
}

# Print results
$i = 0
ForEach($job In $jobs) {
    $result = $job.Job.EndInvoke($job.Result)
    $job.Job.Dispose()
    Write-Timed "Job #$i result: $result"
    $i++
}

$runspace_pool.Close()

The results are very different (note the timestamps):

Case 1

PS C:\Users\Miranda\Documents> .\threading.ps1 -Case 1
[0.050] Creating job #0
[0.051] Starting job #0
[0.052] Creating record for job #0
[0.052] Adding record for job #0 to list
[0.053] Creating job #1
[0.053] Starting job #1
[0.056] Creating record for job #1
[0.057] Adding record for job #1 to list
[0.057] Creating job #2
[0.058] Starting job #2
[0.061] Creating record for job #2
[0.062] Adding record for job #2 to list
[0.062] Creating job #3
[0.063] Starting job #3
[0.066] Creating record for job #3
[0.066] Adding record for job #3 to list
[0.067] Creating job #4
[0.067] Starting job #4
[0.070] Creating record for job #4
[0.071] Adding record for job #4 to list
[0.071] Creating job #5
[0.072] Starting job #5
[0.075] Creating record for job #5
[0.076] Adding record for job #5 to list
[0.076] Creating job #6
[0.077] Starting job #6
[0.080] Creating record for job #6
[0.080] Adding record for job #6 to list
[0.081] Creating job #7
[0.081] Starting job #7
[0.084] Creating record for job #7
[0.085] Adding record for job #7 to list
[0.085] Creating job #8
[0.086] Starting job #8
[0.102] Creating record for job #8
[0.103] Adding record for job #8 to list
[0.104] Creating job #9
[0.104] Starting job #9
[0.114] Creating record for job #9
[0.115] Adding record for job #9 to list
[0.119] Waiting for 10/10 jobs
[1.120] Waiting for 0/10 jobs
[1.121] Job #0 result: 0
[1.122] Job #1 result: 1
[1.122] Job #2 result: 2
[1.123] Job #3 result: 3
[1.124] Job #4 result: 4
[1.124] Job #5 result: 5
[1.124] Job #6 result: 6
[1.125] Job #7 result: 7
[1.125] Job #8 result: 8
[1.126] Job #9 result: 9

Case 2

PS C:\Users\Miranda\Documents> .\threading.ps1 -Case 2
[0.080] Creating job #0
[0.117] Starting job #0
[0.120] Creating record for job #0
[0.121] Adding record for job #0 to list
[1.126] Creating job #1
[1.128] Starting job #1
[1.129] Creating record for job #1
[2.130] Adding record for job #1 to list
[2.130] Creating job #2
[2.132] Starting job #2
[2.132] Creating record for job #2
[3.134] Adding record for job #2 to list
[3.135] Creating job #3
[3.136] Starting job #3
[3.137] Creating record for job #3
[4.137] Adding record for job #3 to list
[4.138] Creating job #4
[4.139] Starting job #4
[4.140] Creating record for job #4
[5.141] Adding record for job #4 to list
[5.142] Creating job #5
[5.143] Starting job #5
[5.144] Creating record for job #5
[6.144] Adding record for job #5 to list
[6.145] Creating job #6
[6.146] Starting job #6
[6.147] Creating record for job #6
[7.148] Adding record for job #6 to list
[7.149] Creating job #7
[7.150] Starting job #7
[7.151] Creating record for job #7
[8.152] Adding record for job #7 to list
[8.153] Creating job #8
[8.166] Starting job #8
[8.167] Creating record for job #8
[9.168] Adding record for job #8 to list
[9.169] Creating job #9
[9.170] Starting job #9
[9.171] Creating record for job #9
[10.172] Adding record for job #9 to list
[10.192] Waiting for 0/10 jobs
[10.206] Job #0 result: 0
[10.208] Job #1 result: 1
[10.209] Job #2 result: 2
[10.209] Job #3 result: 3
[10.209] Job #4 result: 4
[10.210] Job #5 result: 5
[10.211] Job #6 result: 6
[10.211] Job #7 result: 7
[10.212] Job #8 result: 8
[10.212] Job #9 result: 9

Case 1 behaves as I would expect — the threads are spawned instantaneously, and the script spends a second in the wait loop before finishing.

However, in case 2, all concurrency seems to be lost. Each iteration of the spawning loop blocks until the spawned thread finishes, and once the wait loop is reached, there's nothing left to wait for. Why is this happening?

Edit:

For the record, I'm working with PS 3.0. As noted by Roman Kuzmin, running case 2 in PS 2.0 produces some very strange errors:

PS>.\threading.ps1 -Case 2
[0.060] Creating job #0
[0.060] Starting job #0
The '=' operator failed: Index was outside the bounds of the array..
At C:\Users\Miranda\Documents\threading.ps1:50 char:14
+     $result = <<<<  $job.BeginInvoke()
    + CategoryInfo          : InvalidOperation: (System.Manageme...hellAsyncResult:PowerShellAsyncResult) [], RuntimeE
   xception
    + FullyQualifiedErrorId : OperatorFailed

C:\Users\Miranda\Documents\threading.ps1 : Index was outside the bounds of the array.
At line:1 char:16
+ .\threading.ps1 <<<<  -Case 2
    + CategoryInfo          : NotSpecified: (:) [threading.ps1], IndexOutOfRangeException
    + FullyQualifiedErrorId : System.IndexOutOfRangeException,threading.ps1

Answer 1

I cannot tell exactly why PowerShell works so but I can tell what causes the problem and how to work around it. In the case 2 the script block $compute_block is used as the script method in 10 objects/runspaces - this is the culprit. If we make and use cloned script blocks, i.e.

$compute_block2 = [scriptblock]::Create($compute_block)
$object = New-Object PSObject `
    | Add-Member ScriptMethod Compute $compute_block2 -PassThru

then the problem is resolved.

Interestingly, in PowerShell v2 the original script (case 2) does not work at all, it fails with some weird error messages. With a fix it works in v2, as well as in v3. It looks like you hit a problem case to be avoided. I do not remember such a thing documented. It may be a bug or a feature.