Cache-ing Up, Cache-ing In

June 22, 2017

Nb. The fixes described below are available in our GitHub Pull Request: github.com/EpicGames/UnrealEngine/pull/3697
In our last post we described some simple modifications to UE4’s file IO profiler (Improving File Profiler) that allow saving of the profiled data to CSV. This makes it easier to view the collected data, and more importantly helps us spot anomalous behaviour. Particularly, heavily repeated file operations are suspicious as they suggest efficiency savings could be made.

As part of modifying the file profiler we looked at the file IO activity on starting the UE4 editor with one of the lightweight sample projects, and noticed that certain files were being read multiple times. Each .module file in the project was being read in it’s entirety roughly 150-200 times (master branch 16/06/17) just to open the editor! The sample IO data snippet below shows the data read into a spreadsheet program and sorted by read frequency. Column G gives a percentage indicating the bytes read relative to the size of the file. The .module files appear from line 14 downwards. A little further testing showed this was also the case for running the cooker without the editor.

Running our in house memory profiler during the editor startup showed us that there was an FModuleManager function being called rather often, indeed being called as frequently as some common FString and FPath functions which are used throughout the engine. It seemed reasonable that the high read frequency found for .module files, and the large number of calls to FModuleManager::FindModulePathsInDirectory() might be correlated.

Well, the culprit turned out to be FModuleManager::FindModulePaths() in ModuleManager.cpp. This method is called as part of the engine pre initialisation processes and searches a number of known directories for module file names containing a given search pattern (NamePattern) returning a TMap containing the matches. The results are then used by various methods in FModuleManager. The method appeared to be creating a cache of the module filenames the first time it was called, and then searching through that cache.

void FModuleManager::FindModulePaths(const TCHAR* NamePattern, TMap<FName, FString>
&OutModulePaths, bool bCanUseCache /*= true*/) const
{
   if (!ModulePathsCache)
   {
      ModulePathsCache.Emplace();
      const bool bCanUseCacheWhileGeneratingIt = false;
      FindModulePaths(TEXT("*"), ModulePathsCache.GetValue(), bCanUseCacheWhileGeneratingIt);
   } 
   if (bCanUseCache)
   {
      // Try to use cache first
      if (const FString* ModulePathPtr = ModulePathsCache->Find(NamePattern))
      {
         OutModulePaths.Add(FName(NamePattern), *ModulePathPtr);
         return;
      }
   }
...
}

If the cache was empty, or the search failed then the method used to generate the cache, FindModulePathsInDirectory(), was called in a loop on several arrays of directory paths with NamePattern as a search parameter. FindModulePathsInDirectory() verifies module existence and validity by opening and reading the file.

// Use the delegate to query all the modules in this directory
   TMap<FString, FString> ValidModules;
   QueryModulesDelegate.Execute(SearchDirectoryName, bIsGameDirectory, ValidModules);

It began to look like the cache wasn’t being populated fully. Indeed, stepping through the code showed that on the first call to FindModulePaths() two of the arrays of directories the function expected to search were empty. The cache ended up only containing files stored under /Engine/Binaries/ whereas /Engine/Plugins/ and //Binaries/ were omitted. So the plugins and project files weren’t ever making it into the cache! And each time a search of the cache failed every .module file (~120 of them in 4.15.3) in the engine and project was being opened to check it existed, a list of these modules was being instantiated, searched for the pattern of interest, and then deallocated.

FindModulePaths() is first used early in the engine pre initialization, at this point the arrays of pathnames (EngineBinariesDirectories and GameBinariesDirectories) are empty. The engine code is structured such that FPluginManager::ConfigureEnabledPlugins() and FEngineLoop::PreInit() populate the above arrays before their first calls to FModuleManager functions. So given the cache would need to be updated at least once we implemented a simple fix: if searching the cache fails, regenerate the cache and search again. Simple right? Well, no. This stopped the engine from loading at all! Manually inspecting the cache showed it appeared to be correctly populated this time, but clearly something was still going wrong. The program was crashing at an apparently unrelated piece of code, but given no other changes had been made the root of the problem had to be in FindModulePaths().

Since the cache appeared to be populating correctly upon refresh, maybe it wasn’t being searched properly? The existing search used the TMap::Find method which returns an FString if the search pattern is matched, and nullptr if not.

// Try to use cache first
if (const FString* ModulePathPtr = ModulePathsCache->Find(NamePattern))
{
   OutModulePaths.Add(FName(NamePattern), *ModulePathPtr);
   return;
}

This doesn’t account for multiple matches, merely returning the first match, and this turned out to be the issue. Several of the calling methods within FModuleManager (AddModule(), GetOrCreateModule(), IsModuleUpToDate()) were using the size of the array returned from FindModulePaths() to determine behaviour (to deal with multiple module versions for example) and the cache search was only ever going to return a single result. On the other hand the search in FindModulePathsInDirectory() builds a list of all matches.

