Add verbose mode, improve save discovery messages

velit · velit · commit a4e44fb84ea4 · 2022-02-20T05:03:32.000+02:00
Add -verboseResult mode that creates an excel file with tick based log
data stored in sheets for every separate run. Feature required
ImportExcel dependency. See the readme for installation instructions.

-outputNameVerbose and -verboseItems for picking the verbose excel
filename and which debug stats are used for verbose logging

Improvements to save discovery user messages

Human readable headers for normal csv output file

Fix remaining vars to camelCase

Add dependencies.txt
diff --git a/.gitignore b/.gitignore
@@ -1,2 +1,3 @@
 *.csv
 *.log
+Results
diff --git a/Readme.md b/Readme.md
@@ -4,9 +4,12 @@
 
 * Aggregation of benchmark data into an output CSV file
 * Disabling of mods for the duration of the benchmark (can use mods while benchmarking with -enableMods)
-* Cpu Priority selection (Cmdline flag -cpuPriority, defaults to "High")
+* Cpu Priority selection (-cpuPriority, defaults to "High")
 * Loading of benchmarked savefiles via a command line param / config param (-savePath / $savePath)
 * Regex pattern can be used to further limit which saves are benchmarked (-pattern "some pattern")
+* Verbose result mode (-verboseResult) allows creation of an excel file where
+  separate run results are saved to their own sheets with tick based update
+  times
 
 Various other command line options and flags for customizing functionality.
 Default values can be changed by editing the script, in the params section
@@ -20,6 +23,15 @@ Before running please go through at least the Basic Settings section of the
 script and switch the paths that are different for you. The defaults use Steam
 Factorio paths.
 
