The Improvement of the File Profiler

June 19, 2017

You can view and download the code for this post from our Github Pull Request: https://github.com/EpicGames/UnrealEngine/pull/3688

The Existing File Profiler

UE4 has a tool for profiling file IO – but as Michael Caine never said, “there’s not a lot of people that know that”. At least, there is very little information about it online. If you want to try it out, simply add ‘-ProfileFile’ to your command-line when running your project. This overrides usages of IPlatformFile with FProfiledPlatformFile, appending data collection tags to file IO operation functions. To view the profiling, you simply use the console command ‘Profile File’, which will bring up a windows similar to this:-

The window is based on that used for the GPU profiler (docs.unrealengine.com/latest/INT/Engine/Performance/GPU/). Unfortunately, the profiled data isn’t presented in a way that’s very easy to view:-

files are shown as a horrible mixture of relative and absolute paths (see below)
it’s not possible to get a summary of the information displayed in any useful way (you’re simply given a long list of file operations)
you can only view the data while the editor or game is running (nothing is saved to HDD)

The code for handling the collected data and displaying the I/O Profiler window is located in LevelTick.cpp within FFileProfileWrapperExec(). The single Exec() function allows commands to be issued from elsewhere in the program and currently is written to take a snapshot of file IO activity recorded from the time the program started up to the point the user entered the command.

File Profiler Improvements

The first easy change we’ll look at is to improve the path readability. For this we take advantage of Unreal’s FPaths::ConvertRelativePathToFull() method. Rather than doing this in the overridden file IO functions, we do this in DisplayProfileData(), avoiding the need to repeatedly do the conversion (due to the hierarchical organisation of the file IO methods). So, we change:-

TSharedPtr<FProfiledFileStatsFileBase> FileStat = ProfileData[ Index ];
double FileDurationMs = 0.0;

to:-

TSharedPtr<FProfiledFileStatsFileBase> FileStat = ProfileData[Index];
// Convert to full paths for ease of reading
FileStat->Name = FPaths::ConvertRelativePathToFull(FileStat->Name);
double FileDurationMs = 0.0;

With that out of the way there are a few further improvements which would allow us to better take advantage of the data collected by the file profiler. Briefly we’d like to be able to display the data in a more user friendly way, to be able to save and reload data on command, and preferably have the data saved on exit.

While we could go and create a shiny alternative Slate window to display the IO data in, what we really want is to see a table of data with the ability to sort on particular stats. Your favourite spreadsheet program will, of course, do that – so writing a new display window in Unreal would really be reinventing the wheel. As, ideally, we’d like the data to be saved to HDD to future reference, writing out a CSV file solves both of our problems. The profiling data is collected into a tree of FProfiledFileStatsBase structs and converted for display in the current File I/O window by iterating over the tree and creating a list of ‘event names’ with an associated time for each file. We’ve simply added functionality to count up each IO event and then write the data out to file.

At this point, rather than further cluttering up LevelTick.cpp, we took the opportunity to move the whole FFileProfileWrapperExec class out into it’s own h/cpp files. You can grab those files from the pull request we’ve submitted and drop them into your Engine/Source/Runtime/Engine/Private folder. Delete the old FFileProfileWrapperExec code from LevelTick.cpp and, finally, there are now a few unneeded #includes which can be removed from LevelTick.cpp:-

// NOT NEEDED #include "HAL/IPlatformFileProfilerWrapper.h"    
// NOT NEEDED #if !UE_BUILD_SHIPPING    
// NOT NEEDED #include "VisualizerEvents.h"    
// NOT NEEDED #include "STaskGraph.h"    
// NOT NEEDED #endif

Looking at the beginning of the new FileProfileWrapperExec.h/cpp we’ve modified the command-line parsing code to add a ‘Quit’ command. This sets a boolean to suppress the opening of the File I/O window allowing the file profiling data to be saved upon program termination without spawning popup windows. In addition this means the file profiler can be run for automated or command-line processes such as cooking.

bool FFileProfileWrapperExec::Exec(UWorld* InWorld, const TCHAR* Cmd, FOutputDevice& Ar)
{
  // Internal UE4 command line - use to take a snapshot of the file IO data recorded from startup to the current time point.
  // (The file profiler is activated by running the application with 'ProfileFile' as a flag.)
  if (FParse::Command(&Cmd, TEXT("ProfileFile")))
  {
    // 'Quit' command is issued in FEngineLoop::AppPreExit()
    if (FParse::Command(&Cmd, TEXT("Quit")))
    {
      bShouldSuppressIOVisualiser = true;
    }
  }
 
  ….
}

To get the profiler to write out changes on exit, we need to issue the ‘Quit’ command at a suitable point in the application exit process. This can be done in the same place as the memory profiler (MallocProfiler) shutdown is initiated by adding the StaticExec() near the top of FEngineLoop::AppPreExit() (LaunchEngineLoop.cpp) as shown here:-

void FEngineLoop::AppPreExit( )
{
  UE_LOG(LogExit, Log, TEXT("Preparing to exit.") );

  FCoreDelegates::OnPreExit.Broadcast();

  MALLOC_PROFILER( GMalloc->Exec(nullptr, TEXT("MPROF STOP"), *GLog);  );

#if !UE_BUILD_SHIPPING
  FSelfRegisteringExec::StaticExec(nullptr, TEXT("ProfileFile Quit"), *GLog);
#endif // !UE_BUILD_SHIPPING

#if WITH_ENGINE
 
...
 
}

The remaining changes to the FFileProfileWrapperExec() class are relatively unexciting, dealing mainly with CSV formatting and saving. We’ve done a little bit of data manipulation so as to write out comparisons between the field size and the amount of data read from it but otherwise saved the raw data totals per filename.

With all that in place. If you simply run your project with the ‘-ProfileFile’ command-line option you’ll get a CSV file written to \UnrealEngine\\Saved\FileProfiler upon exit. Using the console command ‘ProfileFile’, a snapshot of all the IO activity up to that point will be generated which you can view in the inbuilt IO visualizer window (albeit with more readable filenames!).

With this, you can now view all the file operations and sort them in various ways for better analysis.

In our next blog post, we’ll analyse some data from a capture that we took – and show you how it helps track down bugs, optimise file access and more.

Please let us know if you have any ideas or questions in the comments below!

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