Professional C__ - Marc Gregoire [425]
This main() function creates one NameDB database called boys, telling it to populate itself with the file boys_long.txt, which contains 500,500 names.
There are three steps to using gprof:
1. Compile your program with a special flag that causes it to log raw execution information next time it is run. When using GCC as your compiler, the flag is -pg, for example:
> gcc -lstdc++ -std=c++0x -pg -o namedb NameDB.cpp NameDBTest.cpp
See Bonus Chapter 2 on the website (www.wrox.com) for more information on the -std=c++0x flag.
2. Next, run your program. This run should generate a file called gmon.out in the working directory. Be patient when you run the program because this first version is very slow.
3. The final step is to run the gprof command in order to analyze the gmon.out profiling information and produce a (somewhat) readable report. gprof outputs to standard out, so you should redirect the output to a file:
> gprof namedb gmon.out > gprof_analysis.out
Now you can analyze the data. Unfortunately, the output file is somewhat cryptic and intimidating. It takes a little while to learn how to interpret it. gprof provides two separate sets of information. The first set summarizes the amount of time spent executing each function in the program. The second, and more useful, set summarizes the amount of time spent executing each function and its descendants, and is also called a call graph. Here is some of the output from the gprof_analysis.out file, edited to make it more readable. Note that the numbers will be different on your machine.
index %time self children called name
[1] 100.0 0.00 14.06 main [1]
0.00 14.00 1/1 NameDB::NameDB [2]
0.00 0.04 3/3 NameDB::getNameRank [25]
0.00 0.01 1/1 NameDB::~NameDB [28]
The following list explains the different columns:
index: an index to be able to refer to this entry in the call graph.
%time: the percentage of the total execution time of the program required by this function and its descendants.
self: how many seconds the function itself was executing.
children: how many seconds the descendants of this function were executing.
called: how often this function was called.
name: the name of the function. If the name of the function is followed by a number between square brackets, that number refers to another index in the call graph.
The preceding extract tells us that main() and its descendants took 100 percent of the total execution time of the program, for a total of 14.06 seconds. The second line shows that the NameDB constructor took 14.00 seconds of the total 14.06 seconds. So it’s immediately clear where the performance issue is situated. To track down which part of the constructor is taking so long, you need to jump to the call graph entry with index 2, because that’s the index in square brackets behind the name in the last column. The call graph entry with index 2 is as follows on my test laptop:
[2] 99.6 0.00 14.00 1 NameDB::NameDB [2]
1.20 6.14 500500/500500 NameDB::nameExists [3]
1.24 5.24 499500/499500 NameDB::incrementNameCount [4]
0.00 0.18 1000/1000 NameDB::addNewName [19]
0.00 0.00 1/1 vector::vector [69]
The nested entries below NameDB::NameDB show which of its descendants took the most time. Here you can see that nameExists() took 6.14 seconds, and incrementNameCount()took 5.24 seconds. Remember that these times are the sums of all the calls to the functions. The fourth column in those lines shows the number of calls to the function (500,500 to nameExists() and 499,500 to incrementNameCont()). No other function took a significant amount of time.
Without going any further in this analysis, two things should jump out at you:
1. 14 seconds to populate the database of approximately 500,000 names is slow. Perhaps you need a better data structure.
2. nameExists() and incrementNameCount() take almost identical time, and are called almost the same number of times. If you think about the application domain, that makes sense: Most names in the text file input are duplicates, so the vast majority of