MonoAotLLVM runtime is not actually AOTing things

[naricc]

If you try to do a run with --runtimes monoaotllvm, the run will suceed, but it is not actually aoting anything. A careful examination of the output shows the build of the generated project exited with 1. It does however build enough to continue execution, but skips the AOT step. Trying to manually build the generated project shows the underlying error:

/Users/naricc/workspace/performance-clean/artifacts/bin/MicroBenchmarks/Release/net7.0/Job-QULCUH/BenchmarkDotNet.Autogenerated.csproj(52,4): error MSB4044: The "MonoAOTCompiler" task was not given a value for the required parameter "IntermediateOutputPath"

This is because IntermediateOuputPath was added as a required parameter to the MonoAotCompilerTask by this change:
dotnet/runtime#59153

Example command:

 dotnet run -c Release -f net7.0 --filter "*IntroBasic*" --runtimes monoaotllvm --aotcompilerpath /Users/naricc/workspace/runtime-llvm-clean/artifacts/obj/mono/OSX.x64.Release/out/bin/mono-sgen --customruntimepack /Users/naricc/workspace/runtime-llvm-clean/artifacts/bin/microsoft.netcore.app.runtime.osx-x64/Release/ --aotcompilermode llvm

This is a pretty easy fix. But is there a way to get this to fail fast if similar issues come up in the future? This went undetected for a long time because it does not fail the run. @adamsitnik

[naricc]

Example of the log showing the exit 1 message (this is using the benchmarks in dotnet/performance):

// ***** BenchmarkRunner: Start   *****
// ***** Found 1 benchmark(s) in total *****
// ***** Building 1 exe(s) in Parallel: Start   *****
// start dotnet restore /p:DebugType=portable -bl:benchmarkdotnet.binlog /p:UseSharedCompilation=false /p:BuildInParallel=false /m:1 /p:Deterministic=true /p:Optimize=true in /Users/naricc/workspace/performance-clean/artifacts/bin/MicroBenchmarks/Release/net7.0/Job-QULCUH
// command took 3.64s and exited with 0
// start dotnet build -c Release /p:DebugType=portable -bl:benchmarkdotnet.binlog --no-restore /p:UseSharedCompilation=false /p:BuildInParallel=false /m:1 /p:Deterministic=true /p:Optimize=true in /Users/naricc/workspace/performance-clean/artifacts/bin/MicroBenchmarks/Release/net7.0/Job-QULCUH
// command took 21.42s and exited with 1
// start dotnet build -c Release /p:DebugType=portable -bl:benchmarkdotnet.binlog --no-restore --no-dependencies /p:UseSharedCompilation=false /p:BuildInParallel=false /m:1 /p:Deterministic=true /p:Optimize=true in /Users/naricc/workspace/performance-clean/artifacts/bin/MicroBenchmarks/Release/net7.0/Job-QULCUH
// command took 5.71s and exited with 1
// ***** Done, took 00:00:30 (30.92 sec)   *****
// Found 1 benchmarks:
//   Perf_Char.Char_IsUpper: Job-QULCUH(PowerPlanMode=00000000-0000-0000-0000-000000000000, Runtime=MonoAOTLLVM, Arguments=/p:DebugType=portable,-bl:benchmarkdotnet.binlog, Toolchain=MonoAOTLLVM, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [input=Good afternoon, Constable!]

// **************************
// Benchmark: Perf_Char.Char_IsUpper: Job-QULCUH(PowerPlanMode=00000000-0000-0000-0000-000000000000, Runtime=MonoAOTLLVM, Arguments=/p:DebugType=portable,-bl:benchmarkdotnet.binlog, Toolchain=MonoAOTLLVM, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [input=Good afternoon, Constable!]
// *** Execute ***
// Launch: 1 / 1
// Execute: /Users/naricc/workspace/performance-clean/artifacts/bin/MicroBenchmarks/Release/net7.0/Job-QULCUH/bin/net7.0/osx-x64/publish/Job-QULCUH --benchmarkName "System.Tests.Perf_Char.Char_IsUpper(input: \"Good afternoon, Constable!\")" --job "PowerPlanMode=00000000-0000-0000-0000-000000000000, Runtime=MonoAOTLLVM, Arguments=/p:DebugType=portable,-bl:benchmarkdotnet.binlog, Toolchain=MonoAOTLLVM, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1" --benchmarkId 0 in /Users/naricc/workspace/performance-clean/artifacts/bin/MicroBenchmarks/Release/net7.0/Job-QULCUH/bin/net7.0/osx-x64/publish
Failed to set up high priority. Make sure you have the right permissions. Message: Permission denied
// BeforeAnythingElse

