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

Unity Engine
, , ,
1

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

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 ####)

##### Play Clicked
Unloading 867 Unused Serialized files (Serialized files now loaded: 0)
Loaded scene 'Temp/__Backupscenes/0.backup'
    Deserialize:            2.009 ms
    Integration:            29.487 ms
    Integration of assets:  0.003 ms
    Thread Wait Time:       16.467 ms
    Total Operation Time:   47.966 ms
System memory in use before: 0.69 GB.
System memory in use after: 0.61 GB.

Unloading 2479 unused Assets to reduce memory usage. Loaded Objects now: 7789.
Total: 90.930400 ms (FindLiveObjects: 0.731400 ms CreateObjectMapping: 0.321700 ms MarkObjects: 86.840900 ms  DeleteObjects: 3.033200 ms)

[00:00:01] Enlighten: Builtin Sky manager started.
[00:00:02] Enlighten: Finished 1 Bake Ambient Probe job (0.01s execute, 0.00s integrate, 0.25s wallclock)
Start ondemand import (priority ImportantBackground): Assets/ASSET.asset (Guid(aff79445cf96ed04f8b2615a0b3feb92) Importer(815301076,1909f56bfc062723c751e8b465ee728b))
Start ondemand import (priority ImportantBackground): Assets/ASSET (Guid(c892e41609ee06c4a9b1d5ac4055785a) Importer(815301076,1909f56bfc062723c751e8b465ee728b))
Start ondemand import (priority ImportantBackground): Assets/ASSET.asset (Guid(e2f660666b0e5e049ad16280fee44593) Importer(815301076,1909f56bfc062723c751e8b465ee728b))
Start ondemand import (priority ImportantBackground): Assets/ASSET (Guid(c392d8c32b3a14441aee7fcb6bade918) Importer(815301076,1909f56bfc062723c751e8b465ee728b))
Start ondemand import (priority ImportantBackground): Assets/ASSET.asset (Guid(25b3cb75f00d22b4c975725d639a64ec) Importer(815301076,1909f56bfc062723c751e8b465ee728b))
##### It takes 3-4 seconds to get to this place
##### After that, we need to wait around 90-120 seconds to get any further logs
Start importing Assets/ASSET.asset using Guid(101baa08c6b808345bb9806e6e3a9123) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'aee06ad2b1f25c524984d6ba54e9f136') in 0.001969 seconds
Start importing Assets/ASSET.asset using Guid(25f3025f665a631409566c0eb1329508) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'fc8e7d9efddd29f65b2eb7666a744d86') in 0.001423 seconds
Start importing Assets/ASSET.asset using Guid(b6de37d3d1602b24ea5732c9e37929b4) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'c0f91c8e4c69f0490083e9dd0528bc59') in 0.001549 seconds
Start importing Assets/ASSET.asset using Guid(c70070d110fb9b441ae694078bc722ed) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'e64d46c505b6bb4f88f2bb684ad271fb') in 0.001498 seconds
Start importing Assets/ASSET.asset using Guid(a89e0ee327012114ebf4b8d66c9d1000) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '8bc4735101f9e983a8c897ba0ec4bde2') in 0.001495 seconds
Start importing Assets/ASSET.asset using Guid(b8400f786547b7c4db5b8c4daa1a75bf) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'dabeaf1d3c83806ede54d0fc4e519e6c') in 0.001483 seconds
Start importing Assets/ASSET.asset using Guid(d8ef62463fe5b5e4a944c8e9644b7f31) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '9036cac8550b7e3e660c8442b350d178') in 0.001452 seconds
Start importing Assets/ASSET.asset using Guid(1a1ec2fdcd7e95341bb5d81dc7e6b363) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '769f4228a99dba4a1887830713ece1aa') in 0.001438 seconds
Start importing Assets/ASSET.asset using Guid(cdb922c53f96bd2489c7fade349c5bb0) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '74e59e493872937e7362c7560186cd81') in 0.001585 seconds
Refreshing native plugins compatible for Editor in 1.70 ms, found 4 plugins.
Preloading 1 native plugins for Editor in 0.07 ms.
RefreshInfo: StopAssetImportingV2(NoUpdateAssetOptions) scanfilter:
RefreshProfiler: Total: 1942.313ms
    InvokeBeforeRefreshCallbacks: 0.001ms
    ApplyChangesToAssetFolders: 0.072ms
    Scan: 2.168ms
    OnSourceAssetsModified: 0.000ms
    InitializeImportedAssetsSnapshot: 8.190ms
    GetAllGuidsForCategorization: 0.529ms
    CategorizeAssets: 94.674ms
    ImportAndPostprocessOutOfDateAssets: 1685.154ms (3.986ms without children)
        ImportManagerImport: 24.448ms (2.449ms without children)
            ImportInProcess: 21.903ms
            UpdateCategorizedAssets: 0.096ms
        PostProcessAllAssets: 1644.553ms
        ReloadImportedAssets: 0.004ms
        EnsureUptoDateAssetsAreRegisteredWithGuidPM: 0.904ms
        InitializingProgressBar: 0.003ms
        PostProcessAllAssetNotificationsAddChangedAssets: 0.528ms
        OnDemandSchedulerStart: 0.466ms
        RestoreLoadedAssetsState: 3.584ms
    UpdateImportedAssetsSnapshot: 6.679ms
    ReloadSourceAssets: 1.913ms
    UnloadImportedAssets: 0.315ms
    Hotreload: 9.112ms
    FixTempGuids: 0.007ms
    GatherAllCurrentPrimaryArtifactRevisions: 0.408ms
    UnloadStreamsBegin: 0.595ms
    LoadedImportedAssetsSnapshotReleaseGCHandles: 2.039ms
    GetLoadedSourceAssetsSnapshot: 8.362ms
    PersistCurrentRevisions: 0.338ms
    UnloadStreamsEnd: 0.699ms
    GenerateScriptTypeHashes: 7.094ms
    Untracked: 127.737ms
