Cook Warning that Cooker has been blocked from saving the current package

Hi,

Ever since moving to 5.7 we are starting to experience a new warning on our build machine that the cooker has been blocked from saving the current package for 120, 200, sometimes even 839 seconds.

[Image Removed]

Is this a known issue?

I took an attempt to debug it and actually added to the debug log the *packages* that are in the save queue because by defaut it says:

LogCook: Display: [CookWorker 0]: 1 packages in the savequeue:

LogCook: Display: [CookWorker 0]: <None>

LogCook: Display: [CookWorker 0]: 0 objects that have not yet returned true from IsCachedCookedPlatformDataLoaded:

LogCook: Display: [CookWorker 0]: <None>

Where the <None> would be stuff that its expecting or not so i added the logging of package in queue:

LogCook: Display: [CookWorker 0]: 1 packages in the savequeue:

LogCook: Display: [CookWorker 0]: Package in SaveQueue: /Game/Maps/Level_Instances/Dream_Sequence_01/LI_Dream_Sequence_01

LogCook: Display: [CookWorker 0]: <None>

LogCook: Display: [CookWorker 0]: 0 objects that have not yet returned true from IsCachedCookedPlatformDataLoaded:

LogCook: Display: [CookWorker 0]: <None>

And almost always its happening during the saving of the *map* package or a level instance.

We are using multiprocess cook with 3 instances so I wonder whats changed because in 5.6 we did not have this issue?

I even tried updating our zen cache server exe to the latest from github with no luck

[Attachment Removed]

This looks like a failure of the logging to handle the ICookPackageSplitter that is used by WorldPartition levels for their generated package streaming cells. The cooker code that reports “Cooker has been blocked from saving…” was written with normal packages in mind, where it can find the UObject that the package is waiting on by searching the UObjects in the package. But packages using ICookPackageSplitter have multiple rounds of waiting on objects - to handle the case of objects moving between the generator package and the generated package - and during some of those rounds it is possible the UObject the splitter is waiting on is found in a different package than the package doing the waiting.

If the cook eventually completes, then this is just a failure of the logging and not a behavioral problem.

The long waiting time for the level might be new, or maybe it was always occurring and only the log messages are new. If the long waiting time for the level is new, it could have something to do landscape’s generated HLOD or MaterialInstanceConstant becoming more expensive in 5.7. We should fix the logging first and then open a separate ticket for the longer cook time if cook time for the map has increased.

Does the cook take longer to complete than it did in 5.6?

I will try to get a fix for the logging for you to try out in the next week. If you want to try adding it yourself before I get to it, you will need to investigate UE::cook::FGenerationHelper, and the function that handles the cooking of the packages it monitors - UCookOnTheFlyServer::PrepareSaveGenerationPackage - to see where it can enter a waiting state, and then update the display code in UCookOnTheFlyServer::SetSaveBusy to find the objects its waiting on when the package in the save queue has a non-null PackageData.GetGenerationHelper() or PackageData.GetParentGenerationHelper().

[Attachment Removed]

Sounds good for fixing the warning, I do think the cook time *has* gotten slower since we never really saw this much in 5.6 and in 5.7 we did redo and re-bake the HLOD’s.

If you look at the horde graph:

[Image Removed]

you will see on the right side, A LOT more variability on the cook time after switching to 5.7 from the cooks taking much longer out of no where

[Attachment Removed]

I looked into the display code, and my first guess was wrong; the objects blocking the save of generator packages are polled correctly even if they are outside of the package. I am continuing to look for other ways the save might be blocked. In the meantime, can you send me the log from one of the runs where it was blocked? I want to look for errors.

If there is confidential information in the logs (AssetNames, other information) that is too difficult to remove from the log, please convert the question to confidential and then attach.

[Attachment Removed]

Here is a file [mention removed]​ , can you let me know once you downloaded it so i can delete it:

i removed the confidential stuff

[Attachment Removed]

Thanks, I have downloaded it.

[Attachment Removed]

I’m sorry for the delay on this. I think the issue in your case is that the CookWorker is saving a generator package, and it has reported the generator’s generation manifest to the director, and it is waiting for the director to acknowledge the manifest before it can proceed with the save of the generator, but the directory is busy for multiple minutes on the load of a large map and is not responding to the message from the cookworker for that entire time.

