Implement script to parse provisioners duration from packer diagnostic logs (#2137)

* testing

* Update image-generation.yml

* Update image-generation.yml

* fix comments

* Update measure-provisioners-duration.ps1

.vscode/settings.json

@@ -1,7 +1,3 @@
 {
-    // When enabled, will trim trailing whitespace when you save a file.
-    "files.trimTrailingWhitespace": true,
-    "[markdown]": {
-        "files.trimTrailingWhitespace": false
-    },
+    "files.trimTrailingWhitespace": false
 }

images.CI/linux-and-win/azure-pipelines/image-generation.yml

@@ -6,9 +6,10 @@
 
 jobs:
 - job:
-  pool: ci-agent-pool
+  displayName: Image Generation (${{ parameters.image_type }})
   timeoutInMinutes: 600
   cancelTimeoutInMinutes: 30
+  pool: ci-agent-pool
   variables:
   - group: Image Generation Variables
 
@@ -21,6 +22,18 @@ jobs:
       filePath: ./images.CI/download-repo.ps1
       arguments: -RepoUrl $(CUSTOM_REPOSITORY_URL) `
                  -RepoBranch $(CUSTOM_REPOSITORY_BRANCH)
+    
+  - task: PowerShell@2
+    displayName: 'Set image template variables'
+    inputs:
+      targetType: 'inline'
+      script: |
+        $ImageType = "${{ parameters.image_type }}"
+        $TemplateDirectoryName = if ($ImageType.StartsWith("ubuntu")) { "linux" } else { "win" }
+        $TemplateDirectoryPath = Join-Path "images" $TemplateDirectoryName | Resolve-Path
+        $TemplatePath = Join-Path $TemplateDirectoryPath "$ImageType.json"
+        Write-Host "##vso[task.setvariable variable=TemplateDirectoryPath;]$TemplateDirectoryPath"
+        Write-Host "##vso[task.setvariable variable=TemplatePath;]$TemplatePath"
 
   - task: PowerShell@2
     displayName: 'Build VM'
@@ -30,7 +43,7 @@ jobs:
       arguments: -ResourcesNamePrefix $(Build.BuildId) `
                         -ClientId $(CLIENT_ID) `
                         -ClientSecret $(CLIENT_SECRET) `
-                        -Image ${{ parameters.image_type }} `
+                        -TemplatePath $(TemplatePath) `
                         -ResourceGroup $(AZURE_RESOURCE_GROUP) `
                         -StorageAccount $(AZURE_STORAGE_ACCOUNT) `
                         -SubscriptionId $(AZURE_SUBSCRIPTION) `
@@ -40,14 +53,25 @@ jobs:
                         -VirtualNetworkRG $(BUILD_AGENT_VNET_RESOURCE_GROUP) `
                         -VirtualNetworkSubnet $(BUILD_AGENT_SUBNET_NAME) `
                         -GitHubFeedToken $(GITHUB_TOKEN)
+    env:
+      PACKER_LOG: 1
+      PACKER_LOG_PATH: $(Build.ArtifactStagingDirectory)/packer-log.txt
 
   - task: PowerShell@2
     displayName: 'Output Readme file content'
     inputs:
       targetType: 'inline'
       script: |
-        $docsPath = Get-ChildItem -Path "images" -Include ${{ parameters.image_readme_name }} -Recurse -Depth 1 | Select-Object -First 1
-        Get-Content -Path $docsPath
+        Get-Content -Path (Join-Path "$(TemplateDirectoryPath)" "${{ parameters.image_readme_name }}")
+
+  - task: PowerShell@2
+    displayName: 'Print provisioners duration'
+    inputs:
+      targetType: 'filePath'
+      filePath: ./images.CI/measure-provisioners-duration.ps1
+      arguments: -PackerLogPath "$(Build.ArtifactStagingDirectory)/packer-log.txt" `
+                        -PrefixToPathTrim "$(TemplateDirectoryPath)" `
+                        -PrintTopNLongest 25
 
   - task: PowerShell@2
     displayName: 'Create release for VM deployment'

images.CI/linux-and-win/build-image.ps1

@@ -1,5 +1,5 @@
 param(
-    [String] [Parameter (Mandatory=$true)] $Image,
+    [String] [Parameter (Mandatory=$true)] $TemplatePath,
     [String] [Parameter (Mandatory=$true)] $ClientId,
     [String] [Parameter (Mandatory=$true)] $ClientSecret,
     [String] [Parameter (Mandatory=$true)] $GitHubFeedToken,
@@ -14,8 +14,7 @@ param(
     [String] [Parameter (Mandatory=$true)] $VirtualNetworkSubnet
 )
 
-$TemplatePath = (Get-ChildItem -Path "images" -Include "$Image.json" -Recurse -Depth 2).FullName
-if (-not $TemplatePath)
+if (-not (Test-Path $TemplatePath))
 {
     Write-Error "'-Image' parameter is not valid. You have to specify correct image type."
     exit 1

images.CI/macos/azure-pipelines/image-generation.yml

@@ -87,9 +87,10 @@ jobs:
             $sensitiveString -eq $null
         }
     displayName: 'Build VM'
-    env:
-      PACKER_LOG: 0
     workingDirectory: 'images/macos'
+    env:
+      PACKER_LOG: 1
+      PACKER_LOG_PATH: $(Agent.TempDirectory)/packer-log.txt
 
   - bash: |
       echo "Copy image output files"
@@ -112,6 +113,14 @@ jobs:
       ArtifactName: 'Built_VM_Artifacts'
     displayName: Publish Artifacts
 
+  - task: PowerShell@2
+    displayName: 'Print provisioners duration'
+    inputs:
+      targetType: 'filePath'
+      filePath: ./images.CI/measure-provisioners-duration.ps1
+      arguments: -PackerLogPath "$(Agent.TempDirectory)/packer-log.txt" `
+                        -PrintTopNLongest 25
+
   - task: PublishTestResults@2
     inputs:
       testResultsFiles: '*.xml'

images.CI/measure-provisioners-duration.ps1

@@ -0,0 +1,122 @@
+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)"
+    }
+}