Opening scene 'Assets/Scenes/Launcher.unity'
Unloading 0 Unused Serialized files (Serialized files now loaded: 0)
Loaded scene 'Assets/Scenes/Launcher.unity'
    Deserialize:            1.303 ms
    Integration:            45.269 ms
    Integration of assets:  0.003 ms
    Thread Wait Time:       18.390 ms
    Total Operation Time:   64.965 ms
System memory in use before: 273.8 MB.
System memory in use after: 274.3 MB.

Unloading 101 unused Assets to reduce memory usage. Loaded Objects now: 7894.
Total: 95.426400 ms (FindLiveObjects: 0.853400 ms CreateObjectMapping: 0.598600 ms MarkObjects: 93.904300 ms  DeleteObjects: 0.068000 ms)

Reloading assemblies for play mode.
Begin MonoManager ReloadAssembly
Native extension for WindowsStandalone target not found
Native extension for Android target not found
Native extension for WebGL target not found
Refreshing native plugins compatible for Editor in 9.29 ms, found 4 plugins.
Preloading 1 native plugins for Editor in 0.05 ms.
RefreshInfo: StopAssetImportingV2(NoUpdateAssetOptions) scanfilter:
RefreshProfiler: Total: 46.703ms
##### To this place after waiting we get "instant" and next we have another "waiting"
Start importing Assets/ASSET.asset using Guid(101baa08c6b808345bb9806e6e3a9123) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'aee06ad2b1f25c524984d6ba54e9f136') in 0.011188 seconds
Start importing Assets/ASSET.asset using Guid(25f3025f665a631409566c0eb1329508) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'fc8e7d9efddd29f65b2eb7666a744d86') in 0.001454 seconds
Start importing Assets/ASSET.asset using Guid(b6de37d3d1602b24ea5732c9e37929b4) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'c0f91c8e4c69f0490083e9dd0528bc59') in 0.001487 seconds
Start importing Assets/ASSET.asset using Guid(c70070d110fb9b441ae694078bc722ed) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'e64d46c505b6bb4f88f2bb684ad271fb') in 0.001327 seconds
Start importing Assets/ASSET.asset using Guid(a89e0ee327012114ebf4b8d66c9d1000) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '8bc4735101f9e983a8c897ba0ec4bde2') in 0.001314 seconds
Start importing Assets/ASSET.asset using Guid(b8400f786547b7c4db5b8c4daa1a75bf) Importer(-1,00000000000000000000000000000000)  -> (artifact id: 'dabeaf1d3c83806ede54d0fc4e519e6c') in 0.001435 seconds
Start importing Assets/ASSET.asset using Guid(d8ef62463fe5b5e4a944c8e9644b7f31) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '9036cac8550b7e3e660c8442b350d178') in 0.001469 seconds
Start importing Assets/ASSET.asset using Guid(1a1ec2fdcd7e95341bb5d81dc7e6b363) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '769f4228a99dba4a1887830713ece1aa') in 0.001453 seconds
Start importing Assets/ASSET.asset using Guid(cdb922c53f96bd2489c7fade349c5bb0) Importer(-1,00000000000000000000000000000000)  -> (artifact id: '74e59e493872937e7362c7560186cd81') in 0.001528 seconds
Refreshing native plugins compatible for Editor in 1.45 ms, found 4 plugins.
Preloading 1 native plugins for Editor in 0.07 ms.
RefreshInfo: StopAssetImportingV2(NoUpdateAssetOptions) scanfilter:
RefreshProfiler: Total: 1928.100ms
    InvokeBeforeRefreshCallbacks: 0.001ms
    ApplyChangesToAssetFolders: 0.072ms
    Scan: 2.120ms
    OnSourceAssetsModified: 0.000ms
    InitializeImportedAssetsSnapshot: 8.353ms
    GetAllGuidsForCategorization: 0.488ms
    CategorizeAssets: 4.435ms
    ImportAndPostprocessOutOfDateAssets: 1855.700ms (3.791ms without children)
        ImportManagerImport: 38.216ms (6.843ms without children)
            ImportInProcess: 31.280ms
            UpdateCategorizedAssets: 0.093ms
        PostProcessAllAssets: 1801.711ms
        ReloadImportedAssets: 0.003ms
        EnsureUptoDateAssetsAreRegisteredWithGuidPM: 1.114ms
        InitializingProgressBar: 0.003ms
        PostProcessAllAssetNotificationsAddChangedAssets: 0.583ms
        OnDemandSchedulerStart: 0.360ms
        RestoreLoadedAssetsState: 4.055ms
    UpdateImportedAssetsSnapshot: 5.864ms
    ReloadSourceAssets: 2.014ms
    UnloadImportedAssets: 0.300ms
    Hotreload: 3.242ms
    FixTempGuids: 0.006ms
    GatherAllCurrentPrimaryArtifactRevisions: 0.416ms
    UnloadStreamsBegin: 0.048ms
    LoadedImportedAssetsSnapshotReleaseGCHandles: 1.669ms
    GetLoadedSourceAssetsSnapshot: 7.557ms
    PersistCurrentRevisions: 0.292ms
    UnloadStreamsEnd: 0.116ms
    Untracked: 41.270ms