I have updated the diagnostics in the “Cooker has been blocked from saving…” message to list the packages in the save queue and what save substate they are in, which should confirm that diagnosis.

The warning will still occur, let me know if that is a problem. We could possibly add a downgrade in severity from Warning to Display when we detect that we’re waiting on the director to reply.

Assuming this diagnosis is correct, then the worker is not a problem at all, it is just collateral damage. The real problem is why the director is taking hundreds of seconds to load a package or do whatever it is doing. And since you said this problem is new in 5.7, maybe there is a performance problem we can fix there in addition to fixing the responsiveness issue. Can you do some profiling to try to identify the hotspot?

  • UnrealInsights
    • Build and run the UnrealInsights program, and launch the cooker while it is running with the extra commandline argument:
    • -trace=default,savetime,loadtime,cook
  • General profiler
    • Run a general profiler on the cooker while it is running.
    • We use Superluminal when we capture the cooker internally, it manages a capture using EventTracingForWindows, and provides a good visualization of the results.

The new diagnostics were submitted in CL 52687900, aka github commit fe425a7fe4d6a712317a1b15d0a2e0bd36a8f47a.

That CL will not merge cleanly with 5.7 because we just changed logging code callsites throughout the engine; I have merged it into 5.74. in the attached CookOnTheFlyServer.cpp file, which you should diff against the version present in 5.7.4.

[Attachment Removed]

[mention removed]​ I think you forgot to upload the file but I will try to merge it my self.

As far as profiling it, this is happening on horde, and I get like 3-4 instances of it a day, so it’s going to be quite hard for me to actually attach to it and profile it.

I can merge it and report back with the logging. I’m assuming that indeed something has broken in 5.7 because some jobs are taking 50% longer or more randomly

[Attachment Removed]

[Image Removed]

You can see after that *big* gap is the 5.7, and that’s when the cooking started going randomly much longer…

[Attachment Removed]

I’m having trouble attaching the file (some permissions issue); here’s the function in 5.7. You can also merge it yourself; the UE_Log changes are pretty straight-forward to mechanically change to the 5.7. versions.