// Fill the output map with modules that match the wildcard
for(const TPair<FString, FString>& Pair: ValidModules)
{
   if(Pair.Key.MatchesWildcard(NamePattern))
   {
      OutModulePaths.Add(FName(*Pair.Key), *FPaths::Combine(*SearchDirectoryName, *Pair.Value));
   }
}

So it’s only really by chance that the original code was working at all! The fact the cache wasn’t being populated correctly and that the subset of (engine level) module files it contained were unique allowed the TMap->Find() method to work. The remainder of the module files were being found by the FindModulePathsInDirectory() search function.

To fix this we have altered FindModulePathsInDirectory() to remove it’s search capacity and merely populate a TMap with all the valid modules in the input directory. We’ve removed the NamePattern parameter from the method signature and removed the check for a match with that NamePattern, changing from this:-

void FModuleManager::FindModulePathsInDirectory(const FString& InDirectoryName, bool bIsGameDirectory, const TCHAR* NamePattern, TMap<FName, FString> &OutModulePaths) const
{
... 
// Fill the output map with modules that match the wildcard
   for (const TPair<FString, FString>& Pair : ValidModules)
   {
      if (Pair.Key.MatchesWildcard(NamePattern))
      {
         OutModulePaths.Add(FName(*Pair.Key), *FPaths::Combine(*SearchDirectoryName, *Pair.Value));
      }
   }
}

to this:-

void FModuleManager::FindModulePathsInDirectory(const FString& InDirectoryName, bool bIsGameDirectory, TMap<FName, FString> &OutModulePaths) const
{
... 
// Fill the output map with modules that match the wildcard
   for (const TPair<FString, FString>& Pair : ValidModules)
   {
      OutModulePaths.Add(FName(*Pair.Key), *FPaths::Combine(*Pair.Key, *Pair.Value));
   }
}

FindModulePaths(), however, needed a larger overhaul:-

void FModuleManager::FindModulePaths(const TCHAR* NamePattern, TMap<FName, FString>
&OutModulePaths) const
{
   if (!ModulePathsCache)
   {
      ModulePathsCache.Emplace();
      // Add the engine directory to the cache - only needs to be cached once as the contents do not change at runtime
      FindModulePathsInDirectory(FPlatformProcess::GetModulesDirectory(), false, ModulePathsCache.GetValue());
   }

First of all we’ve got rid of the boolean checking if the cache should be used from the method signature, then if the cache has not been instantiated this is done and it is populated with the contents of the Engine directory.

// If any entries have been added to the EngineBinariesDirectories or GameBinariesDirectories arrays, add any
// new valid modules within them to the cache.
// Static iterators used as once we've cached a BinariesDirectories array entry we don't want to do it again (ModuleManager is a Singleton)
static int EngineIndex = 0;
// Add any new engine binaries directories to the cache
for (; EngineIndex < EngineBinariesDirectories.Num(); EngineIndex++)
{
   FindModulePathsInDirectory(EngineBinariesDirectories[EngineIndex], false, ModulePathsCache.GetValue());
}
static int GameIndex = 0;
// Add any new game binaries directories to the cache
for (; GameIndex < GameBinariesDirectories.Num(); GameIndex++)
{
   FindModulePathsInDirectory(GameBinariesDirectories[GameIndex], true, ModulePathsCache.GetValue());
}

Next if the size of the EngineBinariesDirectories or GameBinariesDirectories arrays have increased since the last time this function was called we call FindmodulePathsInDirectory() on the new entries to add the valid .module files therein to the cache.

// Search the cache
for (const TPair<FName, FString>& Pair : ModulePathsCache.GetValue())
{
   if (Pair.Key.ToString().MatchesWildcard(NamePattern))
   {
      OutModulePaths.Add(Pair.Key, Pair.Value);
   }
}

Finally we search the cache. Importantly we’re now using a method which will return an output map containing all .module files with names matching the NamePattern search parameter

We first started investigating this bug in UE 4.15.2, however, updates to the master branch (4.17.0, June 2017) were showing the EngineBinariesDirectories array added to much more frequently – resulting in an increase of the number of .module file reads by ~50% on editor startup. Our fix slashes the frequency of .module file reads on startup from ~200 to once per file. Unfortunately, there’s not really a perceptible speed increase on starting the standard editor. Looking at the time spent on file IO shows a saving of ~1.6s – note however that this is on a system fully equipped with SSHDs where file IO times are pretty fast! The time saving is, however, less important than catching what could’ve been quite a hard to track down bug before it had a chance to cause anyone a major headache!

Credits:
Programming/Research: Josef Gluyas (Coconut Lizard)
Mentoring: Gareth Martin, Joe Tidmarsh, Robert Troughton, Lee Clark (Coconut Lizard)

cooking optimization ue4