[App Center EdEx MSG965] Created missing AppCenterEditorPrefsSO file
UnityEngine.StackTraceUtility:ExtractStackTrace ()
UnityEngine.DebugLogHandler:LogFormat (UnityEngine.LogType,UnityEngine.Object,string,object[])
UnityEngine.Logger:Log (UnityEngine.LogType,object)
UnityEngine.Debug:Log (object)
AppCenterEditor.LocalLogger:LogWithTimeStamp (string) (at Assets/Scripts/Thirdparty/AppCenterEditorExtensions/Editor/Scripts/Utils/LocalLogger.cs:10)
AppCenterEditor.AppCenterEditorPrefsSO:get_Instance () (at Assets/Scripts/Thirdparty/AppCenterEditorExtensions/Editor/Scripts/Utils/AppCenterEditorPrefsSO.cs:91)
AppCenterEditor.AppCenterEditor/Startup:.cctor () (at Assets/Scripts/Thirdparty/AppCenterEditorExtensions/Editor/AppCenterEditor.cs:87)
System.Runtime.CompilerServices.RuntimeHelpers:RunClassConstructor (System.RuntimeTypeHandle)
UnityEditor.EditorAssemblies:ProcessInitializeOnLoadAttributes (System.Type[])

(Filename: Assets/Scripts/Thirdparty/AppCenterEditorExtensions/Editor/Scripts/Utils/LocalLogger.cs Line: 10)

Invoked RoslynAnalysisRunner static constructor.
RoslynAnalysisRunner will not be running.
RoslynAnalysisRunner has terminated.
[MODES] ModeService[none].Initialize
[MODES] ModeService[none].LoadModes
[MODES] Loading mode Default (0) for mode-current-id-TownCountryUnity
Mono: successfully reloaded assembly
- Completed reload, in 145.747 seconds
Platform modules already initialized, skipping
[Subsystems] Loading plugin ARSimulationPlugin for subsystem arsimulation-meshing...
Loaded scene 'Temp/__Backupscenes/0.backup'
    Deserialize:            2.732 ms
    Integration:            107.236 ms
    Integration of assets:  0.004 ms
    Thread Wait Time:       15.420 ms
    Total Operation Time:   125.393 ms
LightingSettings: switching bake backend from 1 to 2.
[MODES] ModeService[default].RefreshMenus
[MODES] ModeService[default].UpdateModeMenus
Loaded scene 'Assets/Scenes/Launcher_Data/CameraCapturesScene.unity'
##### 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
1 Like
2

I’ll flag this for the team to have a look!

3

@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

public static AddressableAssetEntry CreateAssetEntry<T>(this T source, string groupName) where T : Object
{
    if (source == null || string.IsNullOrEmpty(groupName) || !AssetDatabase.Contains(source))
    {
        return null;
    }

    var addressableSettings = AddressableAssetSettingsDefaultObject.Settings;
    var sourcePath = AssetDatabase.GetAssetPath(source);
    var sourceGuid = AssetDatabase.AssetPathToGUID(sourcePath);
    var group = !GroupExists(groupName)
        ? CreateGroup(groupName)
        : GetGroup(groupName);

    var entry = addressableSettings.CreateOrMoveEntry(sourceGuid, group);
    entry.address = sourcePath;

    addressableSettings.SetDirty(AddressableAssetSettings.ModificationEvent.EntryMoved, entry, true);

    return entry;
}
2 Likes