[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [virgo-dev] Performance degradation problem

Costin Leau is making preparations for a first release of Blueprint, so hopefully that will fit in with your schedule. I think the first milestone of Blueprint is pretty stable if you want to test with that and get some experience of running it in Virgo in parallel with Spring DM 1.2.1.

Regards,
Glyn

On 28 Jun 2011, at 16:28, Shaun McGinnity wrote:

Hi Glyn,
 
Thanks for the response. We also raised the issue on the spring-osgi forum and got similar advice. I will try your recommendation but from our release perspective I think we will have to wait until there is a stable Blueprint release.
 
Regarding your question, I sampled the test every 10 seconds so the x-axis is in 10second units. This aligns with your figures below and I do see the problem after ~ 2.5 hours.
 
Regards,
 
Shaun
 
 
From: virgo-dev-bounces@xxxxxxxxxxx [mailto:virgo-dev-bounces@xxxxxxxxxxx] On Behalf Of Glyn Normington
Sent: Tuesday, June 28, 2011 4:18 PM
To: Virgo Project
Subject: Re: [virgo-dev] Performance degradation problem
 
Hi Shaun
 
Thanks for raising this and for doing some excellent ground work to give us a starting point!
 
May I just check a basic fact. What are the units on the X axis of your graph? (2**31)/250000 is around 8500 seconds. In other words I would expect it to take around 2.5 hours for the use count to go negative if it is incremented once per request. But that's somewhat irrelevant since you hitting this problem.
 
So it seems that Spring DM should be ungetting the service to make this scenario perform reasonably, but unfortunately Spring DM 1.2.1 doesn't unget until the caller's application context is destroyed (and even then it's not clear how many ungets it will do). This behaviour is fixed in Spring DM 2.0 which only went as far as a milestone before becoming Eclilpse Gemini Blueprint. We will upgrade Virgo to use Gemini Blueprint in due course, but not for the 3.0 release since Blueprint will not be released in time.
 
The good news is that you can run Blueprint in parallel with Spring DM 1.2.1 as several users have successfully managed. Then you should get consistent performance. If you can't find how to do this by searching the net, please bring it up on the Virgo forum so other users can advise.
 
This is somewhat of a secondary point, but I notice that the second stack trace shows a class load which was not satisfied by the JVM's class loader cache. This is intriguing because it implies that the class has not been loaded from that class loader before. Yet, there are only two application class loaders that are relevant in this scenario, one per bundle. I'll ask an Equinox expert if he has any idea why this is happening.
 
Regards,
Glyn
 
On 27 Jun 2011, at 16:23, Shaun McGinnity wrote:


Hi,
 
I am using virgo 2.1.0 with org.eclipse.osgi-3.6.1.R36x_v20100806.jar. I have encountered an issue with Virgo which results in a significant performance degradation.
 
The problem first arose with a web services application but I have recreated the problem using 2 simple services provided by bundle#1 and referenced by bundle#2. In bundle#2 I have a client bean that creates a pool of threads, each calling the 2 exposed services.
 
The services have no external dependencies and perform no I/O.
 
After running the test for some time I see the number of requests handled per second drop significantly. The time at which this happens is the same for every test. After another period of time the previous performance level is restored. Again this period is predictable.
 
<image003.png>
 
 
Checked this up to verion 3.7.0 of org.eclipse.osgi.
 
I have traced through the code and I think the error is being caused by the service lookup.
 
Every time the service is used it causes a lookup by the ServiceDynamicInterceptor:
 
"pool-1-thread-39" prio=10 tid=0x00000000548e2000 nid=0x36a8 waiting for monitor entry [0x0000000046003000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at org.eclipse.osgi.framework.internal.core.BundleContextImpl.getService(BundleContextImpl.java:661)
        - locked <0x00002aaab5983528> (a java.lang.Object)
        at org.springframework.osgi.service.importer.support.internal.support.ServiceWrapper.getService(ServiceWrapper.java:99)
        at org.springframework.osgi.service.importer.support.internal.aop.ServiceDynamicInterceptor$ServiceLookUpCallback.doWithRetry(ServiceDynamicInterceptor.java:107)
        at org.springframework.osgi.service.importer.support.internal.support.RetryTemplate.execute(RetryTemplate.java:83)
        at org.springframework.osgi.service.importer.support.internal.aop.ServiceDynamicInterceptor.lookupService(ServiceDynamicInterceptor.java:430)
        - locked <0x00002aaab5d16508> (a java.lang.Object)
        at org.springframework.osgi.service.importer.support.internal.aop.ServiceDynamicInterceptor.getTarget(ServiceDynamicInterceptor.java:415)
        at org.springframework.osgi.service.importer.support.internal.aop.ServiceInvoker.invoke(ServiceInvoker.java:62)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:131)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:119)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.osgi.service.importer.support.LocalBundleContextAdvice.invoke(LocalBundleContextAdvice.java:59)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:131)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:119)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy124.requestHandler(Unknown Source)
 