// Benchmark Process Environment Information:
// Runtime=.NET 7.0.0 (42.42.42.42424), X64 RyuJIT
// GC=Non-concurrent Workstation
// Job: Job-VYOJTI(PowerPlanMode=00000000-0000-0000-0000-000000000000, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1)

OverheadJitting  1: 1 op, 158047.00 ns, 158.0470 us/op
WorkloadJitting  1: 1 op, 566897.00 ns, 566.8970 us/op

OverheadJitting  2: 16 op, 329867.00 ns, 20.6167 us/op
WorkloadJitting  2: 16 op, 241393.00 ns, 15.0871 us/op

WorkloadPilot    1: 16 op, 12427.00 ns, 776.6875 ns/op
WorkloadPilot    2: 321888 op, 226697146.00 ns, 704.2734 ns/op
WorkloadPilot    3: 354976 op, 240825743.00 ns, 678.4282 ns/op
WorkloadPilot    4: 368512 op, 251787431.00 ns, 683.2544 ns/op
WorkloadPilot    5: 365904 op, 234431024.00 ns, 640.6900 ns/op
WorkloadPilot    6: 390208 op, 266552441.00 ns, 683.1035 ns/op
WorkloadPilot    7: 365984 op, 225293767.00 ns, 615.5837 ns/op
WorkloadPilot    8: 406128 op, 272177274.00 ns, 670.1761 ns/op

OverheadWarmup   1: 406128 op, 818312.00 ns, 2.0149 ns/op
OverheadWarmup   2: 406128 op, 772329.00 ns, 1.9017 ns/op
OverheadWarmup   3: 406128 op, 731859.00 ns, 1.8020 ns/op
OverheadWarmup   4: 406128 op, 802069.00 ns, 1.9749 ns/op
OverheadWarmup   5: 406128 op, 771120.00 ns, 1.8987 ns/op
OverheadWarmup   6: 406128 op, 811129.00 ns, 1.9972 ns/op
OverheadWarmup   7: 406128 op, 837385.00 ns, 2.0619 ns/op
OverheadWarmup   8: 406128 op, 793759.00 ns, 1.9545 ns/op

OverheadActual   1: 406128 op, 815954.00 ns, 2.0091 ns/op
OverheadActual   2: 406128 op, 880423.00 ns, 2.1678 ns/op
OverheadActual   3: 406128 op, 816474.00 ns, 2.0104 ns/op
OverheadActual   4: 406128 op, 848762.00 ns, 2.0899 ns/op
OverheadActual   5: 406128 op, 790778.00 ns, 1.9471 ns/op
OverheadActual   6: 406128 op, 717150.00 ns, 1.7658 ns/op
OverheadActual   7: 406128 op, 680373.00 ns, 1.6753 ns/op
OverheadActual   8: 406128 op, 716188.00 ns, 1.7635 ns/op
OverheadActual   9: 406128 op, 755782.00 ns, 1.8609 ns/op
OverheadActual  10: 406128 op, 732895.00 ns, 1.8046 ns/op
OverheadActual  11: 406128 op, 741081.00 ns, 1.8247 ns/op
OverheadActual  12: 406128 op, 790855.00 ns, 1.9473 ns/op
OverheadActual  13: 406128 op, 791744.00 ns, 1.9495 ns/op
OverheadActual  14: 406128 op, 988968.00 ns, 2.4351 ns/op
OverheadActual  15: 406128 op, 791984.00 ns, 1.9501 ns/op
OverheadActual  16: 406128 op, 777138.00 ns, 1.9135 ns/op
OverheadActual  17: 406128 op, 822030.00 ns, 2.0241 ns/op
OverheadActual  18: 406128 op, 840762.00 ns, 2.0702 ns/op
OverheadActual  19: 406128 op, 833001.00 ns, 2.0511 ns/op
OverheadActual  20: 406128 op, 1169970.00 ns, 2.8808 ns/op

