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.
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
