performance analysis help

former_member245181 · ‎2006 Dec 07

Hi All,

I used the information in web blog : /people/markus.kohler/blog/2006/09/14/analyzing-performance-problems-on-a-production-system to perform a thread dump while our system was very busy. During this time, I coud see that the top CPU process was a server process 'jlaunch'. I then took a thread dump of this process using jcmon and then ran the grep/sort/uniq command against the thread dump. The result is below. Can anyone assist in what can be the cause of our high CPU utilization?

*********************************************************

247 at java.lang.Object.wait(Native Method)

211 at java.lang.Object.wait(Object.java:429)

151 at com.sap.engine.lib.util.WaitQueue.dequeue(WaitQueue.java:238)

78 at com.sap.engine.core.thread.impl3.SingleThread.run(SingleThread.java:147)

73 at com.sap.engine.core.thread.impl5.SingleThread.run(SingleThread.java:127)

64 at java.lang.Thread.run(Thread.java:534)

39 at java.lang.Thread.sleep(Native Method)

20 at com.sap.engine.frame.core.thread.Task.run(Task.java:64)

20 at com.sap.engine.core.thread.impl5.SingleThread.run(SingleThread.java:150)

20 at com.sap.engine.core.thread.impl5.SingleThread.execute(SingleThread.java:79)

17 at java.security.AccessController.doPrivileged(Native Method)

15 at com.sapportals.wcm.util.events.EventSenderThread.run(EventSenderThread.java:74)

15 at com.sapportals.wcm.util.events.EventQueue.dequeue(EventQueue.java:68)

13 at com.sap.engine.core.thread.impl3.SingleThread.run(SingleThread.java:170)

13 at com.sap.engine.core.thread.impl3.SingleThread.execute(SingleThread.java:100)

13 at com.sap.engine.core.thread.impl3.ActionObject.run(ActionObject.java:37)

13 at EDU.oswego.cs.dl.util.concurrent.SynchronousChannel.take(SynchronousChannel.java:209)

13 at EDU.oswego.cs.dl.util.concurrent.PooledExecutor.getTask(PooledExecutor.java:707)

13 at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:727)

10 at java.util.TimerThread.run(Timer.java:382)

10 at java.net.SocketInputStream.socketRead0(Native Method)

10 at java.net.SocketInputStream.read(SocketInputStream.java:129)

10 at com.sapportals.portal.prt.jndisupport.util.AbstractHierarchicalContext.lookup(AbstractHierarchicalContext.java:165

)

9 at java.util.TimerThread.mainLoop(Timer.java:429)

8 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:127)

8 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:111)

7 at java.io.BufferedInputStream.read1(BufferedInputStream.java:222)

7 at java.io.BufferedInputStream.read(BufferedInputStream.java:277)

7 at java.io.BufferedInputStream.fill(BufferedInputStream.java:183)

6 at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)

5 at com.sun.jndi.ldap.Connection.run(Connection.java:784)

5 at com.sap.engine.cache.util.ReferenceQueueRunnable.run(ReferenceQueueRunnable.java:43)

5 at com.sap.caf.eu.gp.model.forms.co.IFormsTimeoutProcessor.run(IFormsTimeoutProcessor.java:150)

4 at javax.naming.InitialContext.lookup(InitialContext.java:347)

4 at com.sap.engine.services.servlets_jsp.server.HttpHandlerImpl.handleRequest(HttpHandlerImpl.java:264)

4 at com.sap.engine.services.httpserver.server.RequestAnalizer.startServlet(RequestAnalizer.java:347)

4 at com.sap.engine.services.httpserver.server.RequestAnalizer.startServlet(RequestAnalizer.java:325)

4 at com.sap.engine.services.httpserver.server.RequestAnalizer.invokeWebContainer(RequestAnalizer.java:887)

4 at com.sap.engine.services.httpserver.server.RequestAnalizer.handle(RequestAnalizer.java:241)

4 at com.sap.engine.services.httpserver.server.Processor.request(Processor.java:148)

4 at com.sap.engine.services.httpserver.server.Client.handle(Client.java:92)

*********************************************************

Thanks in advance,

Regards

Anthony

former_member245181 · ‎2006 Dec 07

Hi Again, further information:

