Slow updates to my event handler from DownloadFileAsync during DownloadProgressChanged event

Question

My Problem

I'm writing a PowerShell script that will need to download several large files from a remote web server before carrying on with other tasks. One of my project requirements is to show the progress of each download so the end-user knows what's going on.

A response to another SO question contained a solution which uses registered events and Net.WebClient.DownloadFileAsync. However, when I try the solution in the accepted answer, the download is completing long before my script has handled all of the DownloadProgressChanged events.

What I've Tried

I've created a test script which I've provided below in order to reproduce the problem and attempt to isolate where it's occurring. At first I thought the problem was with the Write-Progress cmdlet being slow, so I replaced it with Write-Host to show the percentage completed. This produced many repeated lines with the same percentage value. Thinking that Write-Host might also be slow, I changed the event handler's action to only output the percentage when it changed. This didn't make a difference.

I noticed in the output that the download was completing before the event handler indicated that it was more than a few percent complete. There was a large delay during the first few percent, then it sped up. But the output of percentage complete was still slow even after the download completed. I made another modification to the script to show the time elapsed at each percentage change.

My environment is Windows 7 and Server 2008 using PowerShell 2.0. I've tried the script on both OS's with the same results. I'm not using a PS profile and the Server 2008 computer is a fresh install.

Here is my test script.

# based on https://stackoverflow.com/a/4927295/588006
$client = New-Object System.Net.WebClient
$url=[uri]"https://www.kernel.org/pub/linux/kernel/v2.6/linux-2.6.18.tar.bz2"
$file="$env:USERPROFILE\Downloads\linux-2.6.18.tar.bz2"

try {
    Register-ObjectEvent $client DownloadProgressChanged -action {     
        if ( $eventargs.ProgressPercentage -gt $percent ) {
            $percent = $eventargs.ProgressPercentage
            if ( $start_time -eq $null ) {
                $start_time = $(get-date)
            }
            # Get the elapsed time since we displayed the last percentage change
            $elapsed_time = new-timespan $start_time $(get-date)
            write-host "Percent complete:" $eventargs.ProgressPercentage "($elapsed_time)"
        }
    }

    Register-ObjectEvent $client DownloadFileCompleted -SourceIdentifier Finished

    $client.DownloadFileAsync($url, $file)

    # optionally wait, but you can break out and it will still write progress
    Wait-Event -SourceIdentifier Finished

} finally {
    write-host "File download completed"
    $client.dispose()
    Unregister-Event -SourceIdentifier Finished
    Remove-Event -SourceIdentifier Finished
}

The script produces the following output.

PS C:\Users\devtest\Desktop> .\write-progress-speed.ps1

Id              Name            State      HasMoreData     Location             Command
--              ----            -----      -----------     --------             -------
1               7989b3fe-cce... NotStarted False                                     ...
Percent complete: 0 (00:00:00)
Percent complete: 1 (00:00:09.2435931)

ComputerName     :
RunspaceId       : 6c207bde-bb4a-442b-a7bd-05a9c12fae95
EventIdentifier  : 9978
Sender           : System.Net.WebClient
SourceEventArgs  : System.ComponentModel.AsyncCompletedEventArgs
SourceArgs       : {System.Net.WebClient, System.ComponentModel.AsyncCompletedEventArgs}
SourceIdentifier : Finished
TimeGenerated    : 8/9/2013 8:02:59 AM
MessageData      :

File download completed


