Bug 52545 - iOS Builds Take Twice As Long to Build w/ Xamarin.iOS 10.3.1.8
Summary: iOS Builds Take Twice As Long to Build w/ Xamarin.iOS 10.3.1.8
Status: VERIFIED FIXED
Alias: None
Product: iOS
Classification: Xamarin
Component: General (show other bugs)
Version: XI 10.4 (C9)
Hardware: Macintosh Mac OS
: High major
Target Milestone: 15.2
Assignee: Alex Soto [MSFT]
URL:
: 55115 (view as bug list)
Depends on: 43462
Blocks:
  Show dependency tree
 
Reported: 2017-02-15 21:56 UTC by Bill
Modified: 2017-06-27 16:27 UTC (History)
11 users (show)

See Also:
Tags:
Is this bug a regression?: Yes
Last known good build: 10.0.1.10


Attachments
Chart of build times doubling and 2 build logs (before and after) (1.67 MB, application/zip)
2017-02-15 21:56 UTC, Bill
Details
latest logs showing same code, different versions of Xamarin, with verbose logging enabled. (3.69 MB, application/zip)
2017-03-01 00:00 UTC, Bill
Details

Description Bill 2017-02-15 21:56:58 UTC
Created attachment 19834 [details]
Chart of build times doubling and 2 build logs (before and after)

After we upgraded to the latest stable channel of Xamarin our build times have doubled. See attached image of our build times on TeamCity. 

I have also attached build logs of before and after. I do not remember what version of Xamarin we upgraded from but we do know that on this latest version our build times went from averaging 20 minutes to averages 40 minutes. 

We tried what is currently on the beta channel and that did not fix the problem.

From what I can tell looking at the logs, it looks like its the llvm optimization/linking that doubled in time.

Complete version information:

Xamarin Studio Community
Version 6.1.5 (build 0)
Installation UUID: ad25229e-3520-4078-a6f7-33a544d0dbba
Runtime:
    Mono 4.6.2 (mono-4.6.0-branch/ac9e222) (64-bit)
    GTK+ 2.24.23 (Raleigh theme)

    Package version: 406020016

NuGet
Version: 3.4.3.0

Xamarin.Profiler
Not Installed

Apple Developer Tools
Xcode 8.2.1 (11766.1)
Build 8C1002

Xamarin.Mac
Not Installed

Xamarin.Android
Version: 7.0.2.42 (Xamarin Studio Community)
Android SDK: /Users/xcpobuild/Library/Developer/Xamarin/android-sdk-macosx
    Supported Android versions:
        2.3   (API level 10)
        4.0.3 (API level 15)
        4.3   (API level 18)
        4.4   (API level 19)
        5.0   (API level 21)
        5.1   (API level 22)
        6.0   (API level 23)
        7.0   (API level 24)

SDK Tools Version: 25.2.3
SDK Platform Tools Version: 25.0.1
SDK Build Tools Version: 25.0.1

Java SDK: /usr
java version "1.8.0_121"
Java(TM) SE Runtime Environment (build 1.8.0_121-b13)
Java HotSpot(TM) 64-Bit Server VM (build 25.121-b13, mixed mode)

Android Designer EPL code available here:
https://github.com/xamarin/AndroidDesigner.EPL

Xamarin Android Player
Not Installed

Xamarin.iOS
Version: 10.3.1.8 (Xamarin Studio Community)
Hash: 7beaef4
Branch: cycle8-xi
Build date: 2016-12-20 02:58:14-0500

Build Information
Release ID: 601050000
Git revision: 7494718e127af9eaec45a3bd6282d3da927488bd
Build date: 2017-01-17 10:31:01-05
Xamarin addins: c92d0626d347aaa02839689eaac2961d24c9f446
Build lane: monodevelop-lion-cycle8

Operating System
Mac OS X 10.11.6
Darwin xcpobuild-7.xactware.com 15.6.0 Darwin Kernel Version 15.6.0
    Thu Jun 23 18:25:34 PDT 2016
    root:xnu-3248.60.10~1/RELEASE_X86_64 x86_64
Comment 1 Sebastien Pouliot 2017-02-16 01:44:52 UTC
> I do not remember what version of Xamarin we upgraded from 

It's part of the logs :)

-					 [Building Xactimate.iOS] 				Xamarin.iOS 10.0.1.10 (cycle8-sr0-xi: ad1cd42) using framework: /Applications/Xcode.app/Contents/Developer/Platforms/iPhoneOS.platform/Developer/SDKs/iPhoneOS10.0.sdk
+					 [Building Xactimate.iOS] 				Xamarin.iOS 10.3.1.8 (cycle8-xi: 7beaef4) using framework: /Applications/Xcode.app/Contents/Developer/Platforms/iPhoneOS.platform/Developer/SDKs/iPhoneOS10.2.sdk