I took several thread dumps over a period of 15 seconds, then used the 'Samurai' as mentioned in https://www.sdn.sap.com/irj/sdn/weblogs?blog=/pub/wlg/4425. [original link is broken] [original link is broken] It is interesting to see that there are 4 threads that seem to be accessing the LDAP the whole time (ie):

"Thread-1927" daemon prio=5 tid=0x0000000102109790 nid=0x8a0 runnable at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at java.io.BufferedInputStream.fill(BufferedInputStream.java:183) at java.io.BufferedInputStream.read1(BufferedInputStream.java:222) at java.io.BufferedInputStream.read(BufferedInputStream.java:277) - locked <

0xfffffffeb0313a78> (a java.io.BufferedInputStream) at com.sun.jndi.ldap.Connection.run(Connection.java:784) at java.lang.Thread.run(Thread.java:534)

Do you agree that this looks like an LDAP lookup issue? I will analyse this further and let you know if I have any further information.

Regards

Anthony

kohlerm · ‎2006 Dec 07

Hi,

> Hi Again, further information:

> I took several thread dumps over a period of 15

> seconds, then used the 'Samurai' as mentioned in

> https://www.sdn.sap.com/irj/sdn/weblogs?blog=/pub/wlg/

> 4425. It is interesting to see that there are 4

> threads that seem to be accessing the LDAP the whole

> time (ie):

>

> "Thread-1927" daemon prio=5 tid=0x0000000102109790

> nid=0x8a0 runnable

> [fffffffe4c9ff000..fffffffe4c9ff8b0] at

> java.net.SocketInputStream.socketRead0(Native Method)

> at

> java.net.SocketInputStream.read(SocketInputStream.java

> :129) at

> java.io.BufferedInputStream.fill(BufferedInputStream.j

> ava:183) at

> java.io.BufferedInputStream.read1(BufferedInputStream.

> java:222) at

> java.io.BufferedInputStream.read(BufferedInputStream.j

> ava:277) - locked <

> 0xfffffffeb0313a78> (a java.io.BufferedInputStream)

> at

> com.sun.jndi.ldap.Connection.run(Connection.java:784)

> at java.lang.Thread.run(Thread.java:534)

>

> Do you agree that this looks like an LDAP lookup

> issue?

It seems to me that the only interesting methods that show up in your thread dumps are related to jndi, which could be related to LDAP.

I'm a bit surprised that this would cause high cpu load because usually, accessing LDAP is not CPU intensive.

I would recommend to take more thread dumps using the sapntkill command as described in my blog (the one you already referenced).

I would also check the garbage collector activity. Maybe full GC's are causing the high cpu consumption.

Regards,

Markus

> I will analyse this further and let you know

> if I have any further information.

>

> Regards

> Anthony

former_member245181 · ‎2006 Dec 11

Hi Markus,

Thanks for your response. I'm not sure if the 'com.sun.jndi.ldap.Connection.run' is the reason for our CPU usage being high, but what I can say is that whenever I see the CPU high and run a series of thread dumps, I always see a set of threads (typically 5 threads) that were running for the whole period and the thread output for these looks like :

""Thread-5497" daemon prio=5 tid=0x0000000102da2160 nid=0x1651 runnable at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at java.io.BufferedInputStream.fill(BufferedInputStream.java:183) at java.io.BufferedInputStream.read1(BufferedInputStream.java:222) at java.io.BufferedInputStream.read(BufferedInputStream.java:277) - locked <

0xfffffffeec888ef8> (a java.io.BufferedInputStream) at com.sun.jndi.ldap.Connection.run(Connection.java:784) at java.lang.Thread.run(Thread.java:534)"

There are other threads that typically run for the whole period also (period is about 15sec of thread dump captures). These are listed below:

***************************

"SAPDSR_watcher"

Thread dump 1/8 "SAPDSR_watcher" prio=10 tid=0x0000000102083440 nid=0xd1 runnable at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:353) - locked <

0xfffffffe960d7ea0> (a java.net.PlainSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:448) at java.net.ServerSocket.accept(ServerSocket.java:419) at com.sap.jdsr.writer.DsrListener.run(DsrListener.java:748)

***************************

"SAPEngine_EnquReader"

Thread dump 1/8 "SAPEngine_EnquReader" prio=5 tid=0x0000000101f48be0 nid=0x8b runnable at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at com.sap.bc.krn.enqu.EncomiHandle.ReceiveMessage(EncomiHandle.java:483) - locked <