WorkloadWarmup   1: 406128 op, 284695847.00 ns, 701.0003 ns/op

// BeforeActualRun
WorkloadActual   1: 406128 op, 253987034.00 ns, 625.3867 ns/op
WorkloadActual   2: 406128 op, 251587597.00 ns, 619.4786 ns/op
WorkloadActual   3: 406128 op, 250477296.00 ns, 616.7447 ns/op
WorkloadActual   4: 406128 op, 248006233.00 ns, 610.6603 ns/op
WorkloadActual   5: 406128 op, 246919078.00 ns, 607.9834 ns/op
WorkloadActual   6: 406128 op, 255175198.00 ns, 628.3123 ns/op
WorkloadActual   7: 406128 op, 245467890.00 ns, 604.4102 ns/op
WorkloadActual   8: 406128 op, 247964545.00 ns, 610.5576 ns/op
WorkloadActual   9: 406128 op, 248528733.00 ns, 611.9468 ns/op
WorkloadActual  10: 406128 op, 250448345.00 ns, 616.6734 ns/op
WorkloadActual  11: 406128 op, 240504810.00 ns, 592.1897 ns/op
WorkloadActual  12: 406128 op, 253749253.00 ns, 624.8012 ns/op
WorkloadActual  13: 406128 op, 264296084.00 ns, 650.7704 ns/op
WorkloadActual  14: 406128 op, 263464160.00 ns, 648.7220 ns/op
WorkloadActual  15: 406128 op, 253348091.00 ns, 623.8134 ns/op

// AfterActualRun
WorkloadResult   1: 406128 op, 253195170.00 ns, 623.4369 ns/op
WorkloadResult   2: 406128 op, 250795733.00 ns, 617.5288 ns/op
WorkloadResult   3: 406128 op, 249685432.00 ns, 614.7949 ns/op
WorkloadResult   4: 406128 op, 247214369.00 ns, 608.7105 ns/op
WorkloadResult   5: 406128 op, 246127214.00 ns, 606.0336 ns/op
WorkloadResult   6: 406128 op, 254383334.00 ns, 626.3625 ns/op
WorkloadResult   7: 406128 op, 244676026.00 ns, 602.4604 ns/op
WorkloadResult   8: 406128 op, 247172681.00 ns, 608.6078 ns/op
WorkloadResult   9: 406128 op, 247736869.00 ns, 609.9970 ns/op
WorkloadResult  10: 406128 op, 249656481.00 ns, 614.7236 ns/op
WorkloadResult  11: 406128 op, 239712946.00 ns, 590.2399 ns/op
WorkloadResult  12: 406128 op, 252957389.00 ns, 622.8514 ns/op
WorkloadResult  13: 406128 op, 252556227.00 ns, 621.8636 ns/op
GC:  0 0 0 0 406128
Threading:  0 0 406128

// AfterAll
// Benchmark Process 82782 has exited with code 0.

Mean = 612.893 ns, StdErr = 2.790 ns (0.46%), N = 13, StdDev = 10.058 ns
Min = 590.240 ns, Q1 = 608.608 ns, Median = 614.724 ns, Q3 = 621.864 ns, Max = 626.362 ns
IQR = 13.256 ns, LowerFence = 588.724 ns, UpperFence = 641.747 ns
ConfidenceInterval = [600.848 ns; 624.938 ns] (CI 99.9%), Margin = 12.045 ns (1.97% of Mean)
Skewness = -0.59, Kurtosis = 2.56, MValue = 2

// ***** BenchmarkRunner: Finish  *****

// * Export *
  Users/naricc/workspace/performance-clean/artifacts/bin/MicroBenchmarks/Release/net7.0/BenchmarkDotNet.Artifacts/results/System.Tests.Perf_Char-report-github.md
  Users/naricc/workspace/performance-clean/artifacts/bin/MicroBenchmarks/Release/net7.0/BenchmarkDotNet.Artifacts/results/System.Tests.Perf_Char-report-full.json

