Skip to end of metadata
Go to start of metadata

Overview

The bootprofiler is used to profile the time it took for the engine to boot, or to profile the load times of levels. It records automatically every time the engine is started or a level is loaded.

Enabling The Bootprofiler

In the standard SDK, when ENABLE_PROFILING_CODE is defined, it will also define ENABLE_LOADING_PROFILER. when this is enabled it will record the boot times and level load times every run.

The results are then stored in TestResults. The files are called bp_boot.xml and bp_level.xml.

Analyzing The Data

In Tools\ProfVis you will find ProfVis.exe, with this tool the data can be analyzed.

Simply drag and drop one of the files from TestResult into the tool, or use the File -> Open and Browse to the desired file.

There is also a reload button at the top that will refresh the data, this is very useful for quick iteration, you can run the launcher, shutdown, hit reload and instantly see your new results for example.

Controls: Use Ctrl + Mouse-Scroll to Zoom in and out, and make sure to only use the horizontal scrollbar at the bottom to navigate left and right.

Understanding the tool

When the data is loaded it creates a timeline. On the horizontal axis it will display the time in milliseconds, on the vertical axis you will find the threads.

The Bars

The gray bars are the threads, and their name is written on them, the 0, 1, 2 ... n lines underneath are sort of the layers. They help you breakdown a function. For example on line 0 you will have a CSystem::Init, and on line 1 InitRenderer, PostInit, InitInput.

The last 3 functions are called from inside CSystem::Init. So when you encapsulate profile markers, they will create multiple layers to breakdown the functions.

The colors are arbitrary at the moment

Block Info

You can hover over one of the blocks to get more information.

  • totalTime: time this block took in milliseconds.
  • cursorAbsolute: the time and percentage of the complete loading time of where your mouse cursor is
  • args: optional arguments provided through the marker, usually useful for file loads etc.

Filter

On the top-right there is a filter, once you hit enter in there it will mask out anything that doesn't match the filter making it easy to find some markers.

Markers in the Code

There are different markers that you can use.

The most basic one is LOADING_TIME_PROFILE_SECTION, this simply marks the function so that it will be profiled.

Then there is LOADING_TIME_PROFILE_SECTION_NAMED, this one allows the programmer to give it a custom name. This can be useful if you are breaking down a function.

Both of the previous one have a variant that takes an argument, so LOADING_TIME_PROFILE_SECTION_ARGS and LOADING_TIME_PROFILE_SECTION_NAMED_ARGS. These do the same as explained before, but it allows the user to send an argument which will show up in the profiler as shown above (argument is a const char*).

These macro's are scope markers, meaning that they measure how much time has passed between their creation and destruction (when they go out of scope), keep this in mind when you use them.

Below is an example of how to take advantage of the scoped markers (take note of the brackets to create scopes):

sample
void Bar()
{
  LOADING_TIME_PROFILE_SECTION;
  ...
}
 
void Foo()
{
  LOADING_TIME_PROFILE_SECTION;
  Bar();
  
  {
    LOADING_TIME_PROFILE_SECTION_NAMED("Foo - Expensive loop");
	while(..) {....}
  }
}

Would result in the following:

  • No labels