On Thu, Jan 14, 2010 at 4:38 PM, Martin Gerner
<martin.ger...@postgrad.manchester.ac.uk
<mailto:martin.ger...@postgrad.manchester.ac.uk>> wrote:
Hi Andreas (and the rest of you),
Thank you very much for your answer.
Seeing as the problem seems to be in accessing the .jar file, I
extracted the .jar file to the services directory and then removed
the .jar file, so axis2 could access the service in an already
extracted format. The access times are now down to what I would
expect them to be, and everything seems to be running fine.
I'm now guessing that the extremely slow accessing of the service
.jar file is related to the following warning I get during axis2
startup: "[WARN] Exception extracting jars into temporary
directory : java.io.IOException: No such file or directory :
switching to alternate class loading mechanism". It would be nice
to be able to solve this root cause of the problem (both so I can
go back to using .jars but also for future readers of this
conversation), but I have been unable to find where this
"temporary directory" is set (so I could change the directory to
something that would work). As far as I can tell, conf/axis2.xml
does not contain any option for this.
It is a bit irritating that the warning does not specify what path
the temporary directory is - that would really be a helpful
addition to the warning message. Axis2 does make use of the /tmp
directory, which it can access (and indeed does store data in)
which just makes it more strange.
normally axis2 creates the temp files at the "java.io.tmpdir".
String tmpDirName = System.getProperty("java.io.tmpdir");
For linux this is /tmp. Could you swith on the debug (which you should
be able to do with log4j file) and see the real exception.
On 13/01/2010 19:17, Andreas Veithen wrote:
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
<mailto: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 <mailto: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
<mailto: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)
--
Martin Gerner
Faculty of Life Sciences
Michael Smith Building
University of Manchester
Manchester, M13 9PT
--
Amila Suriarachchi
WSO2 Inc.
blog: http://amilachinthaka.blogspot.com/