void UCookOnTheFlyServer::SetSaveBusy(bool bInBusy, int32 NumAsyncWorkRetired)
{
	using namespace UE::Cook;
 
	if (!bInBusy)
	{
		if (bSaveBusy)
		{
			bSaveBusy = false;
			SaveBusyStartTimeSeconds = MAX_flt;
			SaveBusyRetryTimeSeconds = MAX_flt;
			SaveBusyWarnTimeSeconds = MAX_flt;
			// Whenever we set Save back to non-busy, reset the counter for how many busy reports with an
			// idle shadercompiler we need before we issue a warning
			bShaderCompilerWasActiveOnPreviousBusyReport = true;
		}
		return;
	}
 
	const double CurrentTime = FPlatformTime::Seconds();
	if (!bSaveBusy)
	{
		bSaveBusy = true;
		SaveBusyStartTimeSeconds = CurrentTime;
		SaveBusyWarnTimeSeconds = CurrentTime + GCookProgressWarnBusyTime;
	}
	SaveBusyRetryTimeSeconds = CurrentTime + CookProgressRetryBusyPeriodSeconds;
 
	if (NumAsyncWorkRetired)
	{
		// Some progress was made so reset the warning time, and the start time in case we later issue a warning.
		SaveBusyStartTimeSeconds = CurrentTime;
		SaveBusyWarnTimeSeconds = CurrentTime + GCookProgressWarnBusyTime;
	}
 
	if (CurrentTime >= SaveBusyWarnTimeSeconds)
	{
		// Compiler users - classes using the shader compiler - can take multiple minutes to be compiled due to long
		// queues and long compile times, so we do not issue a warning when they are the only objects holding us up,
		// so long as the shadercompiler reports it is working on them.
		bool bShaderCompilerIsActive = GShaderCompilingManager->IsCompiling();
		bool bBusyCompilationUsersAreExpected = bShaderCompilerIsActive ||
			// Even if the ShaderCompilerManager is not currently compiling, it might shortly begin or have recently finished.
			// Issue a warning for blocked compiler users only if there are two reports in a row where the compiler is not active
			bShaderCompilerWasActiveOnPreviousBusyReport;
		bShaderCompilerWasActiveOnPreviousBusyReport = bShaderCompilerIsActive;
 
		// Issue a status update. For each UObject we're still waiting on, check whether the long duration is expected using type-specific checks
		// Make the status update a warning if the long duration is not reported as expected.
		TArray<UObject*> NonExpectedObjects;
		TSet<UPackage*> NonExpectedPackages;
		TArray<UObject*> ExpectedObjects;
		TSet<UPackage*> ExpectedPackages;
		FPackageDataQueue& SaveQueue = PackageDatas->GetSaveQueue();
		TArray<UClass*> CompilationUsers({
			UMaterialInterface::StaticClass(),
			FindObject<UClass>(nullptr, TEXT("/Script/Niagara.NiagaraScript")),
			FindObject<UClass>(nullptr, TEXT("/Script/Niagara.NiagaraSystem"))
		});
 
		PackageDatas->ForEachPendingCookedPlatformData(
		[&CompilationUsers, &ExpectedObjects, &ExpectedPackages, &NonExpectedObjects, &NonExpectedPackages, bBusyCompilationUsersAreExpected]
		(const FPendingCookedPlatformData& Data)
		{
			UObject* Object = Data.Object.Get();
			if (!Object)
			{
				return;
			}
			bool bCompilationUser = false;
			for (UClass* CompilationUserClass : CompilationUsers)
			{
				if (Object->IsA(CompilationUserClass))
				{
					bCompilationUser = true;
					break;
				}
			}
			if (bCompilationUser && bBusyCompilationUsersAreExpected)
			{
				ExpectedObjects.Add(Object);
				ExpectedPackages.Add(Object->GetPackage());
			}
			else
			{
				NonExpectedObjects.Add(Object);
				NonExpectedPackages.Add(Object->GetPackage());
			}
		});
		TArray<UPackage*> RemovePackages;
		for (UPackage* Package : ExpectedPackages)
		{
			if (NonExpectedPackages.Contains(Package))
			{
				RemovePackages.Add(Package);
			}
		}
		for (UPackage* Package : RemovePackages)
		{
			ExpectedPackages.Remove(Package);
		}
			
		bool bExpectedDueToSlowBuildOperations = !ExpectedObjects.IsEmpty() && NonExpectedObjects.IsEmpty();
			
		FString Message = FString::Printf(TEXT("Cooker has been blocked from saving the current packages for %.0f seconds."),
			(float)CurrentTime - SaveBusyStartTimeSeconds);
		ELogVerbosity::Type MessageSeverity = ELogVerbosity::Display;
		if (!bExpectedDueToSlowBuildOperations)
		{
			MessageSeverity = CookerIdleWarningSeverity;
		}
#if !NO_LOGGING
		FMsg::Logf(__FILE__, __LINE__, LogCook.GetCategoryName(), MessageSeverity, TEXT("%s"), *Message);
#endif
 
		int DisplayCount = 0;
		const int DisplayMax = 10;
		if (NonExpectedPackages.Num() + ExpectedPackages.Num() > 0)
		{
			UE_LOG(LogCook, Display, TEXT("%d packages in the savequeue: "), SaveQueue.Num());
			for (TSet<UPackage*>* PackageSet : { &NonExpectedPackages, &ExpectedPackages })
			{
				for (UPackage* Package : *PackageSet)
				{
					if (DisplayCount == DisplayMax)
					{
						UE_LOG(LogCook, Display, TEXT("    ..."));
						break;
					}
					UE_LOG(LogCook, Display, TEXT("    %s"), *Package->GetName());
					++DisplayCount;
				}
			}
			if (DisplayCount == 0)
			{
				UE_LOG(LogCook, Display, TEXT("    <None>"));
			}
 
			UE_LOG(LogCook, Display, TEXT("%d objects that have not yet returned true from IsCachedCookedPlatformDataLoaded:"),
				PackageDatas->GetPendingCookedPlatformDataNum());
			DisplayCount = 0;
			for (TArray<UObject*>* ObjectArray : { &NonExpectedObjects, &ExpectedObjects })
			{
				for (UObject* Object : *ObjectArray)
				{
					if (DisplayCount == DisplayMax)
					{
						UE_LOG(LogCook, Display, TEXT("    ..."));
						break;
					}
					UE_LOG(LogCook, Display, TEXT("    %s"), *Object->GetFullName());
 
					TStringBuilder<2048> AdditionalDebugInfo;
					FDelegates::PackageBlocked.Broadcast(Object, AdditionalDebugInfo);
					UE::String::ParseTokens(AdditionalDebugInfo.ToView(), TEXT('\n'),
						[](FStringView Line)
						{
							UE_LOG(LogCook, Display, TEXT("        %.*s"), Line.Len(), Line.GetData());
						}, UE::String::EParseTokensOptions::SkipEmpty);
 
					++DisplayCount;
				}
			}
			if (DisplayCount == 0)
			{
				UE_LOG(LogCook, Display, TEXT("    <None>"));
			}
		}
		else if (SaveQueue.Num() > 0)
		{
			UE_LOG(LogCook, Display, TEXT("%d packages in the savequeue: "), SaveQueue.Num());
			for (FPackageData* PackageData : SaveQueue)
			{
				if (DisplayCount == DisplayMax)
				{
					UE_LOG(LogCook, Display, TEXT("    ..."));
					break;
				}
				FString GeneratorText;
				if (PackageData->GetGenerationHelper())
				{
					GeneratorText = TEXT(" (Generator)");
				}
				else if (PackageData->GetParentGenerationHelper())
				{
					GeneratorText = TEXT(" (Generated)");
				}
				UE_LOG(LogCook, Display, TEXT("    %s%s: %s"),
					*PackageData->GetPackageName().ToString(), *GeneratorText, LexToString(PackageData->GetSaveSubState()));
				++DisplayCount;
			}
		}
 
		SaveBusyWarnTimeSeconds = CurrentTime + GCookProgressWarnBusyTime;
			
		UE::Cook::FDelegates::CookSaveIdle.Broadcast(
			*this, SaveQueue.Num(), PackageDatas->GetPendingCookedPlatformDataNum(), bExpectedDueToSlowBuildOperations);
	}
}

