Help with java profiling (-Xrunhprof)

  • Thread starter NahtMy ReelName
  • Start date
N

NahtMy ReelName

I can't seem to get a decent profile with CPU activity of a tomcat run.

$ export
CATALINA_HOME="-Xrunhprof:cpu=times,file=/tmp/times.prof,depth=12,cutoff=0"

$ CATALINA_HOME/bin/startup.sh

The problem is that whether cpu=times or cpu=samples
It looks like the timing/sampling/counting information stops after some
limited amount.

So a cpu=times run will go for an hour, but appears to have non-zero
data for things run in the first minute.

E.g.:

CPU TIME (ms) BEGIN (total = 75800) Sun Oct 5 14:33:10 2003
rank self accum count trace method
1 26.50% 26.50% 36 547 java.lang.Object.wait
2 22.09% 48.59% 281 369 java.lang.Thread.sleep
3 10.58% 59.17% 536 549 java.lang.Thread.sleep
4 10.58% 69.76% 135 546 java.lang.Object.wait
5 10.56% 80.32% 7899 548 java.net.PlainSocketImpl.socketAccept
6 6.10% 86.42% 335 140 java.lang.Object.wait
7 6.10% 92.53% 150 139 java.lang.Object.wait
8 5.20% 97.72% 1 1381 java.net.PlainSocketImpl.socketAccept
9 0.10% 97.82% 233 1046 java.net.SocketInputStream.socketRead0
10 0.08% 97.91% 4344996 1290 org.apache.xerces.util.XMLChar.isContent
11 0.05% 97.96% 2367420 1090 org.apache.xerces.util.XMLChar.isInvalid
12 0.05% 98.01% 2367420 1201 org.apache.xerces.util.XMLChar.isValid
13 0.04% 98.05% 203 893 java.net.SocketOutputStream.socketWrite0

So far so good, but later:

656 0.00% 100.00% 0 306
com.sun.xml.messaging.jaxm.provider.TransportDescriptor.initErrorDescriptor
657 0.00% 100.00% 0 249
org.apache.catalina.core.StandardWrapper.<init>
658 0.00% 100.00% 0 228
org.apache.catalina.startup.WebRuleSet.addRuleInstances
659 0.00% 100.00% 0 1 <empty trace>
660 0.00% 100.00% 0 875
cm.rep.WorkspaceSubsystemPathMap.resolveWsRelativeFileName
661 0.00% 100.00% 0 778 cm.rep.Repository.<init>
662 0.00% 100.00% 0 599
javax.mail.internet.InternetHeaders.addHeaderLine

All the 'count' fields are zero! And I know these things are called,
you can see it in the traces too. So I'll have a thousand interesting
method calls none of which are profiled.



Similarly, if I enable cpu=samples:

CPU SAMPLES BEGIN (total = 10074) Sun Oct 5 12:56:59 2003
rank self accum count trace method
1 53.44% 53.44% 5384 443 java.net.PlainSocketImpl.socketAccept
2 26.75% 80.20% 2695 464 java.net.PlainSocketImpl.socketAccept
3 16.51% 96.70% 1663 471 java.net.SocketInputStream.socketRead0
4 0.35% 97.05% 35 636 java.net.SocketInputStream.socketRead0
5 0.27% 97.32% 27 646 java.net.SocketOutputStream.socketWrite0
6 0.15% 97.47% 15 103 java.lang.StringBuffer.expandCapacity
7 0.06% 97.53% 6 133 java.lang.ClassLoader.defineClass0

by item #216 I'm at zero counts again:

216 0.00% 100.00% 0 780 cm.rep.WorkspaceVersionDeltas.iterator
217 0.00% 100.00% 0 774
org.postgresql.jdbc1.AbstractJdbc1Statement.setBytes
218 0.00% 100.00% 0 588
org.apache.xerces.impl.xs.traversers.XSDHandler.getSchema
219 0.00% 100.00% 0 1 <empty trace>
220 0.00% 100.00% 0 808
cm.rep.CompositeViewProcessor.ensureNodePoolCapacity
221 0.00% 100.00% 0 607
org.apache.xerces.impl.xs.traversers.XSDElementTraverser.<init>
222 0.00% 100.00% 0 423
org.apache.naming.resources.WARDirContext.loadEntries
223 0.00% 100.00% 0 621
org.apache.xerces.impl.xs.traversers.XSDComplexTypeTraverser.traverseComplexTypeDecl



I've tried all kinds of cutoff values (zero seems to get the most data,
but the switch isn't documented that well).

I'm running Java 1.4.2+ on Redhat 9.0, with the Tomcat shipped as part
of JWSDP1.1.

Anybody else have similar experiences?

What's the solution?
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Members online

Forum statistics

Threads
473,744
Messages
2,569,479
Members
44,899
Latest member
RodneyMcAu

Latest Threads

Top