Release builds are not our normal optimization target, since it's executed less often that debug builds, but this is quite unexpected - even more since this is all from C8 (so the amount of changes is not huge).

-				 [Building Xactimate.iOS.sln] Building Xactimate.iOS (7m:36s)
+				 [Building Xactimate.iOS.sln] Building Xactimate.iOS (30m:26s)

From a quick look all the arguments appears to be identical. Parts of the build is ran in parallel so analyzing the logs will take some time.

Now there's something important that our current* logging does not show, it's the size of the native dependencies. A few people ran into issues rebuilding (or upgrading) native libraries that now includes bitcode and that can make them 10x as large. Can you check if your dependencies size has changed during that period ?

* we'll be logging this information in the future
Comment 2 Sebastien Pouliot 2017-02-16 03:00:31 UTC
mtouch is called on Xactimate.iOS at

> grep "abi=arm" *log.log
> Last sub 20 minute log.log:[13:40:09]
> Most recent log.log:[09:44:56]

Managed Linking starts (twice for 32/64 bits) at

> grep "[Building Xactimate.iOS]" *log.log | grep "Linking /"
> Last sub 20 minute log.log:[13:40:17] +8 sec
> Last sub 20 minute log.log:[13:41:01] +44 sec
> Most recent log.log:[09:45:05] +9 sec
> Most recent log.log:[09:45:49] +44 sec

Native framework detection (first of two groups for 32/64 bits) at

> grep "[Building Xactimate.iOS]" *log.log | grep "Linking with"
> Last sub 20 minute log.log:[13:41:49] +48 sec
> Last sub 20 minute log.log:[13:44:00] +2m11s
> Most recent log.log:[09:46:35] +46 sec
> Most recent log.log:[09:55:50] +9m15s <--- at this stage only one arch was built

So the issue seems related to the native build.

I'll drill it down further tomorrow and start to compare the changes between the 2 versions. 

@Zoltan do you recall any major change wrt LLVM in C8 service releases ?
Comment 3 Zoltan Varga 2017-02-16 21:56:33 UTC
Enabling llvm might cause long build times, but 20/40 minutes seem extreme.