0xfffffffe92f43a78> (a java.lang.Object) at com.sap.bc.krn.enqu.EnccliMultiplexHandle.receive(EnccliMultiplexHandle.java:771) at com.sap.bc.krn.enqu.ReadRunnable.run(EnccliMultiplexHandle.java:958) at java.lang.Thread.run(Thread.java:534)

***************************

"Lazy Reader for cluster node 294620151"

Thread dump 1/8 "Lazy Reader for cluster node 294620151" prio=5 tid=0x0000000101809210 nid=0x87 runnable at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at com.sap.engine.core.cluster.impl6.lazy.MsgObj.read(MsgObj.java:107) at com.sap.engine.core.cluster.impl6.lazy.MsgObj.reuse(MsgObj.java:77) at com.sap.engine.core.cluster.impl6.lazy.MsgObjPool.get(MsgObjPool.java:74) at com.sap.engine.core.cluster.impl6.lazy.Reader.run(Reader.java:64) at com.sap.engine.frame.core.thread.Task.run(Task.java:64) at com.sap.engine.core.thread.impl5.SingleThread.execute(SingleThread.java:79) at com.sap.engine.core.thread.impl5.SingleThread.run(SingleThread.java:150)

***************************

"SAPEngine_System_Thread[impl:5]_7"

Thread dump 1/8 "SAPEngine_System_Thread[impl:5]_7" prio=5 tid=0x0000000101d0eeb0 nid=0x69 runnable at java.net.PlainSocketImpl.socketAccept(Native Method) at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:353) - locked <

0xfffffffe92f482d0> (a java.net.PlainSocketImpl) at java.net.ServerSocket.implAccept(ServerSocket.java:448) at com.sap.engine.core.cluster.impl6.net.ClusterServerSocket.accept(ClusterServerSocket.java:51) at com.sap.engine.core.cluster.impl6.JoinPortListener.run(JoinPortListener.java:72) at com.sap.engine.frame.core.thread.Task.run(Task.java:64) at com.sap.engine.core.thread.impl5.SingleThread.execute(SingleThread.java:79) at com.sap.engine.core.thread.impl5.SingleThread.run(SingleThread.java:150)

***************************

"SAP J2EE Engine|MS Socket Listener"

Thread dump 1/8 "SAP J2EE Engine|MS Socket Listener" prio=5 tid=0x0000000101d13a20 nid=0x64 runnable at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at java.io.BufferedInputStream.fill(BufferedInputStream.java:183) at java.io.BufferedInputStream.read1(BufferedInputStream.java:222) at java.io.BufferedInputStream.read(BufferedInputStream.java:277) - locked <

0xfffffffe92f535d8> (a java.io.BufferedInputStream) at com.sap.engine.core.cluster.impl6.ms.MSMessageHeader.read(MSMessageHeader.java:440) at com.sap.engine.core.cluster.impl6.ms.MSMessageObjectImpl.readHeader(MSMessageObjectImpl.java:142) at com.sap.engine.core.cluster.impl6.ms.MSRawConnection.receiveRawMessage(MSRawConnection.java:1660) at com.sap.engine.core.cluster.impl6.ms.MSListener.run(MSListener.java:86) at com.sap.engine.frame.core.thread.Task.run(Task.java:64) at com.sap.engine.core.thread.impl5.SingleThread.execute(SingleThread.java:79) at com.sap.engine.core.thread.impl5.SingleThread.run(SingleThread.java:150)

***************************

I guess my current questions are:

- I can see which threads are "running" at any period of time using thread dumps, but how can I tell which threads are the problematic and using the majority of CPU?

- Is it normal to often (if not always) see threads processing the "com.sun.jndi.ldap.Connection.run" ? If not, what are the things that I can check to rectify this?

Thanks for your time,

Regards

Anthony

former_member245181 · ‎2006 Dec 12

Hi Again,

I took a series of thread dumps while the system was idle (noone using the system and CPU ~100% idle) and could still see the running threads processing "com.sun.jndi.ldap.Connection.run". In fact, more threads were shown to be processing this than I've seen previously.

I now think that this is not the issue. The CPU load seems to be caused by one of the other threads.

I'll let you know what else I find.

Regards

Anthony

former_member245181 · ‎2006 Dec 12

I'm now going to use note 743206 to attempt to determine the worst performing threads.

kohlerm · ‎2006 Dec 12

> I'm now going to use note 743206 to attempt to

