Loading current level is broken in packaged builds

[krojew]

When loading a game in the same level as the current one, the engine loads the default map in packaged builds. The reason seems to be that the current world gets unloaded from its package, which results in engine not finding it during travel and browsing to the default map as a fallback. A workaround is to load a temporary level first and then perform game loading.

[sinbad]

I thought that #101 dealt with this?

[krojew]

Maybe it fixed some of the cases, but not everything. I simply do a quick save/quick load combo and it's 100% reproducible. @YeNov can you take a look?

[krojew]

After some debugging, it looks like even when keeping a hard reference to the world, as introduced in that fix, it still gets GC'd.

[krojew]

Found the cause of GC - UEngine::LoadMap() calls UWorld::MarkObjectsPendingKill() which marks the world as garbage. Using a property won't help.

[sinbad]

This must have changed at some point because I never used to have this problem in packaged builds for the game I wrote SPUD for (I don't currently use it because we don't have level save state in our new game)

[YeNov]

Hello @krojew . Sorry for not answering for that long, got a bit busy. What you say totally makes sense - world and levels are marked as garbage logically (RF_MirroredGarbage). Though it doesn't fire in my current use-cases, it could've potentially. I tried to do several fast loads from the same level, but it never crashed on the Dev build. I want to try it in shipment, but it will take some time. What is your build config?
Also I remember having similar-ish issue, when trying to load an object which was marked for GC (dialogue scene) and there's a pretty specific way of triggering it - simulating a scarce of resources (or just run the game on any console dev kit). May I ask what is your memory load (RAM) in the moment of loading the game?
UPD: nope, on the shipping build it does not fail either.

[krojew]

@YeNov we should not rely on GC not triggering to be able to load the map. This will sometimes work, other times not, as in my tests. I'm wondering if this can be an engine bug, because it's now impossible to reload current level reliably, regardless of using SPUD or not. If you have access to UDN, can you ask Epic directly?

[YeNov]

@krojew never meant to say we can rely on it, just an observation. I can do the UDN post. It would also help if I included your answers to the questions I posted above. It could be helpful to gather more information to question Epics

[krojew]

@YeNov at the moment of loading I have around 40-50GB RAM free. I'm not sure what parts of build config you need - it's happening on development and debug Windows builds. Do you need any specific settings?

[YeNov]

Hey @krojew , I brought you some news from UDN
The quickest fix would be using "GDelayTrimMemoryDuringMapLoadMode 2" .

// Should we TrimMemory in the middle of LoadMap - this can reduce memory spike during startup at the expense of load time 
// if some objects need to be reloaded due to a GC happening partway through
int32 GDelayTrimMemoryDuringMapLoadMode = 0;
static FAutoConsoleVariableRef GDelayTrimMemoryDuringMapLoadModeCVar(
	TEXT("Engine.DelayTrimMemoryDuringMapLoadMode"),
	GDelayTrimMemoryDuringMapLoadMode,
	TEXT("0: TrimMemory during LoadMap as normal\n")
	TEXT("1: Delay TrimMemory until the end of LoadMap (initial boot up)\n")
	TEXT("2: Delay TrimMemory in _every_ LoadMap call"),
	ECVF_Default
);

