I usually encourage to upgrade early. For me it keeps the overall upgrade effort lower than big bang upgrades. It also brings early access to performance improvements.
But of course you always need to measure! And this is what I did for a customer, planning to upgrade from Drools 5.0.1 to Drools 5.2 .
To my surprise, I noticed that loading and executing rulebases is much slower in 5.2. That customer has a cache, which contains a StatelessSession per rules file. The rules are loaded on startup to provide a smooth experience on the first call. But loading all the files was already causing concerns at startup time. So I hoped for improvements. But initial unit test execution showed degraded performance. Tests took 3 times longer to execute. While the measurements were done quite simple by checking junit execution time, there is no need to discuss precision.
So I attached JProfiler to a unit test which loads and executes 21 Drools Decisiontables based on XLS . The results were quite interesting:
[singlepic id=348 w=320 h=240 float=center]
It is obvious that we have a cause for our performance problem. ClassLoading seems to be the bottleneck. While a single call is quite fast, it is executed a lot.
But there is another interesting fact on these hot spots. Can you spot it?
Yes: System.gc() is invoked 42 times (I like that number). JProfiler says it is accountable for 8% of the total time. But we know Garbage Collection can have side effects.
Why do we have so much Garbage Collection at all? In fact this is not the total amount of Garbage Collection activity, but the number of explicit calls.
I have seen it many times already. Invoking System.gc() is bad (most of the times).
[singlepic id=350 w=320 h=240 float=center]
So why is it invoked? Which is the code guilty of invoking Sytem.gc()? JProfiler can tell us easily:
[singlepic id=352 w=320 h=240 float=center]
I have seen this before as well and for me this is a flaw in the frequently used Java Excel API . It does invoke System.gc() after each time it has read bytes from disk. I really think you shouldn’t do that. And this case again proves why.
But at least there is a flag in jxl and it is explained in WorkbookSettings:
/**
* Flag to indicate whether the system hint garbage collection
* is enabled or not.
* As a rule of thumb, it is desirable to enable garbage collection
* when reading large spreadsheets from a batch process or from the
* command line, but better to deactivate the feature when reading
* large spreadsheets within a WAS, as the calls to System.gc() not
* only garbage collect the junk in JExcelApi, but also in the
* webservers JVM and can cause significant slowdown
* GC deactivated using -Djxl.nogc=true on the JVM command line
* Activated by default or by using -Djxl.nogc=false on the JVM
* command line
*/
Ok, lets add this sytem property. Lets have a look if that did the trick?
[singlepic id=349 w=320 h=240 float=center]
and here the GC activity after activating the nogc flag
[singlepic id=351 w=320 h=240 float=center]
While it did not fix the obvious problem with classloading, it did prove to be a lowhanging fruit. Reducing GC activity and total runtime of this test from 338 seconds to 315 (both in profiled mode). While it is not impressive on a unit test, which by nature has a different JVM setting than a server, it also worked flawlessly in the integration test system. Cache init time was reduced from about 750 seconds to 240 seconds, just by activating this switch.
While the system property made things better for almost no effort, Ill have a look into the classloading madness by drools in a second post.
Was this post helpful?
More articles
fromFabian Lange
8.12.2014 Your job at codecentric?
Jobs
Agile Developer und Consultant (w/d/m)
Alle Standorte
More articles in this subject area
Discover exciting further topics and let the codecentric world inspire you.
Blog author
Fabian Lange
Do you still have questions? Just send me a message.
Do you still have questions? Just send me a message.