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)
