runner-images/images.CI/measure-provisioners-duration.ps1

param(
    [Parameter(Mandatory=$true)]
    [string]$PackerLogPath,
    [string]$PrefixToPathTrim,
    [int]$PrintTopNLongest = 25
)

$DateTimeRegex = "(\d+\/\d+\/\d+ \d+:\d+:\d+)"
$TelemetryLineRegex = "\[INFO\] \(telemetry\)"
$StartProvisionerRegex = "^${DateTimeRegex} ${TelemetryLineRegex} Starting provisioner (.+)$"
$EndProvisionerRegex = "^${DateTimeRegex} ${TelemetryLineRegex} ending (.+)$"
$ShellScriptSubItemRegex = "${DateTimeRegex} ui: ==> .+: Provisioning with \w+ script: (.+)"
$DownloadUploadSubItemRegex = "${DateTimeRegex} ui: ==> .+: (Downloading .+|Uploading .+)"

function Start-ProvisionerItem {
    param([string]$ProvisionerType, [string]$StartTime)

    return @{
        ProvisionerType = $ProvisionerType
        StartTime = [DateTime]::Parse($StartTime)
        SubItems = @()
    }
}

function End-ProvisionerItem {
    param([object]$Provisioner, [string]$EndTime)

    $Provisioner.EndTime = [DateTime]::Parse($EndTime)
    $Provisioner.Duration = New-TimeSpan -Start $Provisioner.StartTime -End $Provisioner.EndTime
}

function Add-ProvisionerSubItem {
    param([object]$Provisioner, [string]$Command, [string]$DateTime)

    $lastItem = $Provisioner.SubItems | Select-Object -Last 1
    if ($lastItem) {
        $lastItem.EndTime = [DateTime]::Parse($DateTime)
        $lastItem.Duration = New-TimeSpan -Start $lastItem.StartTime -End $lastItem.EndTime
    }

    if ($Command) {
        if ($PrefixToPathTrim) { $Command = $Command.Replace($PrefixToPathTrim, ".") }
        $Provisioner.SubItems += @{
            Command = $Command
            StartTime = [DateTime]::Parse($DateTime)
        }
    }
}

function Invoke-TryFindProvisionerSubItem {
    param([object]$Provisioner, [string] $Line)

    if ($Provisioner.ProvisionerType -in "powershell", "shell", "windows-shell") {
        if ($Line -match $ShellScriptSubItemRegex) {
            Add-ProvisionerSubItem -Provisioner $Provisioner -Command $Matches[2] -DateTime $Matches[1]
        }
    } elseif ($Provisioner.ProvisionerType -eq "file") {
        if ($Line -match $DownloadUploadSubItemRegex) {
            Add-ProvisionerSubItem -Provisioner $Provisioner -Command $Matches[2] -DateTime $Matches[1]
        }
    }
}

function Assert-StartProvisioner {
    param([object]$Provisioner, [string]$ProvisionerType)
    if ($null -ne $Provisioner) {
        throw "New provisioner '$ProvisionerType' has been started but previous '$($Provisioner.ProvisionerType)' was not finished yet"
    }
}

function Assert-EndProvisioner {
    param([object]$Provisioner, [string]$ProvisionerType)
    if (($null -ne $Provisioner) -and ($Provisioner.ProvisionerType -ne $ProvisionerType)) {
        throw "Expected end of '$($Provisioner.ProvisionerType)' provisioner but found end of '$ProvisionerType'"
    }
}

$provisionersList = @()
$currentProvisioner = $null

if ((Get-Content $PackerLogPath -Raw) -notmatch $TelemetryLineRegex) {
    throw "Packer log doesn't contain diagnostic information. Env PACKER_LOG must be set to 1"
}
 
Get-Content $PackerLogPath | ForEach-Object {
    if ($_ -match $StartProvisionerRegex) {
        Assert-StartProvisioner -Provisioner $currentProvisioner -ProvisionerType $Matches[2]

        $currentProvisioner = Start-ProvisionerItem -ProvisionerType $Matches[2] -StartTime $Matches[1]
    } elseif (($_ -match $EndProvisionerRegex) -and $currentProvisioner) {
        Assert-EndProvisioner -Provisioner $currentProvisioner -ProvisionerType $Matches[2]

        End-ProvisionerItem -Provisioner $currentProvisioner -EndTime $Matches[1]
        Add-ProvisionerSubItem -Provisioner $currentProvisioner -Command $null -DateTime $Matches[1]
        $provisionersList += $currentProvisioner
        $currentProvisioner = $null
    } elseif ($currentProvisioner) {
        Invoke-TryFindProvisionerSubItem -Provisioner $currentProvisioner -Line $_
    }
}
$totalProvisionersTime = New-TimeSpan
$provisionersList | ForEach-Object { $totalProvisionersTime = $totalProvisionersTime.Add($_.Duration) }

# Print information about provisioners in order of execution
Write-Host "Build timeline:"
$provisionersList | ForEach-Object {
    Write-Host "- $($_.Duration) | $($_.ProvisionerType)"
    $_.SubItems | ForEach-Object {
        Write-Host "      $($_.Duration) | $($_.Command)"
    }
    Write-Host ""
}
Write-Host "Total provisioners time: $totalProvisionersTime"

if ($PrintTopNLongest -gt 0) {
    Write-Host "`n`nTop longest provisioners:"
    $provisionersList | ForEach-Object {
        if ($_.SubItems.Length -gt 0) { $_.SubItems } else { @{ Command = $_.ProvisionerType; Duration = $_.Duration } }
    } | Sort-Object { $_.Duration } | Select-Object -Last $PrintTopNLongest | ForEach-Object {
        Write-Host "- $($_.Duration) | $($_.Command)"
    }
}