db-ojb-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Ilkka Priha <impr...@surfeu.fi>
Subject Re: Commons-lang-2.0 slows down performance
Date Thu, 06 Nov 2003 06:59:39 GMT
Hi Jakob,

Yes it does, this slowing down happens by simply switching between 
commons-lang versions. Below is the total (cumulative) time downwards 
from ClassDescriptor.toString() when using lang 1.0.1:

Method                          	Calls   Total Time (%)
--------------------------------------------------------------
ClassDescriptor.toString		11	11.54
ToStringStyle.appendInternal		1040	11.05
ToStringBuilder.append			11	11.03
ToStringStyle.append			11	11.03
ToStringStyle.appendDetail		11	11.00
ToStringStyle.appendDetail		1040	10.92
FieldDescriptor.toString		53	10.75

So there is only 11 calls, which take about 11% of the total time of 
processing one Velocity web template request, which contains a simple 
OJB query.

Here is exactly the same configuration and test case, except that lang 
2.0 is applied:

Method                          	Calls   Total Time (%)
--------------------------------------------------------------
ClassDescriptor.toString		3276	93.46
ToStringBuilder.append			3276	93.43
ToStringStyle.append			3276	93.43
ToStringStyle.appendDetail		3276	93.43
ToStringStyle.appendInternal		91476	93.26
ToStringStyle.appendDetail		78393	93.23
FieldDescriptor.toString		3265	91.91
ToStringBuilder.reflectionToString	3265	89.97
ReflectionToStringBuilder.toString	3265	89.97	
ReflectionToStringBuilder.toString	3265	89.97
ReflectionToStringBuilder.toString	3265	89.93
ReflectionToStringBuilder.appendFieldsIn	13060	89.92
ToStringBuilder.append			84934	89.21
ToStringStyle.append			84934	89.20
StringBuffer.append			564772	24.99
ReflectionToStringBuilder.isRegistered	176366	14.11
ReflectionToStringBuilder.getRegistry	346146	13.48
StringBuffer.expandCapacity		74787	12.63
ThreadLocal.get				346153	9.75
ReflectionToStringBuilder.unregisterObject	84890	8.03
ReflectionToStringBuilder.registerObject	84890	7.62
ReflectionToStringBuilder.unregister	84890	7.03
ReflectionToStringBuilder.register	84890	6.68
ToStringStyle.appendFieldEnd		91486	6.30
HashMap.get				348160	5.92
String.getChars				565604	5.90

The resource consumption is quite different, now there is 3276 calls to 
ClassDescriptor.toString(), causing e.g. 564772 calls to 
StringBuffer.append() and taking 93% of the processing time of one web page.

The method time, i.e. the real time consumed by a named method without 
the time comsumed by other methods that it calls, shows that extreme 
amounts of string buffer and hash map manipulation is the reason for the 
slowness:

Method                          	Calls   Method Time (%)
--------------------------------------------------------------
StringBuffer.expandCapacity		74787	12.63
StringBuffer.append			564772	6.54
String.getChars				565604	5.90
HashMap.get				348160	4.29
ThreadLocal.get				346153	3.88
ReflectionToStringBuilder.getRegistry	346146	3.72
ReflectionToStringBuilder.appendFieldsIn	13060	3.52
Class.getDeclaredFields			13060	3.08
ReflectionToStringBuilder.isRegistered	176366	3.07 
ToStringStyle.append			84934	2.77
ToStringStyle.appendInternal		91476	2.37
ReflectionToStringBuilder.accept	84890	2.15
Object.equals				445505	2.05
HashSet.contains			176366	1.84
ToStringStyle.appendFieldStart		91486	1.72
HashMap.containsKey			176519	1.69
StringBuffer.append			85115	1.50
ReflectionToStringBuilder.unregister	84890	1.45
ReflectionToStringBuilder.getValue	71830	1.32 
ReflectionToStringBuilder.register	84890	1.31
ToStringStyle.appendFieldEnd		91486	1.20
ToStringStyle.appendFieldSeparator	94762	1.19

I haven't checked from source that what exactly inside lang causes so 
dramatic change, but I guess from class and method names that they are 
applying a reflection based cache or registry, which seems to perform 
more poorly under load than doing without it.

-- Ilkka


Jakob Braeuchi wrote:
> hi ilkka,
> 
> does the performance improve when you switch back to 1.0.1 ?
> 
> jakob
> 
> Ilkka Priha wrote:
> 
>> Hi
>>
>> We've detected extremely slow performance after updating from 
>> commons-lang-1.0.1 to commons-lang-2.0. A web page request making a 
>> simple db query can take up to 5000 msecs when it took only about 100 
>> msecs with the previous version. This happens only when Log4J 
>> categories are fully enabled, i.e. DEBUG level is on.
>>
>> I made some profiling and found out that over 92% of the time was 
>> spent in ClassDescriptor.toString() and further in 
>> ToStringBuilder.append(), which was the first commons class in the 
>> call chain.
>>
>> Most of the method time inside ToStringBuilder was consumed in 
>> StringBuffer.extendCapasity(), StringBuffer.append(), 
>> String.getChars(), HashMap.get() and other quite normal methods. So 
>> the reason must be that the three page refreshes I made generated a 
>> huge number of low level calls, e.g. 9828 calls to 
>> ClassDescriptor.toString(), 274428 calls to 
>> ToStringStyle.appendInternal(), 1038438 calls to 
>> ReflectionToStringBuilder.getRegistry(), etc.
>>
>> I've not subscribed the common list, but it seems that the new version 
>> has some major design flaw making it unsuitable at least for OJB tracing.
>>
>> -- Ilkka
>>
>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: ojb-dev-unsubscribe@db.apache.org
>> For additional commands, e-mail: ojb-dev-help@db.apache.org
>>
>>
> 
> 
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: ojb-dev-unsubscribe@db.apache.org
> For additional commands, e-mail: ojb-dev-help@db.apache.org
> 
> .
> 




---------------------------------------------------------------------
To unsubscribe, e-mail: ojb-dev-unsubscribe@db.apache.org
For additional commands, e-mail: ojb-dev-help@db.apache.org


Mime
View raw message