axis-java-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Amila Suriarachchi <amilasuriarach...@gmail.com>
Subject Re: Axis2 1.5.1 service handling is very slow
Date Thu, 14 Jan 2010 14:36:22 GMT
On Thu, Jan 14, 2010 at 4:38 PM, Martin Gerner <
martin.gerner@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.

thanks,
Amila.

>
> All the best,
> Martin
>
>
>
> 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.gerner@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 <brunosimioni@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.gerner@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/

Mime
View raw message