[Attachment Removed]

If the performance issue is intermittent, one thing you can try is to change your farm to always record the trace; you can pass the commandline arguments

-trace=default,loadtime,savetime,cook -tracefile=<SomeLogDirectory>\CookTrace_<DateTime>.trace

That will require some logic in your farm code to create the dynamic tracefile name though, and you will have to manually prune it or add farm logic to prune it.

We use this technique internally and have already altered MPCook to create unique tracefile for each cookworker, with the suffix _Worker%d on the filename.

It is also possible to trigger the recording of EventTracingForWindows; we do that on our farm as well. But that’s more expensive so we only do it on demand.

[Attachment Removed]

Ok I integrated these changes into our branch so let’s see what it reports now next time it happens.

As far as tracking this on the build machine, can you share the code to generate this unique tracefile for each cookworker?

We are using BuildAndTestProject.xml so I could throw it up on horde if its simple enough to do it

[Attachment Removed]

Our build scripts for Fortnite do not use the unique filename method; they use the same file each time and copy it out to a dedicated folder for the build. It looks like BuildAndTesetProject.xml is set up that same way; I should have suggested that.

BuildAndTestProject.xml has the $(NetworkOutputDirectory) which is a unique directory for the build that is constructed from an initially provided root value of $(NetworkOutputDirectory); that construction is done in Engine\Build\Graph\Tasks\Inc\PathSettings.xml.

<!-- Define your path variables -->
<!-- Maybe this should be a platform-specific path? To handle the case of multi-platform builds -->
<Property Name="ProfilingFilesLocalRootPath" Value="$(ProjectPath)/Saved/Profiling"/>
 
<!-- Set your trace args. Pass these into the commandline of your cook. -->
<Property Name="TraceArgs" Value=""/>
<Property Name="TraceArgs" Value="-trace=cpu,loadtime,savetime,cook" If="$(WithCookUTRACECapture)"/>
<Property Name="TraceArgs" Value="$(TraceArgs) -tracefile=&quot;$(ProfilingFilesLocalRootPath)/Cook.utrace&quot;" If="$(WithCookUTRACECapture)"/>
 
