Re: [virgo-dev] Performance degradation problem

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]

Re: [virgo-dev] Performance degradation problem

From: Glyn Normington <gnormington@xxxxxxxxxx>
Date: Tue, 28 Jun 2011 16:17:56 +0100
Delivered-to: virgo-dev@xxxxxxxxxxx
List-archive: <https://dev.eclipse.org/mailman/private/virgo-dev>
List-help: <mailto:virgo-dev-request@eclipse.org?subject=help>
List-subscribe: <https://dev.eclipse.org/mailman/listinfo/virgo-dev>, <mailto:virgo-dev-request@eclipse.org?subject=subscribe>
List-unsubscribe: <https://dev.eclipse.org/mailman/options/virgo-dev>, <mailto:virgo-dev-request@eclipse.org?subject=unsubscribe>

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

Follow-Ups:
- Re: [virgo-dev] Performance degradation problem
  - From: Shaun McGinnity

References:
- [virgo-dev] Performance degradation problem
  - From: Shaun McGinnity

Prev by Date: [virgo-dev] Performance degradation problem
Next by Date: Re: [virgo-dev] Performance degradation problem
Previous by thread: [virgo-dev] Performance degradation problem
Next by thread: Re: [virgo-dev] Performance degradation problem
Index(es):
- Date
- Thread

Breadcrumbs