Finally, another trivia-post. I could not find the answer easily on the web, but there might be people that are struggling with the same problem we had.
While working on my current project we ran into a problem with a MDX-query. In short, it retrieved about 14,000 rows from a database and displayed a subset of these rows on the screen in a variable ordering. The problem we where facing was that it took about 4-5 minutes before the data showed up.
We knew that the query was not completely trivial, but 14,000 rows is not that much data. Furthermore, one would expect that an OLAP-database could handle this kind of volume very easily. In the beginning we thought that it took so long because all of the data was first retrieved from the database and then sorted within the Java-code. On the other hand, sorting a list of 14,000 items should not take that long. An other theory we had was that the bottleneck was the number of queries that is generated (about 4000) to retrieve the 14,000 rows. This was not the case, every query only took 1-2 ms to complete.
So we fired up YourKit, a Java memory/CPU-profiler. I can highly recommend this tool to anyone who wants to profile there code. It provides detailed reports about all sorts of interesting things and comes with a nice interface.
While going to the profiling output we noticed that the code was spending about 50 percent of the time in a 'Sort'-method, and 40 percent of the time in a 'Debug'-method. Since we didn't see that much debug-output we did what any programmer would do when has not written the tool (s)he works with: we assumed that the profiler was wrong and concentrated on the 'Sort'-method.
Examining the profiler output some more we discovered that 40 percent of the time in the 'Sort'-method was actually spent by calling the 'Debug'-method above! So we looked up the code and found out that the people of Mondrian where actually calling this 'Debug'-method every time they compared two objects.
Question: When sorting 14,000 objects, how many lines of debug-output would you get?
Answer: A lot.
The funny thing was that we did see some debug-output, but not as much as you would expect from the code. Furthermore, the 'Debug'-method was only called when the log4J-level was set to DEBUG. We did use a log4j-configuration, the default that was shipped with the application, but this file did not mention Mondrian anywhere. It did mention a file called 'server.log' which we eventually found. The size of the log-file was about 1 gigabyte, which might explain where all the debug-lines went to.
Our current solution is to simply remove the log4j-configuration from our project. This still gives us enough feedback to track the usual things, but it also prevents Mondrian to go into debug-mode. It reduced the running time from 4-5 minutes to 4-5 seconds, a considerable speed-up don't you think?
No comments:
Post a Comment