Xamarin-android: Profiled AOT proof of concept

[radekdoulik]

For some time mono supports feature called profiled AOT.

We should provide an easy way to use it on Android. It is useful when we don't want to AOT everything and only AOT parts of the assemblies. Like the parts used (and jitted) during application startup.

This way we can have smaller application, compared to normal AOT, and faster in areas we need, like the startup.

Currently it requires multiple steps to use.

• build the app with the aot profiler
• enable the profiling
• run the app and let it exit (aot profile is created at the app shutdown)
• get the profile from the device
• use the profile when building the application
• enjoy reasonably small quick starting app

Here's an example:

[build the app with the embedded aot profiler]
msbuild /t:Install /p:AndroidEmbedProfilers=aot /p:Configuration=Release tests/Xamarin.Forms-Performance-Integration/Droid/Xamarin.Forms.Performance.Integration.Droid.csproj

[enable aot profiling]
adb shell setprop debug.mono.profile aot

[run the app and wait till it exits]

[collect the profile]
adb shell cat /data/data/Xamarin.Forms_Performance_Integration/files/.__override__/profile.aot > profile.aot

[use the profile]
msbuild /t:Install /p:AndroidAotAdditionalArguments="profile-only,profile=profile.aot" /p:AotAssemblies=true /p:Configuration=Release tests/Xamarin.Forms-Performance-Integration/Droid/Xamarin.Forms.Performance.Integration.Droid.csproj

[enjoy your reasonably small and reasonably fast app]

The above example, where we use the profile for startup of the app, resulted in these apk sizes:

ls -lh bin/TestRelease/Xamarin.Forms_Performance_Integration-Signed-*.apk
-rw-r--r--  1 rodo  staff    38M Dec  7 20:17 bin/TestRelease/Xamarin.Forms_Performance_Integration-Signed-aot.apk
-rw-r--r--  1 rodo  staff    17M Dec  7 20:18 bin/TestRelease/Xamarin.Forms_Performance_Integration-Signed-jit.apk
-rw-r--r--  1 rodo  staff    19M Dec  7 20:12 bin/TestRelease/Xamarin.Forms_Performance_Integration-Signed-profiled-aot.apk

The resulting apk sizes:

build | normal | aot | profiled aot
--- | ---: | ---: | ---:
apk size | 17M | 38M | 19M

[radekdoulik]

Performance measurements:

Profiled AOT:

  Time:    323ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606212511::17373565805253454186
  Time:    317ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606182509::17373565805253454600
  Time:    320ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614605838396::17373565805253454633
  Time:    311ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606338238::17373565805253454667
  Time:    332ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606002301::17373565805253454733

No AOT:

  Time:    327ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614605927302::17373565805253455005
  Time:    320ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606028760::17373565805253455037
  Time:    327ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606190166::17373565805253455143
  Time:    316ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606527406::17373565805253455172
  Time:    318ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614605948187::17373565805253455190

AOT:

  Time:    217ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606447760::17373565805253455917
  Time:    219ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606350469::17373565805253455923
  Time:    219ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606095572::17373565805253455929
  Time:    219ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606076511::17373565805253455935
  Time:    221ms Message: Runtime.init: end, total time; elapsed: 0s.18437178614606320208::17373565805253455942

It looks like the AOT compiled methods might not be used? The times of profiled AOT are very close to no AOT times.

The Xamarin.Forms-Performance-Integration test was used, built with master XA and run on Pixel 2 XL.

[radekdoulik]

@vargaz, how do I check whether the AOT compiled methods are used during the runtime?

[luhenry]

@radekdoulik run with MONO_LOG_MASK=aot MONO_LOG_LEVEL=debug, that will log to logcat what functions were loaded or not from AOT

[radekdoulik]

Nice, thanks! I think I will have to use it in Debug configuration or modify Release libraries to be able to enable it. I will definitely try it.

[radekdoulik]

More progress today. Looks like the current XA/mono doesn't add any methods from the profile. Here's one example of AOT invocation:

MONO_PATH="/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/android/assets" MONO_ENV_OPTIONS="" /Users/rodo/git/xa/bin/Release/lib/xamarin.android/xbuild/Xamarin/Android/Darwin/cross-arm --aot=profile-only,profile=/Users/rodo/git/xa/profile.aot,msym-dir=/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a,outfile=/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/libaot-Xamarin.Forms.Performance.Integration.Droid.dll.so,asmwriter,mtriple=armv7-linux-gnueabi,tool-prefix=/Users/rodo/android-toolchain/ndk/toolchains/llvm/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-,ld-flags=,llvm-path=/Users/rodo/git/xa/bin/Release/lib/xamarin.android/xbuild/Xamarin/Android/Darwin,temp-path=/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/android/assets/Xamarin.Forms.Performance.Integration.Droid.dll
Mono Ahead of Time compiler - compiling assembly /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/android/assets/Xamarin.Forms.Performance.Integration.Droid.dll
AOTID D9288C08-44DB-5312-C3A6-D2D73A7192BC
Using profile data file '/Users/rodo/git/xa/profile.aot'
Added 0 methods from profile.
Code: 0(0%) Info: 0(0%) Ex Info: 0(0%) Unwind Info: 0(0%) Class Info: 1540(74%) PLT: 1(0%) GOT Info: 282(13%) Offsets: 256(12%) GOT: 100
Compiled: 0/0 (100%), No GOT slots: 0 (100%), Direct calls: 0 (100%)
Executing the native assembler: "/Users/rodo/android-toolchain/ndk/toolchains/llvm/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-as"   -mfpu=vfp3 -o /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll/temp.s.o /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll/temp.s
Executing the native linker: "/Users/rodo/android-toolchain/ndk/toolchains/llvm/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-ld"  -shared -o /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/libaot-Xamarin.Forms.Performance.Integration.Droid.dll.so.tmp  /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll/temp.s.o 
Stripping the binary: "/Users/rodo/android-toolchain/ndk/toolchains/llvm/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-strip" --strip-symbol=\$a --strip-symbol=\$d /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/libaot-Xamarin.Forms.Performance.Integration.Droid.dll.so.tmp
JIT time: 0 ms, Generation time: 3 ms, Assembly+Link time: 20 ms.

I see 0 methods added by all the assemblies. (note that we run AOT per assembly)

When using the older installed XA/mono it adds methods, although too many it seems:

MONO_PATH="/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/android/assets" MONO_ENV_OPTIONS="" /Library/Frameworks/Xamarin.Android.framework/Libraries/xbuild/Xamarin/Android/Darwin/cross-arm --aot=profile-only,profile=/Users/rodo/git/xa/profile.aot,msym-dir=/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a,outfile=/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/libaot-Xamarin.Forms.Performance.Integration.Droid.dll.so,asmwriter,mtriple=armv7-linux-gnueabi,tool-prefix=/Users/rodo/android-toolchain/ndk/toolchains/arm-linux-androideabi-4.9/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-,ld-flags=,llvm-path=/Library/Frameworks/Xamarin.Android.framework/Libraries/xbuild/Xamarin/Android/Darwin,temp-path=/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/android/assets/Xamarin.Forms.Performance.Integration.Droid.dll
Mono Ahead of Time compiler - compiling assembly /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/android/assets/Xamarin.Forms.Performance.Integration.Droid.dll
AOTID C1C9B94E-DDDA-72F4-3554-82E69E8A5834
Using profile data file '/Users/rodo/git/xa/profile.aot'
Added 2266 methods from profile.
Code: 671408(85%) Info: 20492(2%) Ex Info: 12145(1%) Unwind Info: 29470(3%) Class Info: 1517(0%) PLT: 2152(0%) GOT Info: 34649(4%) Offsets: 13321(1%) GOT: 21484
Compiled: 2086/2086 (100%), No GOT slots: 887 (42%), Direct calls: 0 (100%)
Executing the native assembler: "/Users/rodo/android-toolchain/ndk/toolchains/arm-linux-androideabi-4.9/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-as"   -mfpu=vfp3 -o /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll/temp.s.o /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll/temp.s
Executing the native linker: "/Users/rodo/android-toolchain/ndk/toolchains/arm-linux-androideabi-4.9/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-ld"  -shared -o /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/libaot-Xamarin.Forms.Performance.Integration.Droid.dll.so.tmp  /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll/temp.s.o 
Stripping the binary: "/Users/rodo/android-toolchain/ndk/toolchains/arm-linux-androideabi-4.9/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-strip" --strip-symbol=\$a --strip-symbol=\$d /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/libaot-Xamarin.Forms.Performance.Integration.Droid.dll.so.tmp
JIT time: 243 ms, Generation time: 172 ms, Assembly+Link time: 242 ms.

I think in this case it is adding methods outside of the assembly, as the Xamarin.Forms.Performance.Integration.Droid.dll contains only 45 methods.

That explains the behavior I saw some time ago, where the apk size with profile-only was larger than apk with normal AOT, as the compiled methods were added to multiple shared libraries.

The current behavior, where no compiled method are added also explains the small apk size and slow performance.

@luhenry , @vargaz could you please check the above invocation whether they look right? Could you help me find out why the methods are not compiled and added?

[radekdoulik]

I played with mono and tried to fix the issue. I will open a PR with a possible fix.

The results look good:

No AOT:

  Time:    368ms Message: Runtime.init: end, total time; elapsed: 0s:325::608574
  Time:    366ms Message: Runtime.init: end, total time; elapsed: 0s:326::203731
  Time:    365ms Message: Runtime.init: end, total time; elapsed: 0s:325::254824
  Time:    360ms Message: Runtime.init: end, total time; elapsed: 0s:325::276959
  Time:    366ms Message: Runtime.init: end, total time; elapsed: 0s:326::578470