+## Dependencies
+
+Verbose mode depends on [Import-Excel](https://github.com/dfinke/ImportExcel)
+to create the output excel file with runs in their own sheets.
+
+Install it by running the following command in powershell:
+
+    Install-Module ImportExcel -scope CurrentUser
+
 ## Usage:
 
 Open the folder you put the ```benchmark.ps1``` script in using explorer. Select the
diff --git a/benchmark.ps1 b/benchmark.ps1
@@ -1,4 +1,5 @@
-# Factorio Benchmark Script v1.0.0
+# Factorio Benchmark Script v1.1.0
+# Depends on Import-Excel https://github.com/dfinke/ImportExcel for -verboseOutput
 param (
 
     ##################
@@ -43,8 +44,11 @@ param (
     # ADVANCED SETTINGS #
     #####################
 
-    # Output filename
-    [string]$outputName = "results.csv",
+    # Output csv filename
+    [string]$outputName = "results",
+
+    # Output xlsx verbose filename
+    [string]$outputNameVerbose = "verbose",
 
     # Which folder to output results into.
     [string]$outputFolder = ".\Results\",
@@ -61,6 +65,18 @@ param (
     # If given disables automatic mod disabling feature
     [switch]$enableMods = $false,
 
+    # If given enables verbose mode which logs per-tick benchmarks
+    [switch]$verboseResult = $false,
+
+    # Which items are selected for verbose logging
+    #
+    # Available options are:
+    #
+    # tick,timestamp,wholeUpdate,latencyUpdate,gameUpdate,circuitNetworkUpdate,transportLinesUpdate,fluidsUpdate,heatManagerUpdate,entityUpdate,particleUpdate,mapGenerator,mapGeneratorBasicTilesSupportCompute,mapGeneratorBasicTilesSupportApply,mapGeneratorCorrectedTilesPrepare,mapGeneratorCorrectedTilesCompute,mapGeneratorCorrectedTilesApply,mapGeneratorVariations,mapGeneratorEntitiesPrepare,mapGeneratorEntitiesCompute,mapGeneratorEntitiesApply,crcComputation,electricNetworkUpdate,logisticManagerUpdate,constructionManagerUpdate,pathFinder,trains,trainPathFinder,commander,chartRefresh,luaGarbageIncremental,chartUpdate,scriptUpdate,
+    #
+    # tick must be one of the selected items, otherwise the script won't work
+    [string]$verboseItems = "tick,wholeUpdate,wholeUpdate,gameUpdate,circuitNetworkUpdate,transportLinesUpdate,fluidsUpdate,entityUpdate,electricNetworkUpdate,logisticManagerUpdate,trains,trainPathFinder",
+
     # Can customize used CPU priority.
     [string]$cpuPriority = "High",
 
@@ -71,17 +87,25 @@ param (
     # Eg. enabling core 1, 3 and 5 is 1 + 4 + 16 = 21
     # 0 to disable feature
     [int]$cpuAffinity = 0
-
-    # If given, don't interleave runs and use factorio.exe run mechanism which is faster in real time
-    # TODO: implement
-    # [switch]$noRunInterleaving = $false,
 )
 #End of user variables
 
 $ErrorActionPreference = "Stop"
 
+$excelEnabled = $false
+if (Get-Command Export-Excel -errorAction SilentlyContinue)
+{
+  $excelEnabled = $true
+}
+elseif ($verboseResult) {
+  Write-Output "`nUNMET DEPENDENCY. Export-Excel cmdlet not found for verbose mode." `
+    "Please install it by running this command in powershell:" `
+    "`n    Install-Module ImportExcel -scope CurrentUser`n" `
+    "Script will run normally but verbose excel file won't be generated."
+}
+
 # Collect the saves to benchmark
-echo ""
+Write-Output ""
 if ($pattern -ne "") {
   [array]$saves = dir $savepath -file -recurse | where {$_.BaseName -Match $pattern}
   $saveFoundMessage = "found matching pattern '$pattern'"
@@ -92,17 +116,17 @@ else {
 }
 
 if ($saves.length -ne 0) {
-  echo "Following saves ${saveFoundMessage}:"
+  Write-Output "Following saves ${saveFoundMessage}:"
 }
 else {
-  echo "No saves $saveFoundMessage."
-  echo ""
+  Write-Output "No saves $saveFoundMessage."
+  Write-Output ""
   exit
 }
 
-echo ""
-echo $($saves | select -ExpandProperty BaseName)
-echo ""
+Write-Output ""
+Write-Output $($saves | select -ExpandProperty BaseName)
+Write-Output ""
 Write-Host -NoNewline "Executing benchmark after confirmation. Ctrl-c to cancel. "
 pause
 
@@ -113,11 +137,17 @@ try {
     # Remove illegal filename characters from pattern for output filename
     $sanitized_pattern = ($pattern.Split([IO.Path]::GetInvalidFileNameChars()) -join '_') + " "
   }
-  [System.IO.FileInfo]$output = Join-Path $outputFolder -ChildPath ($sanitized_pattern + $outputName)
+  [System.IO.FileInfo]$output = Join-Path $outputFolder -ChildPath ($sanitized_pattern + $outputName + ".csv")
+  [System.IO.FileInfo]$outputVerbose = Join-Path $outputFolder -ChildPath ($sanitized_pattern + $outputNameVerbose + ".xlsx")
 
   # Delete output file if feature is enabled
-  if (($clearOutputFile) -and (Test-Path $output)) {
-    rm $output
+  if ($clearOutputFile) {
+    if (Test-Path $output) {
+      rm $output
+    }
+    if (Test-Path $outputVerbose) {
+      rm $outputVerbose
+    }
   }
 
   # Check if output file already exists
@@ -126,41 +156,47 @@ try {
     [Void](New-Item -Force (Split-Path -Path $output) -ItemType Directory)
 
     # Create output and print headers
-    echo "save_name,run,startup_time_s,end_time_s,avg_ms,min_ms,max_ms,ticks,execution_time_ms,effective_UPS,version,platform,calibration" > $output
+    Write-Output "Save,Run,Startup time,End time,Avg ms,Min ms,Max ms,Ticks,Execution Time ms,Effective UPS,Version,Platform,Calibration" > $output
   }
 
   # Mod disabling block
   if (-not $enableMods) {
-    $mods_path = Join-Path -Path $configpath -ChildPath "mods"
-    $backup_path = Join-Path -Path $configpath -ChildPath "mods_disabled"
-    if (Test-Path $mods_path) {
-      if (-not (Test-Path $backup_path)) {
-        echo "Disabling mods."
-        Move-Item -Path $mods_path -Destination $backup_path
+    $modsPath = Join-Path -Path $configpath -ChildPath "mods"
+    $backupPath = Join-Path -Path $configpath -ChildPath "mods_disabled"
+    if (Test-Path $modsPath) {
+      if (-not (Test-Path $backupPath)) {
+        Write-Output "Disabling mods."
+        Move-Item -Path $modsPath -Destination $backupPath
       }
       else {
-        echo "Mods already disabled previously. Doing nothing."
+        Write-Output "Mods already disabled previously. Doing nothing."
       }
     }
     else {
-      echo "Mod folder not found. Doing nothing."
+      Write-Output "Mod folder not found. Doing nothing."
     }
   }
 
-  echo ""
+  Write-Output ""
   # Main benchmark loop
   for ($i = 0; $i -lt $runs; $i++) {
     for ($j = 0; $j -lt $saves.length; $j++) {
       $run = $i + 1
       $save = $saves[$j].FullName
-      $save_name = $saves[$j].BaseName
-      $log_path = Join-Path $outputFolder ($save_name + " Run" + $run + ".log")
+      $saveName = $saves[$j].BaseName
+      $runName = $saveName + " Run " + $run
+      $logPath = Join-Path $outputFolder ($runName + ".log")
 
-      Write-Host -NoNewline "Benchmarking '$save_name' Run $run`t"
+      Write-Host -NoNewline "Benchmarking $runName`t"
 
       # Run factorio
-      $arg_list = "--benchmark `"$save`" --benchmark-ticks $ticks --disable-audio"
-      $process = Start-Process -PassThru -FilePath $executable -ArgumentList $arg_list -RedirectStandardOutput $log_path
+      $argList = "--benchmark `"$save`" --benchmark-ticks $ticks --disable-audio"
+      
+      if ($verboseResult) {
+        $argList += " --benchmark-verbose " + $verboseItems
+      }
+
+      $process = Start-Process -PassThru -FilePath $executable -ArgumentList $argList -RedirectStandardOutput $logPath
 
       # Set process flags and wait for execution to finish
       $process.PriorityClass = $cpuPriority
@@ -169,43 +205,70 @@ try {
       }
       $process.WaitForExit()
 
-      # Perform a cleanup pass on the data, since depending on the time to benchmark a number of spaces will be added to the lines
-      $log_data = (Get-Content $log_path) -replace '^\s+', ''
-      $log_data | Set-Content $log_path
+      # Perform a cleanup pass on the data, since depending on the time to benchmark a number of spaces will be added to
+      # the lines
+      $logData = (Get-Content $logPath) -replace '^\s+', ''
+      $logData | Set-Content $logPath
 
       # Parse data
-      $avg_ms = (($log_data | Select-String "avg:") -split " ")[1]
-      $min_ms = (($log_data | Select-String "avg:") -split " ")[4]
-      $max_ms = (($log_data | Select-String "avg:") -split " ")[7]
-      $version = (($log_data | Select-Object -First 1) -split " ")[4]
-      $execution_time_ms = (($log_data | Select-String "Performed") -split " ")[4]
-      $startup_time_s = (($log_data | Select-String "Loading script.dat") -split " ")[0]
-      $end_time_s = (($log_data | Select-Object -Last 1) -split " ")[0]
-      $effective_UPS  = [math]::Round((1000 * $ticks / $execution_time_ms), 2)
+      $avg = (($logData | Select-String "avg:") -split " ")[1]
+      $min = (($logData | Select-String "avg:") -split " ")[4]
+      $max = (($logData | Select-String "avg:") -split " ")[7]
+      $version = (($logData | Select-Object -First 1) -split " ")[4]
+      $executionTime = (($logData | Select-String "Performed") -split " ")[4]
+      $startupTime = (($logData | Select-String "Loading script.dat") -split " ")[0]
+      $endTime = (($logData | Select-Object -Last 1) -split " ")[0]
+      $effectiveUPS  = [math]::Round((1000 * $ticks / $executionTime), 2)
 
       # Save the results
-      echo "$save_name,$run,$startup_time_s,$end_time_s,$avg_ms,$min_ms,$max_ms,$ticks,$execution_time_ms,$effective_UPS,$version,$platform,$calibration" >> $output
-
-      echo "end_time $end_time_s seconds"
+      Write-Output "$($executionTime / 1000) seconds"
+      Write-Output "$saveName,$run,$startupTime,$endTime,$avg,$min,$max,$ticks,$executionTime,$effectiveUPS,$version,$platform,$calibration" >> $output
+
+      # If verbose result is enabled produce a separarte excel file with verbose results
+      if (($verboseResult) -and ($excelEnabled)) {
+        $time = Get-Date -Format "HHmm "
+
+        # Select run-specific lines
+        # remove 't' from tick number
+        $verboseData = $logData `
+          | Select-String -Pattern "(^tick,)|(^t\d+)," `
+          | ForEach-Object {$_ -Replace "^t(\d+)", '$1'} `
+          | ConvertFrom-Csv `
+
+        # Change to milliseconds and make ticks 1-based
+        $verboseData | ForEach-Object { 
+          foreach ($property in $_.PSObject.Properties) {
+            if ($property.Name -eq "tick") {
+              [int]$property.Value += 1
+            }
+            else {
+              $property.Value = $property.Value / 1000000
+            }
+          }
+        }
+
+        # Output excel file
+        $verboseData | Export-Excel -AutoSize -WorksheetName ($time + $runName) $outputVerbose
+      }
 
       if (-not ($keepLogs)) {
-        rm "$log_path"
+        rm "$logPath"
       }
     }
   }
 }
 # Cleanup
 finally {
   if (-not $enableMods) {
-    if (Test-Path $backup_path) {
-      if (Test-Path $mods_path) {
-        echo "`nRestoring original mods."
-        mv -Force (Join-Path -Path $backup_path -ChildPath "\*") $mods_path
-        rm $backup_path
+    if (Test-Path $backupPath) {
+      if (Test-Path $modsPath) {
+        Write-Output "`nRestoring original mods."
+        mv -Force (Join-Path -Path $backupPath -ChildPath "\*") $modsPath
+        rm $backupPath
       }
       else {
-        echo "Mods folder not created. Probably factorio didn't run. Restoring mods."
-        mv $backup_path $mods_path
+        Write-Output "Mods folder not created. Probably factorio didn't run. Restoring mods."
+        mv $backupPath $modsPath
       }
     }
   }
diff --git a/dependencies.txt b/dependencies.txt
@@ -0,0 +1,6 @@
+# https://github.com/dfinke/ImportExcel
+Import-Excel
+
+# Install it by running this command:
+#
+#     Install-Module ImportExcel -scope CurrentUser 