// * Detailed results *
Perf_Char.Char_IsUpper: Job-QULCUH(PowerPlanMode=00000000-0000-0000-0000-000000000000, Runtime=MonoAOTLLVM, Arguments=/p:DebugType=portable,-bl:benchmarkdotnet.binlog, Toolchain=MonoAOTLLVM, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1) [input=Good afternoon, Constable!]
Runtime = .NET 7.0.0 (42.42.42.42424), X64 RyuJIT; GC = Non-concurrent Workstation
Mean = 612.893 ns, StdErr = 2.790 ns (0.46%), N = 13, StdDev = 10.058 ns
Min = 590.240 ns, Q1 = 608.608 ns, Median = 614.724 ns, Q3 = 621.864 ns, Max = 626.362 ns
IQR = 13.256 ns, LowerFence = 588.724 ns, UpperFence = 641.747 ns
ConfidenceInterval = [600.848 ns; 624.938 ns] (CI 99.9%), Margin = 12.045 ns (1.97% of Mean)
Skewness = -0.59, Kurtosis = 2.56, MValue = 2
-------------------- Histogram --------------------
[584.625 ns ; 600.166 ns) | @
[600.166 ns ; 612.889 ns) | @@@@@
[612.889 ns ; 631.977 ns) | @@@@@@@
---------------------------------------------------

// * Summary *

BenchmarkDotNet=v0.13.1.1620-nightly, OS=macOS Monterey 12.0.1 (21A559) [Darwin 21.1.0]
Intel Core i9-8950HK CPU 2.90GHz (Coffee Lake), 1 CPU, 12 logical and 6 physical cores
.NET SDK=7.0.100-alpha.1.21518.14
  [Host]     : .NET 7.0.0 (7.0.21.48001), X64 RyuJIT
  Job-QULCUH : .NET 7.0.0 (42.42.42.42424), X64 RyuJIT

PowerPlanMode=00000000-0000-0000-0000-000000000000  Runtime=MonoAOTLLVM  Arguments=/p:DebugType=portable,-bl:benchmarkdotnet.binlog  
Toolchain=MonoAOTLLVM  IterationTime=250.0000 ms  MaxIterationCount=20  
MinIterationCount=15  WarmupCount=1  

|       Method |                      input |     Mean |    Error |   StdDev |   Median |      Min |      Max | Allocated |
|------------- |--------------------------- |---------:|---------:|---------:|---------:|---------:|---------:|----------:|
| Char_IsUpper | Good afternoon, Constable! | 612.9 ns | 12.05 ns | 10.06 ns | 614.7 ns | 590.2 ns | 626.4 ns |         - |

// * Hints *
Outliers
  Perf_Char.Char_IsUpper: PowerPlanMode=00000000-0000-0000-0000-000000000000, Runtime=MonoAOTLLVM, Arguments=/p:DebugType=portable,-bl:benchmarkdotnet.binlog, Toolchain=MonoAOTLLVM, IterationTime=250.0000 ms, MaxIterationCount=20, MinIterationCount=15, WarmupCount=1 -> 2 outliers were removed (648.72 ns, 650.77 ns)

// * Legends *
  input     : Value of the 'input' parameter
  Mean      : Arithmetic mean of all measurements
  Error     : Half of 99.9% confidence interval
  StdDev    : Standard deviation of all measurements
  Median    : Value separating the higher half of all measurements (50th percentile)
  Min       : Minimum
  Max       : Maximum
  Allocated : Allocated memory per single operation (managed only, inclusive, 1KB = 1024B)
  1 ns      : 1 Nanosecond (0.000000001 sec)

// * Diagnostic Output - MemoryDiagnoser *


// ***** BenchmarkRunner: End *****
// ** Remained 0 benchmark(s) to run **
Run time: 00:00:08 (8.22 sec), executed benchmarks: 1

Global total time: 00:00:39 (39.15 sec), executed benchmarks: 1
// * Artifacts cleanup *