The fix for https://bugzilla.xamarin.com/show_bug.cgi?id=52475 might help here, as it disables llvm on large methods.
Comment 4 Bill 2017-02-28 23:58:52 UTC
To respond to what you asked about native dependencies changing: we tried the same exact code with the same xcode but the two different versions of xamarin and we got double build time on the latest xamarin stable. So the only difference seems to be Xamarin version. I attached new build logs with verbosity turned on so you can see.
Comment 5 Bill 2017-03-01 00:00:30 UTC
Created attachment 20048 [details]
latest logs showing same code, different versions of Xamarin, with verbose logging enabled.
Comment 6 Bill 2017-03-01 17:53:07 UTC
We tried again after the stable channel update (Xamarin.iOS 10.4.0.123) and there was no change.
Comment 7 Alex Soto [MSFT] 2017-03-07 20:21:47 UTC
I could not find remarkable time differences on build time using an app that uses Xamarin Forms plus + other dependencies + LLVM enabled. (Build logs: https://gist.github.com/dalexsoto/8528fc898d1bceb78c4d99c16f0c52c0).

Cycle 8

Time Elapsed 00:06:47.2079750

Cycle 9

Time Elapsed 00:07:04.5010380
Comment 8 Sebastien Pouliot 2017-03-07 20:33:29 UTC
@Bill if the final 10.4 did not help then it seems unrelated to the bug Zoltan mentioned in comment #3.

It's also not something we see if normal tests or what @Alex tried, so you might be running into a corner case.

It's been a while but iirc we had access, at some point, to your application. Do you know if that's still the case ? If so we might be able to do a binary search to pinpoint the change where this started.

Also do you know if other builds (e.g. local debug build) also suffers from this same slowdown ? I assumed not initially, and though it could be related to LLVM, but if it's a corner case then the issue might be inside the mono (not LLVM) AOT backend (we do know the time difference happens when doing native compilation).
Comment 9 Bill 2017-03-08 17:58:14 UTC
@Sebastien you guys still have a copy of our repo. I will update it and then let you know via a comment on this bug. 

Our debug builds are not affected.
Comment 10 Bill 2017-03-13 16:33:27 UTC
I have updated our code on your repo. To build we run this command: ./xactimate.ios/Xactimate.iOS/build.sh "enterprise-build" which ends up running some FAKE scripts.
Comment 11 Bill 2017-03-22 17:17:06 UTC
FYI we also tried MSBuild over xBuild to see if it would make a difference. It didn't.
Comment 12 Alex Soto [MSFT] 2017-04-05 02:34:23 UTC
I am able to reproduce this issue

C9 current stable XI:
	Time Elapsed 00:25:50.5371740
C8 10.0.1.10:
	Time Elapsed 00:08:06.1501160
Comment 13 Zoltan Varga 2017-04-05 19:06:36 UTC
Some results of running mtouch using the mono profiler using
mono64 --profile=log:nocalls,output=log,heapshot=100gc <mtouch args>

GC summary
	GC resizes: 0
	Max heap size: 0
	Object moves: 0
	Gen0 collections: 355, max time: 11243us, total time: 2016881us, average: 5681us
	Gen1 collections: 488, max time: 1035228us, total time: 303848084us, average: 622639us
	GC handles weak: created: 4, destroyed: 4, max: 3
	GC handles weaktrack: created: 41, destroyed: 37, max: 17

-> 303 seconds (5 minutes) are spent doing major GCs.

	Heap shot 3 at 324.910 secs: size: 1357481056, object count: 14100062, class count: 560, roots: 0
	     Bytes      Count  Average Class name
	 339926752      11965    28410 System.Byte[] (bytes: +8464, count: +5)
	 329505344    5884024       56 Mono.Cecil.Cil.Instruction (bytes: +0, count: +0)
	  87706272     292751      299 Mono.Cecil.Cil.Instruction[] (bytes: +0, count: +0)
	  51408320     321302      160 Mono.Cecil.MethodDefinition (bytes: +0, count: +0)
	  48059712     711082       67 System.String (bytes: -1322280, count: -8831)
	  38624000     482800       80 Mono.Cecil.ParameterDefinition (bytes: +0, count: +0)
	  31383680     245185      128 Mono.Cecil.GenericInstanceType (bytes: +0, count: +0)
	  23094000     288675       80 Mono.Cecil.Cil.MethodBody (bytes: +0, count: +0)
	  20689208        569    36360 System.Collections.Generic.Dictionary.Entry<System.UInt32,System.String>[] (bytes: +0, count: +0)
	  20636360     515909       40 Mono.Cecil.MethodReturnType (bytes: +0, count: +0)
	  18510720     144615      128 Mono.Cecil.FieldDefinition (bytes: +0, count: +0)
	  17788664     270415       65 Mono.Cecil.TypeReference[] (bytes: +0, count: +0)
	  15573616          2  7786808 System.Collections.Generic.HashSet.Slot<Mono.Cecil.IMetadataTokenProvider>[] (bytes: +0, count: +0)

-> about 1.5GB of persistent cecil related data is kept around by mtouch, which needs to be scanned on each major gc.
Comment 14 Zoltan Varga 2017-04-06 00:06:27 UTC
Further observations:
* during the assembly phase, the cpu loads seems very low. Is this done in parallel ?
* ditto for the strip phase.
* stripping is done by invoking mono-cil-strip.exe. That spends about 0.5s per invocation just
  for JITting cecil etc.
* the stripper loads assemblies using:
  assembly.MainModule.FullLoad ();
  which will load all IL code, which is discarded right after.
* We should probably upgrade mono-cil-strip to the current cecil. Why is it using its own private copy ?
Comment 15 Zoltan Varga 2017-04-06 01:35:33 UTC
This is caused by this:
https://github.com/xamarin/xamarin-macios/blob/9f0fd32330e127b303874121f96c9e7d737c4297/tools/common/Driver.cs#L213

and similar code in multiple files.

If we want to keep this, we should do it every 10-20 process spawns, since mtouch has a 1gb heap due to cecil data structures.
Comment 16 Alex Soto [MSFT] 2017-04-06 02:03:45 UTC
This is the commit where this was introduced https://github.com/xamarin/xamarin-macios/commit/350be8882124966e6072b12cd6e895c06dab7177
Comment 17 Sebastien Pouliot 2017-04-06 03:14:36 UTC
@Zoltan thanks for helping Alex investigate the issue!

It's a big project, the same did not show up when measuring other, smaller projects. It might be possible to move stuff around and close (reclaim memory) of the loaded assemblies before starting the AOT compilation.


> * during the assembly phase, the cpu loads seems very low. Is this done in parallel ?

Is not the assembly phase run by the AOT compiler ? which is called in parallel;


> * ditto for the strip phase.

Stripping is done in parallel. However I remember this did not help a lot small projects. It's likely that small assemblies are processed a lot faster than calling the tool itself.


> * the stripper loads assemblies using:
  assembly.MainModule.FullLoad ();
  which will load all IL code, which is discarded right after.

@JB is that needed ?


> * We should probably upgrade mono-cil-strip to the current cecil. Why is it using its own private copy ?

mono-cil-strip uses Cecil 0.6.x (not 0.9 or newer 1.0 betas) since it's the last version that could be use without modifying the metadata tokens, which the AOT compiler requires to remain constant. That's the reason it's stuck in the past with it's own copy of Cecil.

This is something I discussed with JB (ETL meeting). Cecil is not design to retain the original order/tokens, so the best option seems to investigate using System.Reflection.Metadata. However it means re-loading the same assemblies again into memory (or again hit the spawn cost).


Q: Zoltan, are you aware of the progress wrt https://bugzilla.xamarin.com/show_bug.cgi?id=43462 ? removing the calls to Collect would be better and safer than guessing the frequency required to avoid the bug.
Comment 18 Zoltan Varga 2017-04-06 03:32:33 UTC
So the low cpu usage was caused by the GC.Collect () calls.
Comment 19 Rolf Bjarne Kvinge [MSFT] 2017-04-06 06:49:25 UTC
(In reply to Zoltan Varga from comment #15)
> This is caused by this:
> https://github.com/xamarin/xamarin-macios/blob/
> 9f0fd32330e127b303874121f96c9e7d737c4297/tools/common/Driver.cs#L213
> 
> and similar code in multiple files.
> 
> If we want to keep this, we should do it every 10-20 process spawns, since
> mtouch has a 1gb heap due to cecil data structures.

We might not need the cecil data structures when these GC.Collect calls occur, so we might be able to just null those out and collect them all.
Comment 20 Zoltan Varga 2017-04-06 11:44:15 UTC
Still, doing 1 gc per process spawn is going to be slow.
Comment 21 Jb Evain 2017-04-06 15:54:37 UTC
Going through the cil-strip and old-cecil code, I think the FullLoad is not necessary. At least it's worth trying to remove.

An intermediate solution would be to have 1 process doing the cil-strip for all assemblies. We can modify cil-strip to take a list of assemblies to process.

I'll think about what we can do with Cecil 0.10 for this use case.
Comment 22 Sebastien Pouliot 2017-04-06 16:02:48 UTC
> At least it's worth trying to remove.

+1 :)

> An intermediate solution would be to have 1 process doing the cil-strip 

and strip in parallel from inside the tool ?

If not this might affect the build performance for smaller projects. Again worth adding, just not sure if it will be useful (or harmful) generally... but we have the choice to use it (or not).

> I'll think about what we can do with Cecil 0.10 for this use case.

Our discussion ended with the fact that strip is called on assemblies that might not have been re-written by Cecil - which makes it more than a "deterministic output" issue.

It would still be _ideal_ to have Cecil be able to _respect_ the original metadata tokens. In such case we could strip from mtouch itself (and the data already in memory) - no more spawning processes, no more reloading assembly data...
Comment 23 Sebastien Pouliot 2017-04-07 20:09:58 UTC
Since the original fix was a workaround for bug #43462 and this was fixed in C9 [1] then I think we can revert the GC.Collect calls in `master` and, time builds are confirmed, in `d15-2`.

@Alex please go ahead with a PR for master. We'll merge it unless other concerns are raised. 

Also please move the 2 other suggestions (strip and collect cecil data once not needed) to different bug reports (with links back here). Thanks!

[1] https://bugzilla.xamarin.com/show_bug.cgi?id=43462#c18
Comment 24 Alex Soto [MSFT] 2017-04-09 16:28:07 UTC
PR: https://github.com/xamarin/xamarin-macios/pull/1976
Comment 25 Alex Soto [MSFT] 2017-04-09 16:30:19 UTC
Project built with current master + PR 1976 patch

Time Elapsed 00:08:25.08
Comment 26 Rolf Bjarne Kvinge [MSFT] 2017-04-10 14:40:54 UTC
Fixed (master): https://github.com/xamarin/xamarin-macios/commit/2a85ec1674da63b2fd808b93721aafd9cbc3faed
Comment 27 Alex Soto [MSFT] 2017-04-10 18:42:11 UTC
Backported to dev15-2 https://github.com/xamarin/xamarin-macios/pull/1979
Comment 28 Timothy Risi 2017-04-13 18:05:14 UTC
*** Bug 55115 has been marked as a duplicate of this bug. ***
Comment 29 Aman Dharwal 2017-04-14 08:37:40 UTC
@Bill Hi, as this is a development related bug. kindly, verify it on your end or provide me steps to verify this.
Comment 30 Bill 2017-04-14 21:12:36 UTC
@Aman I will verify it once it reaches at least the alpha channel. Has the fix made it there?
Comment 31 Sebastien Pouliot 2017-04-14 21:48:40 UTC
@Bill yes, it's in our latest alpha. Anything with 10.10.0.6+ will have it. Again thanks for your help tracking this :)
Comment 32 Bill 2017-04-18 22:05:59 UTC
@Aman @Sebastien The latest alpha improved the build times back to about where they were. Thanks for your help!
Comment 33 Saurabh Paunikar 2017-05-05 06:13:52 UTC
@Bill can you please verify this issue and move it to verified state
Comment 34 Bill 2017-05-05 16:43:38 UTC
@Saurabh verified.
Comment 35 tmrog 2017-05-05 16:51:28 UTC
I am struggling with this slow build problem for devices (10-20 minutes builds) but when I tried to use the alpha channel in Xamarin Studio I got compiler errors for the extensions in my project.  See here: https://bugzilla.xamarin.com/show_bug.cgi?id=55736

Is there a path for me to get this fix?
Comment 36 tmrog 2017-06-26 14:07:05 UTC
I am not seeing this bug fixed.  In shat release will I find the fix?

I am running the latest stable channel and my iOS device builds are taking about 10 minutes to complete.

=== Visual Studio Community 2017 for Mac ===

Version 7.0.1 (build 24)
Installation UUID: 042b87d7-c3d5-4def-bf08-85f1e967d3a0
Runtime:
	Mono 5.0.1.1 (2017-02/5077205) (64-bit)
	GTK+ 2.24.23 (Raleigh theme)

	Package version: 500010001

=== NuGet ===

Version: 4.0.0.2323

=== .NET Core ===

Runtime: /usr/local/share/dotnet/dotnet
SDK: /usr/local/share/dotnet/sdk/1.0.3/Sdks
MSBuild SDKs: /Library/Frameworks/Mono.framework/Versions/5.0.1/lib/mono/msbuild/15.0/bin/Sdks

=== Xamarin.Profiler ===

Version: 1.5.4
Location: /Applications/Xamarin Profiler.app/Contents/MacOS/Xamarin Profiler

=== Xamarin.Android ===

Version: 7.3.1.2 (Visual Studio Community)
Android SDK: /Users/trs2/Library/Developer/Xamarin/android-sdk-macosx
	Supported Android versions:
		7.1 (API level 25)

SDK Tools Version: 26.0.2
SDK Platform Tools Version: 25.0.6
SDK Build Tools Version: 23.0.2

Java SDK: /usr
java version "1.8.0_101"
Java(TM) SE Runtime Environment (build 1.8.0_101-b13)
Java HotSpot(TM) 64-Bit Server VM (build 25.101-b13, mixed mode)

Android Designer EPL code available here:
https://github.com/xamarin/AndroidDesigner.EPL

=== Apple Developer Tools ===

Xcode 8.3 (12169)
Build 8E162

=== Xamarin.iOS ===

Version: 10.10.0.36 (Visual Studio Community)
Hash: d2270eec
Branch: d15-2
Build date: 2017-05-22 16:30:53-0400

=== Xamarin Inspector ===

Version: 1.2.2
Hash: b71b035
Branch: d15-1
Build date: Fri, 21 Apr 2017 17:57:12 GMT

=== Xamarin.Mac ===

Version: 3.4.0.36 (Visual Studio Community)

=== Build Information ===

Release ID: 700010024
Git revision: 7ab1ca2ced6f584e56b7a0d4d321d00775cd95c9
Build date: 2017-05-19 05:44:51-04
Xamarin addins: 08d17158f3365beee5e60f67999e607cce4b3f93
Build lane: monodevelop-lion-d15-2

=== Operating System ===

Mac OS X 10.12.5
Darwin 16.6.0 Darwin Kernel Version 16.6.0
    Fri Apr 14 16:21:16 PDT 2017
    root:xnu-3789.60.24~6/RELEASE_X86_64 x86_64
Comment 37 Rolf Bjarne Kvinge [MSFT] 2017-06-27 12:24:44 UTC
@tmrog, your problem might be different from the one that was reported in this bug, which means the fix would be different. Please file a new bug report, and we'll have a look at it.
Comment 38 tmrog 2017-06-27 16:27:11 UTC
I entered bug https://bugzilla.xamarin.com/show_bug.cgi?id=57791.  This is already been marked "Resolved/Answered" as expected behavior.  I don't think 10 minutes builds can ever be acceptable when a simulator build takes 16 seconds.

Note You need to log in before you can comment on or make changes to this bug.