The var controls whether a full garbage collection pass is done in-between the current map being unloaded and the new map being loaded (this would allow the map to be loaded cleanly. Also they mentioned using hard reference to the packages one want to keep from being GCd. The hard references should be kept in something that survives map travel lifecycle ofc (like spud subsystem, which is game instance subsystem).
Also they question to provide some additional info so they could investigate it thoroughly.

I also want to investigate in how far 'failing to reload current map' affects projects with default settings. Can you provide the following info?

What's your current value for GDelayTrimMemoryDuringMapLoadMode?
What's your level setup - using world partition? Level Instances? Sub levels?
Are you using the experimental Incremental Garbage Collection feature?
Have you been able to reproduce the bug in a fresh project, like ThirdPersonTemplate? Just making sure if your repro steps will lead to a repro or are theoretical, because project settings may be important to repro.
Do your log files show any warnings/errors that may hint at what exactly goes wrong?

[krojew]

@YeNov I tried setting GDelayTrimMemoryDuringMapLoadModeCVar to 2, but then it crashes GameplayDebuggerModule on map load, unfortunately. Looks like this is another engine bug:

[2024.11.06-14.31.41:619][539]LogWindows: Error: Assertion failed: ManagerOb [File:D:\build\++UE5\Sync\Engine\Source\Runtime\GameplayDebugger\Private\GameplayDebuggerModule.cpp] [Line: 136] 
[2024.11.06-14.31.41:619][539]LogWindows: Error: 
[2024.11.06-14.31.41:619][539]LogWindows: Error: 
[2024.11.06-14.31.41:619][539]LogWindows: Error: 
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff614a31961 xxx.exe!FGameplayDebuggerModule::GetPlayerManager() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff614a3c3a8 xxx.exe!FGameplayDebuggerModule::OnWorldInitialized() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff614a30011 xxx.exe!TBaseRawMethodDelegateInstance<0,FGameplayDebuggerModule,void __cdecl(UWorld * __ptr64,FWorldInitializationValues),FDefaultDelegateUserPolicy>::ExecuteIfSafe() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff614679f0d xxx.exe!TMulticastDelegateBase<FDefaultDelegateUserPolicy>::Broadcast<IBaseDelegateInstance<void __cdecl(UWorld * __ptr64,FWorldInitializationValues),FDefaultDelegateUserPolicy>,UWorld * __ptr64,FWorldInitializationValues>() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff6146af496 xxx.exe!UWorld::InitWorld() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff61454c762 xxx.exe!UEngine::LoadMap() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff6144cf225 xxx.exe!UEngine::Browse() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff6145892cf xxx.exe!UEngine::TickWorldTravel() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff6136fec60 xxx.exe!UGameEngine::Tick() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff614d5f9ca xxx.exe!FEngineLoop::Tick() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff614d77d1c xxx.exe!GuardedMain() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff614d77dea xxx.exe!GuardedMainWrapper() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff614d7a9b5 xxx.exe!LaunchWindowsStartup() []
[2024.11.06-14.31.41:619][539]LogWindows: Error: [Callstack] 0x00007ff614d8ac94 xxx.exe!WinMain() []

To answer the questions:

What's your current value for GDelayTrimMemoryDuringMapLoadMode?

0

What's your level setup - using world partition? Level Instances? Sub levels?

World partition; nothing else.

Are you using the experimental Incremental Garbage Collection feature?

No.

Do your log files show any warnings/errors that may hint at what exactly goes wrong?

There's no error and I don't think this should be treated as such - it's a normal flow in the engine. The world is marked as garbage explicitly, GC runs, and then the problem occurs.

[krojew]

@YeNov I don't know if it's important, but I'm using the CommonLoadingScreen plugin.

[YeNov]

Hey @krojew , coming back to you. I have no knowledge about CommonLoadingScreen plugin, have you tried without it? Do you have reproducibility only on your PC or other computers also have it? We have like 5 different computers and no crashes since my fix (hard reference property + long path name) is provided. I want to speculate that maybe having hard reference to a pending kill object blocks GC, even though the object is removed from the root set. Maybe you have something else that could break GC on your side?

Also epics asked me to provide some info which I cannot, as my version doesn't crash, so maybe you could help with that:

You haven't shared errors or warnings, but I'd expect something in the logs that hints to why the map fails to load. Is there anything? Otherwise can you investigate and share back with us the following info.

Which code branch in UEngine::Browse is it returning the EBrowseReturnVal::Failure value? Alternatively what is the failure message returned by Browse? This should be printed if you enable the log category LogGlobalStatus.
Enabling log category LogUObjectGlobals may also reveal some relevant information, if the root cause is related to occupied UObject path names. If some objects are alive that the map reload are trying to create as well, that could be causing failures.

[krojew]

I'll try without the plugin later, but it's made by Epic for Lyra, so I would assume it should work. As for the errors - there are none, because the error message is ignored:

1. UEngine::Browse() calls UEngine::LoadMap().
2. UEngine::LoadMap() calls CastChecked<UWorld>(Level->GetOuter())->MarkObjectsPendingKill(); which marks the world as garbage.
3. Later we have:

        if (GDelayTrimMemoryDuringMapLoadMode == 0)
	{
		TrimMemory();
	}

That GC's the world.
4. Then it tries to find the world in package: NewWorld = UWorld::FindWorldInPackage(WorldPackage);. This fails, since the world is no longer loaded. It also sets the error message, which gets ignored later.
5. UEngine::LoadMap() returns false which causes UEngine::Browse() to go to HandleBrowseToDefaultMapFailure(). This loads the default map and then Browse() exits with an error. The error message never gets printed, but it's quite useless: FString::Printf(TEXT("Failed to load package '%s'"), *URL.Map);.

Can you forward this to Epic?

[YeNov]

Thx, I'll forward it to them