Profiling MSBuild Tasks

Profiling MSBuild Tasks on Mono

Sometimes we need to profile an actual MSBuild task This is so we can find out where there slow parts of that particular task are. My first though was to export the MONO_OPTIONS flag so that we can run the profiler during a normal msbuild call

export MONO_OPTIONS=--profile=log
msbuild /t:Build

However this resulted in the following output in the profile

unmatched leave at stack pos: 0 for method unknown method 0xffffffffffffffe5
unhandled profiler event: 0x6d at file offset: 490309 + 30049 (len: 65396
)

so the profiler crashed :(.

So the next idea is to write a small console app to test the Task directly. This will use the same MockBuildEngine we use in our NUnit tests to test Tasks. So we can do something like this in the Program's Main entry point

MockBuildEngine engine = new MockBuildEngine (Console.Out);
Example task = new Example () {
    BuildEngine = engine,
    Source = new ITaskItem [] { new TaskItem ("Hello"), new TaskItem ("World") },
};
for (int i = 0; i < 100; i++) {
    task.Execute ();
}

We can then build the app and run the profile using.

mono --profile=log:calls,callspec=Xamarin.Android.Build.Tasks ~MSBuildBenchmarkTask.exe

The above command will produce enter/exit timings for all methods within the Xamarin.Android.Build.Tasks assembly. This will produce an output.mlpd file which we can then use mprof-report to view. This will result in data such as

mprof-report output.mlpd 

Mono log profiler data
	Profiler version: 3.0
	Data version: 17
	Arguments: log:calls,callspec=Xamarin.Android.Build.Tasks
	Architecture: x86-64
	Operating system: osx
	Mean timer overhead: 18 nanoseconds
	Program startup: Mon Dec  9 11:16:53 2019
	Program ID: 7022
	Server listening on: 52292

JIT summary
	Compiled methods: 1342
	Generated code size: 489767
	JIT helpers: 0
	JIT helpers code size: 0

GC summary
	GC resizes: 0
	Max heap size: 0
	Object moves: 0

Method call summary
Total(ms) Self(ms)      Calls Method name
     113       14        100 Xamarin.Android.Build.Tasks.Example:Execute ()
      66       66        200 Xamarin.Android.Build.Tasks.MSBuildExtensions:LogDebugTaskItems (Microsoft.Build.Utilities.TaskLoggingHelper,string,Microsoft.Build.Framework.ITaskItem[])
      30       30          1 MSBuildXamarin.Android.Build.TasksSandbox.MSBuildExtensions:.cctor ()
       1        1        200 Xamarin.Android.Build.Tasks.Example:ComputeHash (System.Security.Cryptography.SHA1,string)
Total calls: 803

Metadata summary
	Loaded images: 7
	Loaded assemblies: 7

Exception summary
	Throws: 0
	Executed finally clauses: 10606

Thread summary
	Thread: 0x700008a78000, name: "Finalizer"
	Thread: 0x700008c7b000, name: "Profiler Sampler"
	Thread: 0x1095465c0, name: "Main"
	Thread: 0x700008e04000, name: "Profiler Dumper"
	Thread: 0x700008cfe000, name: "Profiler Helper"
	Thread: 0x700008d81000, name: "Profiler Writer"

Domain summary
	Domain: 0x0, friendly name: "MSBuildBenchmarkTask.exe"

Context summary
	Context: 0x0, domain: 0x0

Counters:
	Mono System:
		User Time                      : 141.128ms
		System Time                    : 40.415ms
		Total Time                     : 181.579ms
		Working Set                    : 26136576
		Private Bytes                  : 12394496
		Virtual Bytes                  : 196775936
		Page Faults                    : 0
		CPU Load Average - 1min        : 1.902832
		CPU Load Average - 5min        : 1.933594
		CPU Load Average - 15min       : 2.008789
	Mono JIT:
		Methods from AOT               : 869
		Methods JITted using mono JIT  : 399
		Methods JITted using LLVM      : 0

We can now take a look at the data and see where the time is going.