A profiling war story
The other day I ran across an XML schema that took the XSD compiler unusually long to translate to C++. While the schema itself was quite large, almost 2MB of definitions spread over 80 files, the compilation time on my machine was excessive, about 160 seconds. We also had another report from several months ago where XSD would seem to run indefinitely while trying to compile a really large schema (15K element declarations across about 200 files). Unfortunately, the reporter couldn’t provide us with that schema for debugging due to distribution restrictions. All we could do was give them a new version of the compiler and they had to tell us whether it worked or not.
I set out to figure out what was going on using the schema I had suspecting that it was the same problem as the one affecting the other schema. The first step was to understand which part of the compilation process takes so much time. A good profiler can be very helpful in accomplishing this. I personally prefer OProfile mainly because: 1) it is system-wide so you can see the complete picture (your application, libraries, even the kernel), 2) it is transparent in the sense that you don’t need a special build of your application and all the libraries that it depends on, and 3) it has a low overhead which means that your application doesn’t take 10 times as long to execute when profiling.
I ran OProfile while the XSD compiler was compiling the schema. My first step in analyzing the program execution was to get a flat symbol list that shows how much time is spent in each function. Here is the top of the listing for XSD:
samples % image name symbol name 405527 14.4254 libc.so _int_malloc 334761 11.9081 libc.so _int_free 287232 10.2174 libc.so free 285081 10.1409 xsd Cult::MM::allocate 199565 7.0989 libc.so malloc 124309 4.4219 xsd Schema::find 119779 4.2608 xsd operator delete 104893 3.7312 xsd std::map<...>::find 94964 3.3780 libc.so wmemcmp 85689 3.0481 xsd Cult::MM::Key::size 80308 2.8567 xsd operator new 62390 2.2193 libc.so strlen 37687 1.3406 xsd std::string::_S_create 35205 1.2523 libc.so memcpy
When you read articles about profiling you are normally presented with a listing similar to the one above where one or two functions at the top account for 90% percent of the execution time. This, however, doesn’t happen very often for complex programs that were built by competent engineers. Complex programs perform several operations in a pipe-line manner instead of just one algorithmic task (image conversion is good example of an algorithmic application where you may see a single function at the top taking 90% of the time). Competent engineering means that there are no silly programming or architectural mistakes that result in single-function bottlenecks. Instead, you normally see a listing like the one above: execution time is spread over many functions without any time standing out as unreasonable. Such information is completely useless in understanding what’s going on in the program.
What we need instead are the aggregate times for each function. That is, a time spent in the function itself and in all the functions that it calls. We also need to know which other functions each function calls with their respective times. With this information we can find which operation in our program takes most of the execution time as well as figure out which parts of this operation are responsible for the slowdown.
The best way to get this information from OProfile is to collect the samples with the call graph information (see the --callgraph option), then convert them to the gprof format with the opgprof command, and finally generate the call graph with the gprof -q command. One limitation of the call graph information is that it is very inaccurate if your application is optimized. To get a useful result you will need to recompile your application with optimization turned off.
The call graph output is quite a bit more complex and can be a lot more verbose compared to the flat symbol list presented above. The gprof call graph format is explained in detail in the gprof documentation.
One way to get a summary of the gprof call graph that just tells us which functions have the largest aggregate times is to run the following sed script on the call graph output:
sed -e '/^\[/p;d' callgraph >summary
Here is the top of the summary listing for XSD:
% time self children called name 99.8 0 645554 main 94.0 16021 591541 588759+ Schema::find 3889477 82.6 1024 533243 512793+ <cycle 4 as a whole> 36104907 82.4 0 532686 512443 Parser::parse 55.5 8 358965 465329 Node<Element>::trampoline 49.5 27896 291869 265608+ <cycle 1 as a whole> 36968 47.9 0 309389 299838 Resolver::resolve_element 42.6 18427 256696 215619 operator new 38.6 1 249727 242001 Resolver::traverse
From this listing it is immediately apparent that the problem is most likely in the Schema::find operation. It takes up 94% of the program execution time and is called half a million times from other functions and almost four million times recursively.
The Schema::find() function looks up namespaces with the specified XML namespace name in the schema graph. To understand how it works one needs a basic understanding of how the schema graph is organized. Each schema file is represented by a Schema object which contains a list of references to included and imported schema files (also represented as Schema objects) along with the Namespace object which contains the actual type, element, etc., declarations. Schema::find() returns a list of Namespace object corresponding to a namespace name. To collect this list, it traverses the include/import graph to make sure it visits every Schema object visible, directly or indirectly, from the initial schema.
There could be two general reasons why Schema::find() takes a disproportional amount of time. It can be because it is called too many times by other functions. Or the problem could be in its implementation. Or it can be both. Seeing that Schema::find() is called almost 8 times more often recursively than from outside, the suspicion is that it is the implementation. Here is the fragment of the call graph listing corresponding to this function:
self children called name 16021 591541 588759+3889477 Schema::find 8275 217657 208177/208268 Context::set 3528 174629 158008/158008 std::list<...>::insert 3190 45372 65030/65055 Context::remove 346 47712 43879/43880 std::list<...>::clear 3500 28218 32082/37821 Scope::find 3560 9619 20461/20586 Context::count
As you can see the time is dominated by two sets of operations. The first are Context operations which are used to detect recursive import/inclusion (that is, a flag is set in the Schema’s context to indicate that it is being traversed). The second are the list insertion and removal operations. This tells us two things: a lot of Schema objects are being traversed and a lot of Namespace objects are being inserted into the resulting list.
The size of the schema, and in particular the number of files which corresponds to the number of Schema objects, could not by itself explain the long compilation time since there are comparable or even larger schemas that compile much faster. There had to be something else special about this schema. As it turned out, and this is something I just had to figure out on my own since no profiling tool is available for this last step, the schema had a very expansive include/import tree. Most files in this schema included or imported a handful of other files which in turn did the same. The end result was that each schema file was included or imported, directly and indirectly, hundreds of times. That meant that the Schema::find() implementation had to traverse the same files over and over again (thus all the Context operations) and insert the same Namespace objects into the resulting list over and over again (thus all the list operations).
The solution was fairly straightforward. I added a set which keeps track of all the Schema objects that has already been seen in this execution of Schema::find(). The compilation time dropped from 160 seconds to 1.5 seconds which is more than 100 times speedup. And, as it turned out, this was the same problem that affected the larger schema which we could not get.