Profiled AOT:

  Time:    259ms Message: Runtime.init: end, total time; elapsed: 0s:215::16115
  Time:    263ms Message: Runtime.init: end, total time; elapsed: 0s:218::214709
  Time:    250ms Message: Runtime.init: end, total time; elapsed: 0s:214::419813
  Time:    248ms Message: Runtime.init: end, total time; elapsed: 0s:213::317157
  Time:    262ms Message: Runtime.init: end, total time; elapsed: 0s:214::172313

AOT:

  Time:    282ms Message: Runtime.init: end, total time; elapsed: 0s:246::433202
  Time:    279ms Message: Runtime.init: end, total time; elapsed: 0s:236::330753
  Time:    267ms Message: Runtime.init: end, total time; elapsed: 0s:232::307732
  Time:    267ms Message: Runtime.init: end, total time; elapsed: 0s:228::444398
  Time:    263ms Message: Runtime.init: end, total time; elapsed: 0s:228::738252

Looks like the profiled AOT startup might be even faster compared to normal AOT, probably because of the smaller size?

The profiled AOT apk size is now around 20Mbytes.

The whole start of the XF test takes about 1 second compared to about 2 seconds without AOT.

[radekdoulik]

With the fix, the compilation looks like this:

MONO_PATH="/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/android/assets" MONO_ENV_OPTIONS="" /Users/rodo/git/xa/bin/Release/lib/xamarin.android/xbuild/Xamarin/Android/Darwin/cross-arm --aot=profile-only,profile=/Users/rodo/git/xa/profile.aot,msym-dir=/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a,outfile=/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/libaot-Xamarin.Forms.Performance.Integration.Droid.dll.so,asmwriter,mtriple=armv7-linux-gnueabi,tool-prefix=/Users/rodo/android-toolchain/ndk/toolchains/llvm/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-,ld-flags=,llvm-path=/Users/rodo/git/xa/bin/Release/lib/xamarin.android/xbuild/Xamarin/Android/Darwin,temp-path=/Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/android/assets/Xamarin.Forms.Performance.Integration.Droid.dll 
Mono Ahead of Time compiler - compiling assembly /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/android/assets/Xamarin.Forms.Performance.Integration.Droid.dll
AOTID 3FB87415-5E45-F2BA-5D43-60AA9F751749
Using profile data file '/Users/rodo/git/xa/profile.aot'
Added 13 methods from profile.
Code: 4080(55%) Info: 90(1%) Ex Info: 190(2%) Unwind Info: 295(4%) Class Info: 1540(21%) PLT: 28(0%) GOT Info: 765(10%) Offsets: 350(4%) GOT: 392
Compiled: 13/13 (100%), No GOT slots: 3 (23%), Direct calls: 0 (100%)
Executing the native assembler: "/Users/rodo/android-toolchain/ndk/toolchains/llvm/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-as"   -mfpu=vfp3 -o /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll/temp.s.o /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll/temp.s
Executing the native linker: "/Users/rodo/android-toolchain/ndk/toolchains/llvm/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-ld"  -shared -o /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/libaot-Xamarin.Forms.Performance.Integration.Droid.dll.so.tmp  /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/Xamarin.Forms.Performance.Integration.Droid.dll/temp.s.o 
Stripping the binary: "/Users/rodo/android-toolchain/ndk/toolchains/llvm/prebuilt/darwin-x86_64/bin/arm-linux-androideabi-strip" --strip-symbol=\$a --strip-symbol=\$d /Users/rodo/git/xa/tests/Xamarin.Forms-Performance-Integration/Droid/obj/Release/aot/armeabi-v7a/libaot-Xamarin.Forms.Performance.Integration.Droid.dll.so.tmp
JIT time: 8 ms, Generation time: 8 ms, Assembly+Link time: 27 ms.

[jonpryor]

The mentioned fix is: https://github.com/mono/mono/pull/13148

[radekdoulik]

Remeasured the XF test today, with recently added Activity displayed time reporting (fcfbf935819071776c77665a7d1a52fb0b91d0a4).

No AOT:

log1-measurement.txt:  Time:   1447ms Activity displayed
log2-measurement.txt:  Time:   1447ms Activity displayed
log3-measurement.txt:  Time:   1446ms Activity displayed
log4-measurement.txt:  Time:   1442ms Activity displayed
log5-measurement.txt:  Time:   1449ms Activity displayed

AOT:

log1-measurement.txt:  Time:    790ms Activity displayed
log2-measurement.txt:  Time:    792ms Activity displayed
log3-measurement.txt:  Time:    781ms Activity displayed
log4-measurement.txt:  Time:    778ms Activity displayed
log5-measurement.txt:  Time:    780ms Activity displayed

Profiled AOT:

log1-measurement.txt:  Time:    767ms Activity displayed
log2-measurement.txt:  Time:    758ms Activity displayed
log3-measurement.txt:  Time:    759ms Activity displayed
log4-measurement.txt:  Time:    766ms Activity displayed
log5-measurement.txt:  Time:    767ms Activity displayed