none
Start-Job ... was braucht da so lange? RRS feed

  • Frage

  • Moin!

    Ich habe ein Script, das ein anders Script 10 mal startet, dann auf wartet, dass alle 10 Jobs beendet sind, um danach deren Ausgabe anzuzeigen. Was ich nicht verstehe, ist, warum das so lange dauert.

    Hier das äußere Script (c:\ps\tst.ps1):

    $Logfile="C:\ps\tst.log"
    ##############################################################
    # Schreibt "LogData" mit vorangestelltem Timestamp in die
    # Logdatei (gemäß $Logfile).
    Function LogWrite($LogData)  {
        $LogTime=Get-Date -Format "yyyy-dd-MM HH:mm:ss"
        $LogMsg=$LogTime + " " + $LogData
        Add-content $Logfile -Value $LogMsg
    }
    
    $jobs=@()
    for($i=0; $i -lt 10; $i++) {
        $jobs+=Start-Job -Name ("job{0}" -f $i)  -filepath C:\ps\sub.ps1 -ArgumentList @("job", $i)
        LogWrite ("Job{0} gestartet" -f $i)
    }
    
    "warten, bis alle fertig"
    do {
        Start-Sleep -Milliseconds 200
        $stillRunning=$false
        foreach($jobstate in $jobs.State) {
            if($jobstate -eq "Running") {
                $stillRunning=$true
                break
            }
        }
    } while($stillRunning)
    "alle sind fertig"
    
    foreach($job in $jobs) {
        receive-job -job $job
    }
    
    Get-Job | Remove-Job
    

    Und das innere (c:\ps\sub.ps1):

    param([string]$nam, [string]$nr)
    
    $Logfile="C:\ps\sub.log"
    ##############################################################
    # Schreibt "LogData" mit vorangestelltem Timestamp in die
    # Logdatei (gemäß $Logfile).
    Function LogWrite($LogData)  {
        $LogTime=Get-Date -Format "yyyy-dd-MM HH:mm:ss"
        $LogMsg=$LogTime + " " + $LogData
        Add-content $Logfile -Value $LogMsg
    }
    
    LogWrite "nam=", $nam, "nr=", $nr
    
    $r=Get-Random -Minimum 0 -Maximum 5000
    Start-Sleep -Milliseconds $r
    
    LogWrite "nam=", $nam, "nr=", $nr, "rand=", $r
    Write-Host "nam=", $nam, "nr=", $nr, "rand=", $r
    
    exit 0
    

    Wenn ich .\tst.ps1 laufen lasse, gibts folgende Ausgabe:

    PS C:\ps> .\tst.ps1
    warten, bis alle fertig
    alle sind fertig
    nam= job nr= 0 rand= 2817
    nam= job nr= 1 rand= 3766
    nam= job nr= 2 rand= 2512
    nam= job nr= 3 rand= 4742
    nam= job nr= 4 rand= 282
    nam= job nr= 5 rand= 1258
    nam= job nr= 6 rand= 3766
    nam= job nr= 7 rand= 1536
    nam= job nr= 8 rand= 4306
    Stream was not readable.
        + CategoryInfo          : InvalidArgument: (C:\ps\sub.log:String) [Add-Content], ArgumentException
        + FullyQualifiedErrorId : GetContentWriterArgumentError,Microsoft.PowerShell.Commands.AddContentCommand
        + PSComputerName        : localhost
    
    nam= job nr= 9 rand= 282
    PS C:\ps>
    

    Die Logdatei tst.log hat diesen (durchaus akzeptablen) Inhalt:

    2016-11-02 17:35:55 Job0 gestartet
    2016-11-02 17:35:55 Job1 gestartet
    2016-11-02 17:35:55 Job2 gestartet
    2016-11-02 17:35:55 Job3 gestartet
    2016-11-02 17:35:55 Job4 gestartet
    2016-11-02 17:35:56 Job5 gestartet
    2016-11-02 17:35:56 Job6 gestartet
    2016-11-02 17:35:56 Job7 gestartet
    2016-11-02 17:35:56 Job8 gestartet
    2016-11-02 17:35:56 Job9 gestartet
    

    Aber sub.log diesen:

    2016-11-02 17:36:14 nam= job nr= 0
    2016-11-02 17:36:17 nam= job nr= 0 rand= 2817
    2016-11-02 17:36:22 nam= job nr= 1
    2016-11-02 17:36:22 nam= job nr= 6
    2016-11-02 17:36:22 nam= job nr= 3
    2016-11-02 17:36:22 nam= job nr= 7
    2016-11-02 17:36:22 nam= job nr= 2
    2016-11-02 17:36:22 nam= job nr= 8
    2016-11-02 17:36:22 nam= job nr= 4
    2016-11-02 17:36:22 nam= job nr= 9
    2016-11-02 17:36:22 nam= job nr= 5
    2016-11-02 17:36:22 nam= job nr= 4 rand= 282
    2016-11-02 17:36:23 nam= job nr= 5 rand= 1258
    2016-11-02 17:36:23 nam= job nr= 7 rand= 1536
    2016-11-02 17:36:24 nam= job nr= 2 rand= 2512
    2016-11-02 17:36:25 nam= job nr= 1 rand= 3766
    2016-11-02 17:36:25 nam= job nr= 6 rand= 3766
    2016-11-02 17:36:26 nam= job nr= 8 rand= 4306
    2016-11-02 17:36:26 nam= job nr= 3 rand= 4742
    

    1.) warum, verdammt nochmal, dauert es nach Start des letzten Jobs um 17:35:56 bis 17:36:14, bevor der erste Logeintrag von sub.ps1 geschrieben wird?

    2.) in sub.ps1 wird maximal fünf Sekunden gewartet - warum liegen die Logeinträge aber zwischen 17:36:14 und 17:36:26?

    Selbst wenn ich sämtliches Log-Schreiben auskommentiere, läuft das Script immer noch ca. 20 Sekunden. Kann also nicht [nur] daran liegen, das ein Job die Logdatei mit seinem Schreibzugriff sperrt. BTW: der "Add-content" schließt die Logdatei doch wohl hoffentlich unmittelbar nachdem reingeschrieben hat !?

    Ich verstehe es nicht.... :-(

    Vielen Dank im voraus für Tipps, wie man erreicht, dass .\tst.ps1 nach maximal sechs Sekunden fertig ist.

    Donnerstag, 11. Februar 2016 17:05

Antworten

  • Moin,

    ich kan leider auch nicht sagen, warum das Starten, Warten udn Einsammeln der Jobs so lange dauert. Bei mir zeigt sich das gleiche verhalten wie ebi dir. Was wie lange dauert, hab ich mal mitgeloggt und in Excel dargestellt (zwei Durchläufe):

    Da deine Jobs nun wirklich keine Aufwendigen Dinge tun, kann ich mir das nur damit erklären, dass Powershell die Jobs einfach nicht sehr effizient verwaltet. Dieses Problem gibt es wohl schon sehr lange. Nicht umsonst haben viele schlaue Powershell Kollegen sich Dinge wie z.B. Invoke-Parallel ausgedacht, welches parallele Verarbeitung besser handhabt. Hier dein Script mit Invoke-Parallel:

    tst.ps1

    . 'C:\ps\Invoke-Parallel.ps1'
    
    $a = 1..10 | Invoke-Parallel -LogFile C:\ps\tst.log -ScriptBlock {
        C:\ps\sub.ps1 -nam job -nr $_
    }
    $a | Out-File C:\ps\sub.log


    sub-ps1

    param([string]$nam, [int]$nr)
    
    $r=Get-Random -Minimum 0 -Maximum 5000
    Start-Sleep -Milliseconds $r
    
    "nam= $nam nr= $nr rand= $r"
    
    exit 0

    Laufzeit bei mir ca 5,5 Sekunden.

    Achja, mit mehreren Threads in eine Datei schreiben, wird immer zu Problemen führen, selbst mit Add-Content. Darum erst alles Jobs laufen lassen und später das Ergebnis einsammeln.

    Gruß



    • Bearbeitet psott Freitag, 12. Februar 2016 10:46
    • Als Antwort markiert dahlgrimm Freitag, 12. Februar 2016 12:42
    Freitag, 12. Februar 2016 10:44

Alle Antworten

  • Moin,

    ich kan leider auch nicht sagen, warum das Starten, Warten udn Einsammeln der Jobs so lange dauert. Bei mir zeigt sich das gleiche verhalten wie ebi dir. Was wie lange dauert, hab ich mal mitgeloggt und in Excel dargestellt (zwei Durchläufe):

    Da deine Jobs nun wirklich keine Aufwendigen Dinge tun, kann ich mir das nur damit erklären, dass Powershell die Jobs einfach nicht sehr effizient verwaltet. Dieses Problem gibt es wohl schon sehr lange. Nicht umsonst haben viele schlaue Powershell Kollegen sich Dinge wie z.B. Invoke-Parallel ausgedacht, welches parallele Verarbeitung besser handhabt. Hier dein Script mit Invoke-Parallel:

    tst.ps1

    . 'C:\ps\Invoke-Parallel.ps1'
    
    $a = 1..10 | Invoke-Parallel -LogFile C:\ps\tst.log -ScriptBlock {
        C:\ps\sub.ps1 -nam job -nr $_
    }
    $a | Out-File C:\ps\sub.log


    sub-ps1

    param([string]$nam, [int]$nr)
    
    $r=Get-Random -Minimum 0 -Maximum 5000
    Start-Sleep -Milliseconds $r
    
    "nam= $nam nr= $nr rand= $r"
    
    exit 0

    Laufzeit bei mir ca 5,5 Sekunden.

    Achja, mit mehreren Threads in eine Datei schreiben, wird immer zu Problemen führen, selbst mit Add-Content. Darum erst alles Jobs laufen lassen und später das Ergebnis einsammeln.

    Gruß



    • Bearbeitet psott Freitag, 12. Februar 2016 10:46
    • Als Antwort markiert dahlgrimm Freitag, 12. Februar 2016 12:42
    Freitag, 12. Februar 2016 10:44
  • Danke!

    Ich werde dieses Invoke-Parallel mal testen...hat ja praktischerweise eine MIT-Lizenz und liegt als Powershell-Script vor...womit die Chancen gut stehen, dass mein Kunde nix gegen dessen Einsatz hat.

    Freitag, 12. Februar 2016 12:50