Resolved [SOLVED] Addressables - long Editor reload times/play times

Short story

My codebase for an app grew, and after a while reload times and time to enter play mode took off.

Usually, I had 15-25 seconds of reload time. That time was usually to reload the C# code. After the Unity update from 2020.1.17f1 to 2020.2.6f1 and a few other changes (merge with features from other members of the team), my reloading times reached 4-6 minutes (instead of seconds).

We found that in our "feature specific" branches this never happened, but after merging this happens 50% of the time.

Findings

We found that hiccups happen before the addressable import process(?) logged as such

Code (Log):

1. Start importing Assets/ASSET.asset using Guid(101baa08c6b808345bb9806e6e3a9123) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'aee06ad2b1f25c524984d6ba54e9f136') in 0.001969 seconds

As you will see in the full log below, this happens twice, and two times it takes awfully long time, and for sure, not 0.0019 seconds it thinks it took.

This didn't happen before Unity/Addressabels update.

Also selecting Script Play mode does not have any impact on the time. We cannot use "Existing Build" but on "Use Asset Database" and "Simulate Groups" result is the same.
Note for "Simulate Groups": Sometimes we get a "progress bar" with insights, but it still takes a few minutes total, and the logs do not differ.

Questions

1. How can we measure the loading times better during reloading and whats happens underneath - Deep Editor Profilig do not offer any help
2. Is there a way to stop addressable reimport indexes, since we do not add/remove items, just modify them most of the time? It would be understandable to rebuild them after adding or removing them!
3. Is there anything we can do to go back to few seconds reload since with 5 minutes waiting time we can only do only a few play tests per hour.