Percent complete: 2 (00:00:12.2896000)
PS C:\Users\devtest\Desktop> Percent complete: 3 (00:00:12.6756120)
Percent complete: 4 (00:00:13.0646281)
Percent complete: 5 (00:00:13.2796284)
Percent complete: 6 (00:00:13.4656313)
Percent complete: 7 (00:00:13.6106315)
Percent complete: 8 (00:00:13.7756318)
Percent complete: 9 (00:00:13.9656320)
Percent complete: 10 (00:00:14.1306323)
Percent complete: 11 (00:00:14.2406324)
Percent complete: 12 (00:00:14.3706326)
Percent complete: 13 (00:00:14.5006328)
Percent complete: 14 (00:00:14.6556330)
Percent complete: 15 (00:00:14.7806332)
Percent complete: 16 (00:00:14.9006333)
Percent complete: 17 (00:00:15.0156335)
Percent complete: 18 (00:00:15.1406337)
Percent complete: 19 (00:00:15.2556338)
Percent complete: 20 (00:00:15.3656340)
Percent complete: 21 (00:00:15.4756342)
Percent complete: 22 (00:00:15.5856343)
Percent complete: 23 (00:00:15.6706344)
Percent complete: 24 (00:00:15.7906346)
Percent complete: 25 (00:00:15.9056348)
Percent complete: 26 (00:00:16.0156349)
Percent complete: 27 (00:00:16.1206351)
Percent complete: 28 (00:00:16.2056352)
Percent complete: 29 (00:00:16.3006353)
Percent complete: 30 (00:00:16.4006354)
Percent complete: 31 (00:00:16.5106356)
Percent complete: 32 (00:00:16.6206358)
Percent complete: 33 (00:00:16.7356359)
Percent complete: 34 (00:00:16.8256360)
Percent complete: 35 (00:00:16.9156362)
Percent complete: 36 (00:00:17.0306363)
Percent complete: 37 (00:00:17.1506365)
Percent complete: 38 (00:00:17.2606367)
Percent complete: 39 (00:00:17.3756368)
Percent complete: 40 (00:00:17.5856371)
Percent complete: 41 (00:00:17.7356373)
Percent complete: 42 (00:00:17.9056376)
Percent complete: 43 (00:00:18.0256377)
Percent complete: 44 (00:00:18.1366405)
Percent complete: 45 (00:00:18.2216406)
Percent complete: 46 (00:00:18.3216408)
Percent complete: 47 (00:00:18.4166409)
Percent complete: 48 (00:00:18.5066410)
Percent complete: 49 (00:00:18.6116412)
Percent complete: 50 (00:00:18.7166413)
Percent complete: 51 (00:00:18.8266415)
Percent complete: 52 (00:00:18.9316416)
Percent complete: 53 (00:00:19.0716418)
Percent complete: 54 (00:00:19.1966420)
Percent complete: 55 (00:00:19.2966421)
Percent complete: 56 (00:00:19.3766423)
Percent complete: 57 (00:00:19.4616424)
Percent complete: 58 (00:00:19.5441441)
Percent complete: 59 (00:00:19.6426453)
Percent complete: 60 (00:00:19.7526454)
Percent complete: 61 (00:00:19.8476455)
Percent complete: 62 (00:00:19.9226457)
Percent complete: 63 (00:00:20.0026458)
Percent complete: 64 (00:00:20.0676459)
Percent complete: 65 (00:00:20.1626460)
Percent complete: 66 (00:00:20.2626461)
Percent complete: 67 (00:00:20.3626463)
Percent complete: 68 (00:00:20.4576464)
Percent complete: 69 (00:00:20.5676466)
Percent complete: 70 (00:00:20.6826467)
Percent complete: 71 (00:00:20.7776468)
Percent complete: 72 (00:00:20.8626470)
Percent complete: 73 (00:00:20.9526471)
Percent complete: 74 (00:00:21.0326472)
Percent complete: 75 (00:00:21.1076473)
Percent complete: 76 (00:00:21.1976474)
Percent complete: 77 (00:00:21.2776475)
Percent complete: 78 (00:00:21.3626477)
Percent complete: 79 (00:00:21.4476478)
Percent complete: 80 (00:00:21.5276479)
Percent complete: 81 (00:00:21.6076480)
Percent complete: 82 (00:00:21.6876481)
Percent complete: 83 (00:00:21.7726482)
Percent complete: 84 (00:00:21.8226483)
Percent complete: 85 (00:00:21.8876484)
Percent complete: 86 (00:00:21.9876485)
Percent complete: 87 (00:00:22.0626486)
Percent complete: 88 (00:00:22.1226487)
Percent complete: 89 (00:00:22.1876488)
Percent complete: 90 (00:00:22.2626489)
Percent complete: 91 (00:00:22.3026490)
Percent complete: 92 (00:00:22.3726491)
Percent complete: 93 (00:00:22.4376492)
Percent complete: 94 (00:00:22.4926493)
Percent complete: 95 (00:00:22.5676494)
Percent complete: 96 (00:00:22.6126494)
Percent complete: 97 (00:00:22.6926495)
Percent complete: 98 (00:00:22.7776496)
Percent complete: 99 (00:00:22.8426497)
Percent complete: 100 (00:00:22.9176498)

Does anyone have any recommendations on how I can fix this problem or further investigate what is causing it?

Answer 1

Async eventing is rather poorly supported in Powershell. When events are fired they go into some Powershell event queue, which is then fed to handlers as they become available. I've seen various performance or functionality issues with this before, where it seems the handlers need to wait for the console to become idle before they are executed. See this question for an example.

From what I can tell, your code is set up well and "should" work. I think it's slow just because powershell doesn't support this kind of pattern very well.

Here's a workaround which reverts to plain .NET C# code to handle all the event stuff, which avoids the Powershell event queue entirely.

# helper for handling events
Add-Type -TypeDef @"
  using System;
  using System.Text;
  using System.Net;
  using System.IO;

  public class Downloader
  {
      private Uri source;
      private string destination;
      private string log;
      private object syncRoot = new object();
      private int percent = 0;

      public Downloader(string source, string destination, string log)
      {
          this.source = new Uri(source);
          this.destination = destination;
          this.log = log;
      }

      public void Download()
      {
          WebClient wc = new WebClient();
          wc.DownloadProgressChanged += new DownloadProgressChangedEventHandler(OnProgressChanged);
          wc.DownloadFileAsync(source, destination);
      }

      private void OnProgressChanged(object sender, DownloadProgressChangedEventArgs e)
      {
          lock (this.syncRoot)
          {
              if (e.ProgressPercentage > this.percent)
              {
                  this.percent = e.ProgressPercentage;
                  string message = String.Format("{0}: {1} percent", DateTime.Now, this.percent);
                  File.AppendAllLines(this.log, new string[1] { message }, Encoding.ASCII);
              }
          }
      }
  }
"@


$source = 'https://www.kernel.org/pub/linux/kernel/v2.6/linux-2.6.18.tar.bz2'
$dest = "$env:USERPROFILE\Downloads\linux-2.6.18.tar.bz2"
$log = [io.path]::GetTempFileName()

$downloader = new-object Downloader $source,$dest,$log
$downloader.Download();

gc $log -tail 1 -wait `
 |?{ $_ -match ': (\d+) percent' } `
 |%{ 
     $percent = [int]$matches[1]
     if($percent -lt 100)
     {
         Write-Progress -Activity "Downloading $source" -Status "${percent}% complete" -PercentComplete $percent
     }
     else{ break }
 }