> determine the worst performing threads.

That's a good idea, and you can also use it together with the information from the thread dumps.

By the way, on Windows the same can be done using the pslist utility (

http://www.microsoft.com/technet/sysinternals/utilities/PsList.mspx)

I think I should write a blog entry about this ...

Regards,

Markus (/people/markus.kohler/blog)

former_member245181 · ‎2006 Dec 15

Any idea what this is used for?:

"SAPEngine_System_Thread[impl:5]_39" prio=5 tid=0x0000000101aa63f0 nid=0x66 runnable [fffffffe4ebfe000..fffffffe4ebff8b0]

at java.util.zip.Deflater.deflateBytes(Native Method)

at java.util.zip.Deflater.deflate(Deflater.java:287)

- locked <0xfffffffe9a846780> (a java.util.zip.Deflater)

at java.util.zip.DeflaterOutputStream.deflate(DeflaterOutputStream.java:154)

at java.util.zip.DeflaterOutputStream.write(DeflaterOutputStream.java:114)

at java.util.zip.ZipOutputStream.write(ZipOutputStream.java:260)

- locked <0xfffffffe91d678c0> (a java.util.zip.ZipOutputStream)

at com.sap.engine.services.log_configurator.archive.ArchivingThread.archiveTask(ArchivingThread.java:81)

at com.sap.engine.services.log_configurator.archive.ArchivingThread.run(ArchivingThread.java:40)

at com.sap.engine.frame.core.thread.Task.run(Task.java:64)

at com.sap.engine.core.thread.impl5.SingleThread.execute(SingleThread.java:79)

at com.sap.engine.core.thread.impl5.SingleThread.run(SingleThread.java:150)

I've seen this thread consume a about 400% more CPU than others at the same time.

Regards

Anthony

kohlerm · ‎2006 Dec 15

> Any idea what this is used for?:

Yes. your default.trace log files are getting archived, after some time.

Please check your log settings. Maybe you have a lot of errors, or some components on the log level debug.

Regards,

Markus

>

> "SAPEngine_System_Thread[impl:5]_39" prio=5

> tid=0x0000000101aa63f0 nid=0x66 runnable

> [fffffffe4ebfe000..fffffffe4ebff8b0]

> at java.util.zip.Deflater.deflateBytes(Native

> Method)

> at

> java.util.zip.Deflater.deflate(Deflater.java:287)

> - locked <0xfffffffe9a846780> (a

> java.util.zip.Deflater)

> at

> java.util.zip.DeflaterOutputStream.deflate(DeflaterOut

> putStream.java:154)

> at

> java.util.zip.DeflaterOutputStream.write(DeflaterOutpu

> tStream.java:114)

> at

> java.util.zip.ZipOutputStream.write(ZipOutputStream.ja

> va:260)

> - locked <0xfffffffe91d678c0> (a

> java.util.zip.ZipOutputStream)

> at

> com.sap.engine.services.log_configurator.archive.Archi

> vingThread.archiveTask(ArchivingThread.java:81)

> at

> com.sap.engine.services.log_configurator.archive.Archi

> vingThread.run(ArchivingThread.java:40)

> at

> com.sap.engine.frame.core.thread.Task.run(Task.java:64

> )

> at

> com.sap.engine.core.thread.impl5.SingleThread.execute(

> SingleThread.java:79)

> at

> com.sap.engine.core.thread.impl5.SingleThread.run(Sing

> leThread.java:150)

>

> I've seen this thread consume a about 400% more CPU

> than others at the same time.

>

> Regards

> Anthony

Former Member · ‎2007 Jan 15

Hi Anthony,

We are experiencing same issue in Dev box ( which has 4 CPUs and 12 GB physical RAM). Did you find any solution for your problem? I would appreciate if you could let us know your resolution if you have one

Thanks

Venkat

former_member245181 · ‎2007 Jan 15

Hi Venkat,

I assume that you mean you are getting the same 'java.util.zip.Deflater.deflateBytes' showing up in your thread dumps. Check your defaultTrace.trc file(s) (/usr/sap/<SID>/<instance>/cluster/server<n>/log). Try to stop the Portal from logging so frequently, by :

1- Rectify the issue causing the errors

2- Reduce your logging level (use Visual Admin -> Cluster -> Server<n> -> Services -> Log configuration).

In our case, I found the cause of the error and stopped it.

Regards

Anthony