Built-in Profiler
| Portability & Compatibility |
|---|
| Performance |
| Efforts |
FlightGear 2.9+ provides two new fgcommands that have been added to control a built-in profiler based on Google PerfTools. FlightGear's profiler support can be used to benchmark hot spots and do extremely fine-grained profiling for certain parts of the C++/Nasal code, which makes it easy to determine the overhead of calling certain functions/loops and optimize the code accordingly.
This is exactly how we managed to quickly optimize the new airport selection dialog which uses the Canvas system to draw complex taxiway layouts in a largely Nasal-driven way.
To use the profiler FlightGear has to be compiled with gperftools and the CMake variable ENABLE_PROFILE set to ON (OFF is the default).
Note that it makes sense to also build a debug binary when profiling is enabled, to ensure that the runtime profile contains all the required information such as function or variable names, which could otherwise get optimized out by the compiler.
If the profiler-related fgcommands are used without profiling support being available, the following non-critical warning will be printed to the console, indicating that the commands have NO effect:
No profiling support! Install gperftools and reconfigure/rebuild fgfs.
To check at runtime if the binary provides profiling support or not, use the /sim/debug/profiler-available property.
Installing gperftools
Debian/Ubuntu
For Debian/Ubuntu and their derivatives libgoogle-perftools-dev and for analyzing the results also google-perftools can be installed through the package manager:
$ sudo apt-get install libgoogle-perftools-dev google-perftools
Other
See http://code.google.com/p/gperftools/downloads/list for available downloads.
Starting/Stopping the Profiler
For controlling the profiler the commands profiler-start and profiler-stop are available. profiler-start starts up the profiler and dumps its output to a file named fgfs.profile in the current directory (You can pass an argument filename to profiler-start to use another name). profiler-stop stops the profiler and ensures all data has been written to the output file.
C++
globals->get_commands()->execute("profiler-start");
// or with filename
SGPropertyNode args;
args.setStringValue("filename", "output.profile");
globals->get_commands()->execute("profiler-start", &args);
globals->get_commands()->execute("profiler-stop");
Nasal
fgcommand("profiler-start"); # default file name is fgfs.profile
// or with a custom filename
fgcommand("profiler-start", props.Node.new({"filename": "output.profile"}));You can easily use different file names to profile different parts of your code using the same simulator session.
fgcommand("profiler-stop");
For example, to profile a certain Nasal extension function like airportinfo(), just wrap the function call in between two fgcommands like this:
fgcommand("profiler-start"); # default file name is fgfs.profile
airportinfo("ksfo");
fgcommand("profiler-stop"); # immediately stop the profiler againYou can also easily profile loops like this:
fgcommand("profiler-start"); # default file name is fgfs.profile
foreach(var airport; findAirportsWithinRange(100)) {
airportinfo(airport);
}
fgcommand("profiler-stop"); # immediately stop the profiler again
For regression testing purposes, you can also directly terminate the process by running the exit fgcommand directly after stopping the profiler:
fgcommand("exit");Analyzing the Results
- http://kratos-wiki.cimne.upc.edu/index.php/How_to_Profile_an_application_(using_google-perftools)
- http://goog-perftools.sourceforge.net/doc/cpu_profiler.html
Afterwards, you can safely close FG (or run fgcommand("exit")) and inspect the file fgfs.profile created in the CWD (current working directory) from where you started the whole thing. To actually process the file, use pprof (Depending on the installation you will need to use google-pprof in place of pprof):
$ pprof --text /path/to/fgfs /path/to/fgfs.profile > profiling.results
$ google-pprof --text /path/to/fgfs /path/to/fgfs.profile > profiling.results
A possible output (written to profiling.results) could be:
47 29.6% 29.6% 47 29.6% sqlite3VdbeExec
22 13.8% 43.4% 22 13.8% __read_nocancel
8 5.0% 48.4% 8 5.0% lseek64
7 4.4% 52.8% 7 4.4% sqlite3VdbeMemRelease
4 2.5% 55.3% 4 2.5% likeFunc
4 2.5% 57.9% 4 2.5% sqlite3DbFree
4 2.5% 60.4% 4 2.5% sqlite3VdbeMemMove
3 1.9% 62.3% 3 1.9% _IO_str_pbackfail
3 1.9% 64.2% 3 1.9% fetchPayload
3 1.9% 66.0% 3 1.9% sqlite3BtreeCursorHasMoved
3 1.9% 67.9% 3 1.9% sqlite3VdbeMemGrow
3 1.9% 69.8% 3 1.9% sqlite3VdbeRealValue
2 1.3% 71.1% 2 1.3% 0063154b
2 1.3% 72.3% 2 1.3% btreeParseCellPtr
2 1.3% 73.6% 2 1.3% memcpy
2 1.3% 74.8% 2 1.3% pcache1Fetch
2 1.3% 76.1% 2 1.3% sqlite3BtreeDataFetch
2 1.3% 77.4% 2 1.3% sqlite3BtreeDataSize
2 1.3% 78.6% 2 1.3% sqlite3ValueText
2 1.3% 79.9% 2 1.3% sqlite3VdbeMemNulTerminate
2 1.3% 81.1% 2 1.3% sqlite3VdbeSerialTypeLen
2 1.3% 82.4% 2 1.3% sqlite3_mutex_leave
2 1.3% 83.6% 2 1.3% sqlite3_value_text
The columns can be interpreted as follows:
- Number of profiling samples in this function
- Percentage of profiling samples in this function
- Percentage of profiling samples in the functions printed so far
- Number of profiling samples in this function and its callees
- Percentage of profiling samples in this function and its callees
- Function name
For more options to analyze the results (eg. callgraphs or focusing on specific parts of the code) have a look at http://google-perftools.googlecode.com/svn/trunk/doc/cpuprofile.html.
Visualizing the results
See the gprof2dot python script available at: http://code.google.com/p/jrfonseca/wiki/Gprof2Dot