Full log (added my comments after ####)

Code (Log):

1. ##### Play Clicked
2. Unloading 867 Unused Serialized files (Serialized files now loaded: 0)
3. Loaded scene 'Temp/__Backupscenes/0.backup'
4.     Deserialize:            2.009 ms
5.     Integration:            29.487 ms
6.     Integration of assets:  0.003 ms
7.     Thread Wait Time:       16.467 ms
8.     Total Operation Time:   47.966 ms
9. System memory in use before: 0.69 GB.
10. System memory in use after: 0.61 GB.
11.  
12. Unloading 2479 unused Assets to reduce memory usage. Loaded Objects now: 7789.
13. Total: 90.930400 ms (FindLiveObjects: 0.731400 ms CreateObjectMapping: 0.321700 ms MarkObjects: 86.840900 ms  DeleteObjects: 3.033200 ms)
14.  
15. [00:00:01] Enlighten: Builtin Sky manager started.
16. [00:00:02] Enlighten: Finished 1 Bake Ambient Probe job (0.01s execute, 0.00s integrate, 0.25s wallclock)
17. Start ondemand import (priority ImportantBackground): Assets/ASSET.asset (Guid(aff79445cf96ed04f8b2615a0b3feb92) Importer(815301076,1909f56bfc062723c751e8b465ee728b))
18. Start ondemand import (priority ImportantBackground): Assets/ASSET (Guid(c892e41609ee06c4a9b1d5ac4055785a) Importer(815301076,1909f56bfc062723c751e8b465ee728b))
19. Start ondemand import (priority ImportantBackground): Assets/ASSET.asset (Guid(e2f660666b0e5e049ad16280fee44593) Importer(815301076,1909f56bfc062723c751e8b465ee728b))
20. Start ondemand import (priority ImportantBackground): Assets/ASSET (Guid(c392d8c32b3a14441aee7fcb6bade918) Importer(815301076,1909f56bfc062723c751e8b465ee728b))
21. Start ondemand import (priority ImportantBackground): Assets/ASSET.asset (Guid(25b3cb75f00d22b4c975725d639a64ec) Importer(815301076,1909f56bfc062723c751e8b465ee728b))
22. ##### It takes 3-4 seconds to get to this place
23. ##### After that, we need to wait around 90-120 seconds to get any further logs
24. Start importing Assets/ASSET.asset using Guid(101baa08c6b808345bb9806e6e3a9123) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'aee06ad2b1f25c524984d6ba54e9f136') in 0.001969 seconds
25. Start importing Assets/ASSET.asset using Guid(25f3025f665a631409566c0eb1329508) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'fc8e7d9efddd29f65b2eb7666a744d86') in 0.001423 seconds
26. Start importing Assets/ASSET.asset using Guid(b6de37d3d1602b24ea5732c9e37929b4) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'c0f91c8e4c69f0490083e9dd0528bc59') in 0.001549 seconds
27. Start importing Assets/ASSET.asset using Guid(c70070d110fb9b441ae694078bc722ed) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'e64d46c505b6bb4f88f2bb684ad271fb') in 0.001498 seconds
28. Start importing Assets/ASSET.asset using Guid(a89e0ee327012114ebf4b8d66c9d1000) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '8bc4735101f9e983a8c897ba0ec4bde2') in 0.001495 seconds
29. Start importing Assets/ASSET.asset using Guid(b8400f786547b7c4db5b8c4daa1a75bf) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'dabeaf1d3c83806ede54d0fc4e519e6c') in 0.001483 seconds
30. Start importing Assets/ASSET.asset using Guid(d8ef62463fe5b5e4a944c8e9644b7f31) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '9036cac8550b7e3e660c8442b350d178') in 0.001452 seconds
31. Start importing Assets/ASSET.asset using Guid(1a1ec2fdcd7e95341bb5d81dc7e6b363) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '769f4228a99dba4a1887830713ece1aa') in 0.001438 seconds
32. Start importing Assets/ASSET.asset using Guid(cdb922c53f96bd2489c7fade349c5bb0) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '74e59e493872937e7362c7560186cd81') in 0.001585 seconds
33. Refreshing native plugins compatible for Editor in 1.70 ms, found 4 plugins.
34. Preloading 1 native plugins for Editor in 0.07 ms.
35. RefreshInfo: StopAssetImportingV2(NoUpdateAssetOptions) scanfilter:
36. RefreshProfiler: Total: 1942.313ms
37.     InvokeBeforeRefreshCallbacks: 0.001ms
38.     ApplyChangesToAssetFolders: 0.072ms
39.     Scan: 2.168ms
40.     OnSourceAssetsModified: 0.000ms
41.     InitializeImportedAssetsSnapshot: 8.190ms
42.     GetAllGuidsForCategorization: 0.529ms
43.     CategorizeAssets: 94.674ms
44.     ImportAndPostprocessOutOfDateAssets: 1685.154ms (3.986ms without children)
45.         ImportManagerImport: 24.448ms (2.449ms without children)
46.             ImportInProcess: 21.903ms
47.             UpdateCategorizedAssets: 0.096ms
48.         PostProcessAllAssets: 1644.553ms
49.         ReloadImportedAssets: 0.004ms
50.         EnsureUptoDateAssetsAreRegisteredWithGuidPM: 0.904ms
51.         InitializingProgressBar: 0.003ms
52.         PostProcessAllAssetNotificationsAddChangedAssets: 0.528ms
53.         OnDemandSchedulerStart: 0.466ms
54.         RestoreLoadedAssetsState: 3.584ms
55.     UpdateImportedAssetsSnapshot: 6.679ms
56.     ReloadSourceAssets: 1.913ms
57.     UnloadImportedAssets: 0.315ms
58.     Hotreload: 9.112ms
59.     FixTempGuids: 0.007ms
60.     GatherAllCurrentPrimaryArtifactRevisions: 0.408ms
61.     UnloadStreamsBegin: 0.595ms
62.     LoadedImportedAssetsSnapshotReleaseGCHandles: 2.039ms
63.     GetLoadedSourceAssetsSnapshot: 8.362ms
64.     PersistCurrentRevisions: 0.338ms
65.     UnloadStreamsEnd: 0.699ms
66.     GenerateScriptTypeHashes: 7.094ms
67.     Untracked: 127.737ms
68. Opening scene 'Assets/Scenes/Launcher.unity'
69. Unloading 0 Unused Serialized files (Serialized files now loaded: 0)
70. Loaded scene 'Assets/Scenes/Launcher.unity'
71.     Deserialize:            1.303 ms
72.     Integration:            45.269 ms
73.     Integration of assets:  0.003 ms
74.     Thread Wait Time:       18.390 ms
75.     Total Operation Time:   64.965 ms
76. System memory in use before: 273.8 MB.
77. System memory in use after: 274.3 MB.
78.  
79. Unloading 101 unused Assets to reduce memory usage. Loaded Objects now: 7894.
80. Total: 95.426400 ms (FindLiveObjects: 0.853400 ms CreateObjectMapping: 0.598600 ms MarkObjects: 93.904300 ms  DeleteObjects: 0.068000 ms)
81.  
82. Reloading assemblies for play mode.
83. Begin MonoManager ReloadAssembly
84. Native extension for WindowsStandalone target not found
85. Native extension for Android target not found
86. Native extension for WebGL target not found
87. Refreshing native plugins compatible for Editor in 9.29 ms, found 4 plugins.
88. Preloading 1 native plugins for Editor in 0.05 ms.
89. RefreshInfo: StopAssetImportingV2(NoUpdateAssetOptions) scanfilter:
90. RefreshProfiler: Total: 46.703ms
91. ##### To this place after waiting we get "instant" and next we have another "waiting"
92. Start importing Assets/ASSET.asset using Guid(101baa08c6b808345bb9806e6e3a9123) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'aee06ad2b1f25c524984d6ba54e9f136') in 0.011188 seconds
93. Start importing Assets/ASSET.asset using Guid(25f3025f665a631409566c0eb1329508) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'fc8e7d9efddd29f65b2eb7666a744d86') in 0.001454 seconds
94. Start importing Assets/ASSET.asset using Guid(b6de37d3d1602b24ea5732c9e37929b4) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'c0f91c8e4c69f0490083e9dd0528bc59') in 0.001487 seconds
95. Start importing Assets/ASSET.asset using Guid(c70070d110fb9b441ae694078bc722ed) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'e64d46c505b6bb4f88f2bb684ad271fb') in 0.001327 seconds
96. Start importing Assets/ASSET.asset using Guid(a89e0ee327012114ebf4b8d66c9d1000) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '8bc4735101f9e983a8c897ba0ec4bde2') in 0.001314 seconds
97. Start importing Assets/ASSET.asset using Guid(b8400f786547b7c4db5b8c4daa1a75bf) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'dabeaf1d3c83806ede54d0fc4e519e6c') in 0.001435 seconds
98. Start importing Assets/ASSET.asset using Guid(d8ef62463fe5b5e4a944c8e9644b7f31) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '9036cac8550b7e3e660c8442b350d178') in 0.001469 seconds
99. Start importing Assets/ASSET.asset using Guid(1a1ec2fdcd7e95341bb5d81dc7e6b363) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '769f4228a99dba4a1887830713ece1aa') in 0.001453 seconds
100. Start importing Assets/ASSET.asset using Guid(cdb922c53f96bd2489c7fade349c5bb0) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '74e59e493872937e7362c7560186cd81') in 0.001528 seconds
101. Refreshing native plugins compatible for Editor in 1.45 ms, found 4 plugins.
102. Preloading 1 native plugins for Editor in 0.07 ms.
103. RefreshInfo: StopAssetImportingV2(NoUpdateAssetOptions) scanfilter:
104. RefreshProfiler: Total: 1928.100ms
105.     InvokeBeforeRefreshCallbacks: 0.001ms
106.     ApplyChangesToAssetFolders: 0.072ms
107.     Scan: 2.120ms
108.     OnSourceAssetsModified: 0.000ms
109.     InitializeImportedAssetsSnapshot: 8.353ms
110.     GetAllGuidsForCategorization: 0.488ms
111.     CategorizeAssets: 4.435ms
112.     ImportAndPostprocessOutOfDateAssets: 1855.700ms (3.791ms without children)
113.         ImportManagerImport: 38.216ms (6.843ms without children)
114.             ImportInProcess: 31.280ms
115.             UpdateCategorizedAssets: 0.093ms
116.         PostProcessAllAssets: 1801.711ms
117.         ReloadImportedAssets: 0.003ms
118.         EnsureUptoDateAssetsAreRegisteredWithGuidPM: 1.114ms
119.         InitializingProgressBar: 0.003ms
120.         PostProcessAllAssetNotificationsAddChangedAssets: 0.583ms
121.         OnDemandSchedulerStart: 0.360ms
122.         RestoreLoadedAssetsState: 4.055ms
123.     UpdateImportedAssetsSnapshot: 5.864ms
124.     ReloadSourceAssets: 2.014ms
125.     UnloadImportedAssets: 0.300ms
126.     Hotreload: 3.242ms
127.     FixTempGuids: 0.006ms
128.     GatherAllCurrentPrimaryArtifactRevisions: 0.416ms
129.     UnloadStreamsBegin: 0.048ms
130.     LoadedImportedAssetsSnapshotReleaseGCHandles: 1.669ms
131.     GetLoadedSourceAssetsSnapshot: 7.557ms
132.     PersistCurrentRevisions: 0.292ms
133.     UnloadStreamsEnd: 0.116ms
134.     Untracked: 41.270ms
135. [App Center EdEx MSG965] Created missing AppCenterEditorPrefsSO file
136. UnityEngine.StackTraceUtility:ExtractStackTrace ()
137. UnityEngine.DebugLogHandler:LogFormat (UnityEngine.LogType,UnityEngine.Object,string,object[])
138. UnityEngine.Logger:Log (UnityEngine.LogType,object)
139. UnityEngine.Debug:Log (object)
140. AppCenterEditor.LocalLogger:LogWithTimeStamp (string) (at Assets/Scripts/Thirdparty/AppCenterEditorExtensions/Editor/Scripts/Utils/LocalLogger.cs:10)
141. AppCenterEditor.AppCenterEditorPrefsSO:get_Instance () (at Assets/Scripts/Thirdparty/AppCenterEditorExtensions/Editor/Scripts/Utils/AppCenterEditorPrefsSO.cs:91)
142. AppCenterEditor.AppCenterEditor/Startup:.cctor () (at Assets/Scripts/Thirdparty/AppCenterEditorExtensions/Editor/AppCenterEditor.cs:87)
143. System.Runtime.CompilerServices.RuntimeHelpers:RunClassConstructor (System.RuntimeTypeHandle)
144. UnityEditor.EditorAssemblies:ProcessInitializeOnLoadAttributes (System.Type[])
145.  
146. (Filename: Assets/Scripts/Thirdparty/AppCenterEditorExtensions/Editor/Scripts/Utils/LocalLogger.cs Line: 10)
147.  
148. Invoked RoslynAnalysisRunner static constructor.
149. RoslynAnalysisRunner will not be running.
150. RoslynAnalysisRunner has terminated.
151. [MODES] ModeService[none].Initialize
152. [MODES] ModeService[none].LoadModes
153. [MODES] Loading mode Default (0) for mode-current-id-TownCountryUnity
154. Mono: successfully reloaded assembly
155. - Completed reload, in 145.747 seconds
156. Platform modules already initialized, skipping
157. [Subsystems] Loading plugin ARSimulationPlugin for subsystem arsimulation-meshing...
158. Loaded scene 'Temp/__Backupscenes/0.backup'
159.     Deserialize:            2.732 ms
160.     Integration:            107.236 ms
161.     Integration of assets:  0.004 ms
162.     Thread Wait Time:       15.420 ms
163.     Total Operation Time:   125.393 ms
164. LightingSettings: switching bake backend from 1 to 2.
165. [MODES] ModeService[default].RefreshMenus
166. [MODES] ModeService[default].UpdateModeMenus
167. Loaded scene 'Assets/Scenes/Launcher_Data/CameraCapturesScene.unity'
168. ##### Total reload time --- 5 minutes