org.eclipse.osgi.framework.internal.core.BundleContextImpl ends up in ServiceUse.getService()
 
 
In here there is a counter, useCount, which is incremented on every get. It is decremented in ungetService but this is not called by Spring DM. In this case useCount eventually wraps round and becomes a negative number. The following check in getService then fails:
 
        Object getService() {
               if ((useCount > 0) || (factory == null)) {
                       useCount++;
                       return cachedService;
               }
 
This causes the service to be reloaded. The stack trace when the performance degrades shows this happening:
 
        at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass_LockClassLoader(ClasspathManager.java:468)
        - waiting to lock <0x00002aaab59679f0> (a org.eclipse.virgo.kernel.userregion.internal.equinox.KernelBundleClassLoader)
        at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:449)
        at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:216)
        at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:393)
        at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:469)
        at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:422)
        at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:410)
        at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:107)
        at org.eclipse.virgo.kernel.userregion.internal.equinox.KernelBundleClassLoader.loadClass(KernelBundleClassLoader.java:135)
        at java.lang.ClassLoader.loadClass(Unknown Source)
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.checkServiceClass(ServiceRegistry.java:1015)
        at org.eclipse.osgi.internal.serviceregistry.ServiceUse.getService(ServiceUse.java:146)
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:447)
        - locked <0x00002aaab5983420> (a org.eclipse.osgi.internal.serviceregistry.ServiceUse)
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:430)
        at org.eclipse.osgi.framework.internal.core.BundleContextImpl.getService(BundleContextImpl.java:667)
        at org.springframework.osgi.service.importer.support.internal.support.ServiceWrapper.getService(ServiceWrapper.java:99)
        at org.springframework.osgi.service.importer.support.internal.aop.ServiceDynamicInterceptor$ServiceLookUpCallback.doWithRetry(ServiceDynamicInterceptor.java:107)
        at org.springframework.osgi.service.importer.support.internal.support.RetryTemplate.execute(RetryTemplate.java:83)
        at org.springframework.osgi.service.importer.support.internal.aop.ServiceDynamicInterceptor.lookupService(ServiceDynamicInterceptor.java:430)
        - locked <0x00002aaab5d1d790> (a java.lang.Object)
        at org.springframework.osgi.service.importer.support.internal.aop.ServiceDynamicInterceptor.getTarget(ServiceDynamicInterceptor.java:415)
        at org.springframework.osgi.service.importer.support.internal.aop.ServiceInvoker.invoke(ServiceInvoker.java:62)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:131)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:119)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.osgi.service.importer.support.LocalBundleContextAdvice.invoke(LocalBundleContextAdvice.java:59)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:131)
        at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:119)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
        at $Proxy123.handleRequest(Unknown Source)
 
 
The service will continue to be reloaded until useCount increments to 0! This explains the behavior shown in the graph where the performance is restored.
 
Is there something we can do to work-around the problem?
 
Regards,
 
Shaun McGinnity
_______________________________________________
virgo-dev mailing list
virgo-dev@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/virgo-dev
 
_______________________________________________
virgo-dev mailing list
virgo-dev@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/virgo-dev