<!-- Reference: the Existing code in BuildAndTestProject.xml:945 to publish staged results: -->
<Node Name="$(PlatformPublishStagedNodeName)" Requires="$(PlatformPublishStageDependencyName)">
	<Log Message="Network upload is disabled, skipping upload." If="!$(PublishToNetworkOutputDirectory)"/>
	<Do If="$(PublishToNetworkOutputDirectory)">				
		<Error Message="NetworkOutputDirectory is not set" If="'$(NetworkOutputDirectory)' == ''"/>
		<Copy Files="..." From="$(ProjectOutputDirectory)/$(StagedPlatformFolder)" To="$(NetworkOutputDirectory)/$(StagedPlatformFolder)/Staged"/>
		<Copy Files="..." From="$(ShaderSymbolsDirectory)/*$(TargetPlatform)*" To="$(NetworkOutputDirectory)/$(StagedPlatformFolder)/ShaderSymbols"/>
	</Do>
</Node>
 
<!-- Copy the publishing code from <Node Name=$(PlatformPublishStagedNodeName)"> into your own <Node Name="PublishProfilingData"> -->
<!-- Maybe this should be a platform-specific copy step, and use platform-specific paths? -->
<Node Name="PublishProfilingData"> <!-- Requires == ??? -->
	<Do If="$(PublishToNetworkOutputDirectory) And '$(NetworkOutputDirectory)' != ''">				
		<Copy Files="..." From="$(ProfilingFilesLocalRootPath)" To="$(NetworkOutputDirectory)/Profiling"/>
	</Do>
</Node>

[Attachment Removed]

Oh, you asked about the code to generate the unique trace file for each cookworker.

You already are using that code; it is done inside of the CookCommandlet by modifying the -tracefile commandline argument that was passed into the CookCommandlet when passing the commandline on to the CookWorker’s invocation of the CookCommandlet.

Engine\Source\Editor\UnrealEd\Private\Cooker\CookDirector.cpp:1714-ish

		else if (Token.StartsWith(TEXT("-tracefile=")))
		{
			FString TraceFile;
			FString TokenString(Token);
			if (FParse::Value(*TokenString, TEXT("-tracefile="), TraceFile) && !TraceFile.IsEmpty())
			{
				FStringView BaseFilenameWithPath = FPathViews::GetBaseFilenameWithPath(TraceFile);
				FStringView Extension = FPathViews::GetExtension(TraceFile, true /* bIncludeDot */);
				Tokens.Add(FString::Printf(TEXT("-tracefile=\"%.*s_Worker%d%.*s\""),
					BaseFilenameWithPath.Len(), BaseFilenameWithPath.GetData(),
					ProfileId,
					Extension.Len(), Extension.GetData()));
				continue;
			}
		}

[Attachment Removed]

[mention removed]​ this is what the warnings are showing now:

[Image Removed]

[Attachment Removed]

That confirms the issue is what I thought. The Worker is waiting on a response from the director.

The relevant code is in UCookOnTheFlyServer::PrepareSaveGenerationPackage

// We cannot proceed with Populate,PreSave,Save,PostSave on the generator until after
		// QueuedGeneratedPackagesFencePassed, because we might discover during processing of that fence that we are
		// not allowed to save the generator package.
		if (Info.IsGenerator() && !GenerationHelper.IsQueuedGeneratedPackagesFencePassed())
		{
			return EPollStatus::Incomplete;
		}

We therefore no longer need to investigate what is happening on the CookWorker when that message occurs, but instead need to look at what the director is doing that makes it fail to reply for so long.

[Attachment Removed]

Ok and I’m assuming that is me looking through the traces? or is there something you want to add to help debug this on your side?

[Attachment Removed]

Yes, please look through the traces for ideas (or post the trace to a confidential question and I can take a look). I don’t have any leads yet for what might have gotten slower. I assume it’s something about HLOD, but if that assumption is correct then I’m not sure what about HLOD it is and I’m hoping for an idea from the trace.

[Attachment Removed]

It’s highly possible its HLOD related, I will try do a capture insights / superluminal captures and see if I can get something for you this week

[Attachment Removed]

Posting to keep it

open so I can try this in the next week

[Attachment Removed]