Project specification:
- com.unity.addressables from "1.16.16" to "1.17.6-preview"
- com.unity.scriptablebuildpipeline from "1.15.2" to "1.16.1"
- Unity Editor 2020.2.6f1 and 2020.2.7f1

 

@TreyK-47 Thanks for notifying the team. But I will note that I found the issue - this might be relevant to fix or not since this was my team's mistake.

The issue was caused by this code that ran on a few "big" scenes and was attached to on-play state changed. Since every time this method marked addressableSettings as Dirty, it took him 5 minutes to process them for each recompile.

The issue is gone, once we added additional checks to prevent "re-adding" asset that was already marked as addressable

Code (CSharp):

1.  
2. public static AddressableAssetEntry CreateAssetEntry<T>(this T source, string groupName) where T : Object
3. {
4.     if (source == null || string.IsNullOrEmpty(groupName) || !AssetDatabase.Contains(source))
5.     {
6.         return null;
7.     }
8.  
9.     var addressableSettings = AddressableAssetSettingsDefaultObject.Settings;
10.     var sourcePath = AssetDatabase.GetAssetPath(source);
11.     var sourceGuid = AssetDatabase.AssetPathToGUID(sourcePath);
12.     var group = !GroupExists(groupName)
13.         ? CreateGroup(groupName)
14.         : GetGroup(groupName);
15.  
16.     var entry = addressableSettings.CreateOrMoveEntry(sourceGuid, group);
17.     entry.address = sourcePath;
18.  
19.     addressableSettings.SetDirty(AddressableAssetSettings.ModificationEvent.EntryMoved, entry, true);
20.  
21.     return entry;
22. }
23.