The issue seems to be as follows: * For POJO services, Axis2 uses the JRE's bean introspector to detect the properties of the POJOs. * Following the Java Beans standard, the introspector attempts to find BeanInfo classes corresponding to these POJOs. BeanInfo classes are optional and rarely used in this context. * Axis2 uses the service class loader to introspect the beans. This is not a standard class loader, but a component specific to Axis2 (DeploymentClassLoader) which uses a different strategy to load the classes. I had a quick look at the code, and it appears that in order to load a class, it needs to scan all the JARs used by the service archive.
Conclusion: in this case, Axis2 repeatedly attempts to load non existing classes from a class loader that uses a suboptimal strategy to load resources from JARs. Unfortunately, I'm not very familiar with the POJO and class loading parts of Axis2. Maybe some of the other developers can shed some light on the following questions: * Shouldn't the POJO code cache the results returned by the bean introspector? * Why is the DeploymentClassLoader implemented in this way? My guess is that it is to avoid file locking issues. Thus, it is only used when hot deployment is enabled? Andreas On Wed, Jan 13, 2010 at 15:24, Martin Gerner <martin.ger...@postgrad.manchester.ac.uk> wrote: > I've attached a full thread dump. I'd greatly appreciate any help in > determining the cause, as I'm quite a novice when it comes to Axis2 and its > internal workings. CPU usage for the java process goes up to 100% when it's > blocking. > > The top parts of a few dumps (taken at different times to get an idea about > whether it's the same thing blocking): > > "HttpConnection-8080-1" prio=10 tid=0x08c06c00 nid=0x1c77 runnable > [0x2e9fe000] > java.lang.Thread.State: RUNNABLE > at java.util.zip.Inflater.inflateBytes(Native Method) > at java.util.zip.Inflater.inflate(Inflater.java:223) > - locked <0xa65b86e0> (a java.util.zip.Inflater) > at > java.util.zip.InflaterInputStream.read(InflaterInputStream.java:135) > at java.util.zip.ZipInputStream.read(ZipInputStream.java:146) > at java.util.zip.ZipInputStream.closeEntry(ZipInputStream.java:92) > at java.util.zip.ZipInputStream.getNextEntry(ZipInputStream.java:70) > at > org.apache.axis2.deployment.DeploymentClassLoader.getBytes(DeploymentClassLoader.java:198) > at > org.apache.axis2.deployment.DeploymentClassLoader.getBytes(DeploymentClassLoader.java:178) > at > org.apache.axis2.deployment.DeploymentClassLoader.findClass(DeploymentClassLoader.java:81) > at java.lang.ClassLoader.loadClass(ClassLoader.java:307) > - locked <0x34220a70> (a > org.apache.axis2.deployment.DeploymentClassLoader) > at java.lang.ClassLoader.loadClass(ClassLoader.java:252) > at java.beans.Introspector.instantiate(Introspector.java:1453) > [...] > > > ---- > > "HttpConnection-8080-2" prio=10 tid=0x08a4fc00 nid=0x1cf6 runnable > [0x2e9ad000] > java.lang.Thread.State: RUNNABLE > at java.util.zip.ZipInputStream.readFully(ZipInputStream.java:403) > at java.util.zip.ZipInputStream.readEnd(ZipInputStream.java:361) > at java.util.zip.ZipInputStream.read(ZipInputStream.java:148) > at java.util.zip.ZipInputStream.closeEntry(ZipInputStream.java:92) > at java.util.zip.ZipInputStream.getNextEntry(ZipInputStream.java:70) > at > org.apache.axis2.deployment.DeploymentClassLoader.getBytes(DeploymentClassLoader.java:198) > at > org.apache.axis2.deployment.DeploymentClassLoader.getBytes(DeploymentClassLoader.java:178) > at > org.apache.axis2.deployment.DeploymentClassLoader.findClass(DeploymentClassLoader.java:81) > at java.lang.ClassLoader.loadClass(ClassLoader.java:307) > - locked <0x342afa70> (a > org.apache.axis2.deployment.DeploymentClassLoader) > at java.lang.ClassLoader.loadClass(ClassLoader.java:252) > at java.beans.Introspector.instantiate(Introspector.java:1453) > > ---- > > Best wishes, > Martin Gerner > > On 13/01/2010 12:30, Andreas Veithen wrote: >> >> The type of databinding cannot account for this delay. I would suggest >> to take a thread dump and try to understand where Axis2 is blocking. >> >> Andreas >> >> On Wed, Jan 13, 2010 at 13:04, Bruno Simioni <brunosimi...@gmail.com> >> wrote: >> >>> >>> Maybe using JAXB annotations on Java return objects, you can speed up the >>> process. >>> >>> Bruno. >>> >>> On Wed, Jan 13, 2010 at 9:51 AM, Martin Gerner >>> <martin.ger...@postgrad.manchester.ac.uk> wrote: >>> >>>> >>>> Hi all, >>>> >>>> I'm running a simple web service which receives a string from the >>>> client, processes it and returns an array of custom objects (nothing >>>> complicated, they're just data holders containing a few ints, strings >>>> and booleans). While the actual serverside processing performed by my >>>> server code is performed very fast, the response times from the server >>>> are very large and seem to be linear in the number of returned objects. >>>> >>>> A short example: if I send a string to the server which results in 0 >>>> objects being returned, the response from the server is received just a >>>> few milliseconds after the request is made. If the string is modified >>>> such that it returns one object, that increases to 8 seconds, and if it >>>> returns two objects it increases to 16 seconds. In all cases, I can see >>>> that the actual processing takes less than a second, so the web service >>>> java code that I've deployed is handling the requests quickly. >>>> >>>> All responses are small in size - the largest is ~900 bytes (so I can't >>>> imagine that it's an XML transformation issue). Using packet sniffers, I >>>> can see that the delay definitely is occurring on the server side (for >>>> the last example, I could see the POST packet going to the server, and >>>> then the response packet coming back 16 seconds later). Going by client >>>> and server log timings, I can see that the delay occurs after processing >>>> rather than before. >>>> >>>> I'm running axis2 1.5.1 with default settings, have tested it running on >>>> both the bundled SimpleAxisServer and Tomcat (both on a Debian server) >>>> and am using a very simple client based on code auto-generated by axis >>>> from the WSDL (running in Windows). >>>> >>>> Does anybody here have any clue as to what's causing the delays? It >>>> seems clear enough that it's something in the internal axis2 system, but >>>> as I'm quite new to axis2 I'm having difficulties locating the issue. >>>> >>>> Best wishes, >>>> Martin Gerner >>>> >>> >>> > > > -- > Martin Gerner > Faculty of Life Sciences > Michael Smith Building > University of Manchester > Manchester, M13 9PT > > > Full thread dump Java HotSpot(TM) Server VM (14.2-b01 mixed mode): > > "HttpConnection-8080-1" prio=10 tid=0x08c06c00 nid=0x1c77 runnable > [0x2e9fe000] > java.lang.Thread.State: RUNNABLE > at java.util.zip.Inflater.inflateBytes(Native Method) > at java.util.zip.Inflater.inflate(Inflater.java:223) > - locked <0xa65b86e0> (a java.util.zip.Inflater) > at > java.util.zip.InflaterInputStream.read(InflaterInputStream.java:135) > at java.util.zip.ZipInputStream.read(ZipInputStream.java:146) > at java.util.zip.ZipInputStream.closeEntry(ZipInputStream.java:92) > at java.util.zip.ZipInputStream.getNextEntry(ZipInputStream.java:70) > at > org.apache.axis2.deployment.DeploymentClassLoader.getBytes(DeploymentClassLoader.java:198) > at > org.apache.axis2.deployment.DeploymentClassLoader.getBytes(DeploymentClassLoader.java:178) > at > org.apache.axis2.deployment.DeploymentClassLoader.findClass(DeploymentClassLoader.java:81) > at java.lang.ClassLoader.loadClass(ClassLoader.java:307) > - locked <0x34220a70> (a > org.apache.axis2.deployment.DeploymentClassLoader) > at java.lang.ClassLoader.loadClass(ClassLoader.java:252) > at java.beans.Introspector.instantiate(Introspector.java:1453) > at > java.beans.Introspector.findExplicitBeanInfo(Introspector.java:425) > - locked <0x303c7a30> (a java.lang.Class for java.beans.Introspector) > at java.beans.Introspector.<init>(Introspector.java:374) > at java.beans.Introspector.getBeanInfo(Introspector.java:231) > at java.beans.Introspector.getBeanInfo(Introspector.java:217) > at > org.apache.axis2.databinding.utils.BeanUtil.getPropertyQnameList(BeanUtil.java:132) > at > org.apache.axis2.databinding.utils.BeanUtil.getPullParser(BeanUtil.java:67) > at > org.apache.axis2.databinding.utils.reader.ADBXMLStreamReaderImpl.processProperties(ADBXMLStreamReaderImpl.java:998) > at > org.apache.axis2.databinding.utils.reader.ADBXMLStreamReaderImpl.next(ADBXMLStreamReaderImpl.java:854) > at org.apache.axis2.util.StreamWrapper.next(StreamWrapper.java:71) > at > javax.xml.stream.util.StreamReaderDelegate.next(StreamReaderDelegate.java:60) > at > org.apache.axiom.om.impl.builder.SafeXMLStreamReader.next(SafeXMLStreamReader.java:183) > at > org.apache.axiom.om.impl.builder.StAXOMBuilder.parserNext(StAXOMBuilder.java:597) > at > org.apache.axiom.om.impl.builder.StAXOMBuilder.next(StAXOMBuilder.java:172) > at > org.apache.axiom.om.impl.llom.OMNodeImpl.build(OMNodeImpl.java:335) > at > org.apache.axiom.om.impl.llom.OMElementImpl.build(OMElementImpl.java:737) > at > org.apache.axiom.om.impl.llom.OMElementImpl.detach(OMElementImpl.java:706) > at > org.apache.axiom.om.impl.llom.OMNodeImpl.setParent(OMNodeImpl.java:124) > at > org.apache.axiom.om.impl.llom.OMElementImpl.addChild(OMElementImpl.java:297) > at > org.apache.axiom.om.impl.llom.OMElementImpl.addChild(OMElementImpl.java:213) > at > org.apache.axiom.soap.impl.llom.SOAPBodyImpl.addChild(SOAPBodyImpl.java:231) > at > org.apache.axis2.rpc.receivers.RPCUtil.processResponseAsDocLitWrapped(RPCUtil.java:381) > at > org.apache.axis2.rpc.receivers.RPCMessageReceiver.invokeBusinessLogic(RPCMessageReceiver.java:138) > at > org.apache.axis2.receivers.AbstractInOutMessageReceiver.invokeBusinessLogic(AbstractInOutMessageReceiver.java:40) > at > org.apache.axis2.receivers.AbstractMessageReceiver.receive(AbstractMessageReceiver.java:114) > at org.apache.axis2.engine.AxisEngine.receive(AxisEngine.java:173) > at > org.apache.axis2.transport.http.HTTPTransportUtils.processHTTPPostRequest(HTTPTransportUtils.java:167) > at > org.apache.axis2.transport.http.HTTPWorker.service(HTTPWorker.java:266) > at > org.apache.axis2.transport.http.server.AxisHttpService.doService(AxisHttpService.java:281) > at > org.apache.axis2.transport.http.server.AxisHttpService.handleRequest(AxisHttpService.java:187) > at > org.apache.axis2.transport.http.server.HttpServiceProcessor.run(HttpServiceProcessor.java:82) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:619) > > "DestroyJavaVM" prio=10 tid=0x2ee3c000 nid=0x1c66 waiting on condition > [0x00000000] > java.lang.Thread.State: RUNNABLE > > "HttpListener-8080-1" prio=10 tid=0x2f013400 nid=0x1c75 runnable > [0x2ebad000] > java.lang.Thread.State: RUNNABLE > at java.net.PlainSocketImpl.socketAccept(Native Method) > at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390) > - locked <0x34998010> (a java.net.SocksSocketImpl) > at java.net.ServerSocket.implAccept(ServerSocket.java:453) > at java.net.ServerSocket.accept(ServerSocket.java:421) > at > org.apache.axis2.transport.http.server.DefaultConnectionListener.run(DefaultConnectionListener.java:79) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:619) > > "Timer-1" daemon prio=10 tid=0x0896ac00 nid=0x1c74 in Object.wait() > [0x2ebfe000] > java.lang.Thread.State: TIMED_WAITING (on object monitor) > at java.lang.Object.wait(Native Method) > - waiting on <0x3445d260> (a java.util.TaskQueue) > at java.util.TimerThread.mainLoop(Timer.java:509) > - locked <0x3445d260> (a java.util.TaskQueue) > at java.util.TimerThread.run(Timer.java:462) > > "Timer-0" daemon prio=10 tid=0x08c17c00 nid=0x1c73 in Object.wait() > [0x2eda7000] > java.lang.Thread.State: TIMED_WAITING (on object monitor) > at java.lang.Object.wait(Native Method) > - waiting on <0x342b3a08> (a java.util.TaskQueue) > at java.util.TimerThread.mainLoop(Timer.java:509) > - locked <0x342b3a08> (a java.util.TaskQueue) > at java.util.TimerThread.run(Timer.java:462) > > "Low Memory Detector" daemon prio=10 tid=0x2f78d800 nid=0x1c6f runnable > [0x00000000] > java.lang.Thread.State: RUNNABLE > > "CompilerThread1" daemon prio=10 tid=0x2f78b400 nid=0x1c6e waiting on > condition [0x00000000] > java.lang.Thread.State: RUNNABLE > > "CompilerThread0" daemon prio=10 tid=0x2f789800 nid=0x1c6d waiting on > condition [0x00000000] > java.lang.Thread.State: RUNNABLE > > "Signal Dispatcher" daemon prio=10 tid=0x2f788000 nid=0x1c6c waiting on > condition [0x00000000] > java.lang.Thread.State: RUNNABLE > > "Finalizer" daemon prio=10 tid=0x2f778800 nid=0x1c6b in Object.wait() > [0x2f517000] > java.lang.Thread.State: WAITING (on object monitor) > at java.lang.Object.wait(Native Method) > - waiting on <0x341b10f0> (a java.lang.ref.ReferenceQueue$Lock) > at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118) > - locked <0x341b10f0> (a java.lang.ref.ReferenceQueue$Lock) > at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134) > at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) > > "Reference Handler" daemon prio=10 tid=0x2f777000 nid=0x1c6a in > Object.wait() [0x2f568000] > java.lang.Thread.State: WAITING (on object monitor) > at java.lang.Object.wait(Native Method) > - waiting on <0x341b1110> (a java.lang.ref.Reference$Lock) > at java.lang.Object.wait(Object.java:485) > at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116) > - locked <0x341b1110> (a java.lang.ref.Reference$Lock) > > "VM Thread" prio=10 tid=0x2f773000 nid=0x1c69 runnable > > "GC task thread#0 (ParallelGC)" prio=10 tid=0x08891800 nid=0x1c67 runnable > > "GC task thread#1 (ParallelGC)" prio=10 tid=0x08893000 nid=0x1c68 runnable > > "VM Periodic Task Thread" prio=10 tid=0x2f78f800 nid=0x1c70 waiting on > condition > > JNI global references: 1196 > > Heap > PSYoungGen total 105984K, used 11722K [0xa5e10000, 0xacb90000, > 0xb4190000) > eden space 103232K, 8% used [0xa5e10000,0xa66d9fc8,0xac2e0000) > from space 2752K, 98% used [0xac8e0000,0xacb889e8,0xacb90000) > to space 4096K, 0% used [0xac390000,0xac390000,0xac790000) > PSOldGen total 23552K, used 18525K [0x34190000, 0x35890000, > 0xa5e10000) > object space 23552K, 78% used [0x34190000,0x353a7510,0x35890000) > PSPermGen total 16384K, used 8087K [0x30190000, 0x31190000, > 0x34190000) > object space 16384K, 49% used [0x30190000,0x30975f70,0x31190000) >
