Document ID: 0011
Topic: Java, JVM, HotSpot, Performance
Created: 2007-06-10
Last Updated: 2007-10-01
Author: Stefan Parvu
References:
OS: Solaris

My Java application is very slow

Often people are talking about their Java applications running very slow in PROD environments, or test machines. As more and more services are built on top of JVM it seems reasonable to talk about this and list some common procedures for administrators or Java developers, how to troubleshoot and identify these issues. Even if some of these procedures will look more friendly to a system administrator anyone in the Java development team can start using these procedures.

It is as well very interesting to see Dynamic Tracing methods being used versus traditional profiling, so Java developers can easily pickup new methods of understanding their applications!

Table of Contents

Basics		general knowledge
Profiling		basic Java profiling using JDK tools
DTrace		dynamic tracing your application: dvm, hotspot

---

Basics

Teams: Java Development, Support

Before you start debugging your application, make sure couple of things:

• Hardware side - Check for any hardware problems and make sure you are ok from infrastructure point of view: cpu, mem, disk, network. Check you dont have any failures in syslog.
  
  
• Software side - Make sure you are running the latest JDK or at least check carefully each Release Notes of your application vendor and JVM provider for any possible defects. This should be part of your normal activity and to stay uptodate. JDK updates should be included in your normal Software Update Plan.
  
  
• What is slow ? - Try to identify first what is slow: use common sense and try to basically see what Java application folks are saying. Use prstat, jmap, jstack, pstack from Solaris to collect initial observations.
  
  
• JVM Tuning - Check with your Java group if this application has ever been tuned from JVM point of view. Try to suggest them to tune the application by running a Tuning Procedure.
  
  

It is very important to have a tuning document where you record all these test cases and write down the findings.

---

Profiling

When you run in troubles and would like to know how your application really works you basically need to profile it. There are many ways of doing this: using the default JDK tools, free available profiling tools or use a commercial one. Whatever you use it is very good that you know how to use the tool and how to interpret the results.

The standard Java edition, J2SE contains a default profiler option which can be used to profile your application. Im selecting to talk about this since it is very easy to use and it is more simple from administration point of view. In your case use whatever tool you will think will do your job easier and more flexible.

• Xrunhprof
  JDK tools can be directly used, out of box to do basic profiling using the following startup option passed to the JVM: -Xrunhprof. This option will help to record the time spent in CPU and Heap.
  
  

  $ java -Xrunhprof:help HPROF: Heap and CPU Profiling Agent (JVMTI Demonstration Code) hprof usage: java -agentlib:hprof=[help]|[=, ...] Option Name and Value Description Default --------------------- ----------- ------- heap=dump|sites|all heap profiling all cpu=samples|times|old CPU usage off monitor=y|n monitor contention n format=a|b text(txt) or binary output a file= write data to file java.hprof[{.txt}] net=: send data over a socket off depth= stack trace depth 4 interval= sample interval in ms 10 cutoff= output cutoff point 0.0001 lineno=y|n line number in traces? y thread=y|n thread in traces? n doe=y|n dump on exit? y msa=y|n Solaris micro state accounting n force=y|n force output to y verbose=y|n print messages about dumps y Example: java -agentlib:hprof=heap=sites -jar myjar.jar java -agentlib:hprof=cpu=samples -jar myjar.jar Make sure you kill -3 the JVM in order to obtain the profiling information or wait until you quit your application. SITES BEGIN (ordered by live bytes) Tue Oct 2 01:59:44 2007 percent live alloc'ed stack class rank self accum bytes objs bytes objs trace name 1 7.90% 7.90% 658936 10135 658936 10135 300000 char[] 2 7.52% 15.42% 627488 82 630448 87 302879 int[] 3 2.91% 18.33% 242672 10091 242672 10091 300000 java.lang.String 4 2.59% 20.91% 215952 7 215952 7 312604 int[] 5 1.73% 22.65% 144760 979 163400 1117 300987 char[] 6 1.58% 24.23% 132208 5 132208 5 307232 int[] 7 1.12% 25.35% 93288 547 214112 1262 314498 char[] 8 1.03% 26.38% 85560 2139 162280 4057 310169 java.util.StringTokenizer 9 0.87% 27.25% 72760 783 146576 1686 303554 char[] 10 0.86% 28.11% 71600 1790 143800 3595 310176 java.util.StringTokenizer 11 0.84% 28.95% 70192 454 184328 1296 300978 char[] 12 0.82% 29.77% 68544 2142 68544 2142 315712 javax.swing.text.html.parser.ContentModel 13 0.71% 30.49% 59584 133 59584 133 305582 javax.swing.JCheckBox 14 0.68% 31.16% 56320 110 98304 192 305582 com.incors.plaf.alloy.ds 15 0.64% 31.80% 53728 146 75440 205 307494 javax.swing.JLabel 16 0.64% 32.44% 53448 2227 64968 2707 305109 sun.font.TrueTypeFont$DirectoryEntry 17 0.59% 33.03% 49200 3 82000 5 307005 int[] 18 0.59% 33.62% 49200 3 82000 5 307004 int[] 19 0.57% 34.20% 47744 1492 63520 1985 300603 java.util.LinkedHashMap$Entry 20 0.57% 34.77% 47712 1988 85344 3556 310172 java.awt.Insets 21 0.50% 35.27% 42032 468 114752 1262 314506 char[] 22 0.47% 35.74% 39216 1634 59088 2462 300030 java.util.Vector 23 0.43% 36.17% 36080 82 36080 82 305970 javax.swing.JTextField 24 0.42% 36.60% 35456 1108 35456 1108 308918 java.lang.String[] 25 0.41% 37.01% 34032 1418 45528 1897 301058 java.io.ExpiringCache$Entry 26 0.39% 37.39% 32328 1347 85776 3574 310170 java.lang.String 27 0.36% 37.75% 30024 417 94608 1314 300354 java.lang.reflect.Field 28 0.35% 38.11% 29544 1 29544 1 301728 char[] 29 0.34% 38.44% 28000 84 28000 84 300000 byte[] 30 0.33% 38.77% 27328 1708 48224 3014 304306 java.awt.Dimension 31 0.31% 39.08% 25480 245 32240 310 302891 sun.awt.image.IntegerInterleavedRaster 32 0.30% 39.37% 24624 3 41040 5 307003 char[] 33 0.30% 39.67% 24624 3 41040 5 307006 char[] 34 0.28% 39.95% 23616 72 23616 72 305151 se.datadosen.component.ControlPanel 35 0.28% 40.23% 23472 978 26808 1117 300986 java.lang.String 36 0.27% 40.50% 22200 925 58560 2440 305902 java.util.HashMap$Entry 37 0.26% 40.76% 21776 1 21776 1 314766 long[] 38 0.26% 41.02% 21776 1 21776 1 314765 long[] 39 0.26% 41.28% 21504 1152 21504 1152 300000 java.beans.PropertyChangeListener[] 40 0.26% 41.53% 21296 1331 38592 2412 310174 java.awt.Dimension 41 0.25% 41.79% 21120 264 24320 304 305025 java.util.HashMap$Entry[] 42 0.25% 42.04% 21120 528 24560 614 305712 java.util.WeakHashMap$Entry 43 0.25% 42.29% 20664 41 20664 41 305582 com.incors.plaf.alloy.dr 44 0.24% 42.52% 19672 375 38112 940 300024 char[] 45 0.23% 42.76% 19536 1221 47952 2997 307893 java.awt.Dimension 46 0.23% 42.99% 19360 55 33792 96 305565 javax.swing.JScrollPane$ScrollBar 47 0.23% 43.22% 19320 483 43840 1096 310177 java.util.StringTokenizer 48 0.23% 43.45% 18840 785 31104 1296 303561 java.util.HashMap$Entry 49 0.23% 43.67% 18792 783 31152 1298 303555 java.lang.String 50 0.22% 43.89% 18504 771 18504 771 316800 java.util.LinkedList$Entry 51 0.22% 44.11% 18144 756 31152 1298 303556 java.lang.String 52 0.22% 44.33% 18048 48 18048 48 305546 javax.swing.JScrollPane ...

  Results are stored in a file called: java.hprof.txt - this can be changed using file= option passed in the command line. This will slightly slow down the startup for your application, so make sure you experiment with your application. If you intend to run this on an application server test as well carefully - it might happen the startup of your app server will be much slower. In case your application is very slow consider using dynamic tracing, DTrace.

  
  
  
• Other Profiling Tools
  JFluid, NetBeans, commercial tools - N/A
  
  

---

Dynamic Tracing

It is not always possible to profile directly to a production system, more you should be able to debug a live system as entire or only one or two processes. To do this, you can easily use a dynamic tracing framework, developed under Solaris 10, called DTrace. DTrace can easily be used hand in hand with Java. DTrace is well integrated with Java 6, for all the other versions you will need to load an agent during your application startup.

Teams: Java Development, Support

• Jstack
  
  
  
• Java 1.4, 5: The DVM agent
  

  DTrace can be used to debug and trace your Java applications using a JVM agent, called dvm. Source: https://solaris10-dtrace-vm-agents.dev.java.net/

  The DVM agent is based on JVMTI for Java 5. The JVMTI is a enough stable interface comparing with JVMPI found in Java 1.4.xx. You can as well use the DVM agent for Java 1.4 applications but the agent is not very stable. It is highly recommended at least to use Java 5 if not even Java 6. The dvmti agent, is a shared library in Solaris which should be loaded during your application startup. Below you can see a simple example how to get started.

  Install the DVM agent # mkdir -p /opt/dtrace/dvm # cd /opt/dtrace/dvm # unzip dvm.zip Open a terminal and export a series of options to load the DVM agent. After that simple start your application using the same trminal window. Setup the DVM for X86/64 $ export LD_LIBRARY_PATH_64=/opt/dtrace/dvm/build/amd64/lib $ export LD_LIBRARY_PATH_32=/opt/dtrace/dvm/build/i386/lib $ export JAVA_TOOL_OPTIONS=-Xrundvmti:all Setup the DVM for SPARC $ export LD_LIBRARY_PATH_64=/opt/dtrace/dvm/build/sparcv9/lib $ export LD_LIBRARY_PATH_32=/opt/dtrace/dvm/build/sparc/lib $ export JAVA_TOOL_OPTIONS=-Xrundvmti:all Test the DVM agent $ /opt/java/jdk1.5.0_11/bin/java -version Picked up JAVA_TOOL_OPTIONS: -Xrundvmti:all java version "1.5.0_11" Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_11-b03) Java HotSpot(TM) Client VM (build 1.5.0_11-b03, mixed mode) Run your application java -jar JAlbum.jar & [1] 2223 Picked up JAVA_TOOL_OPTIONS: -Xrundvmti:all Note: it is important here to see the message "Picked up..." that means that your dvm agent has been loaded along with the JVM. To double check that, simple run pldd on the running process: $pldd 3447 3447: /opt/java/jdk1.5.0_11/bin/java -jar JAlbum.jar /lib/libthread.so.1 /lib/libdl.so.1 /lib/libc.so.1 /opt/java/jdk1.5.0_11/jre/lib/i386/client/libjvm.so /lib/libsocket.so.1 /usr/lib/libsched.so.1 /usr/lib/libCrun.so.1 /lib/libm.so.1 /lib/libnsl.so.1 /lib/libm.so.2 /lib/libscf.so.1 /lib/libuutil.so.1 /lib/libgen.so.1 /lib/libmd.so.1 /lib/libmp.so.2 /opt/java/jdk1.5.0_11/jre/lib/i386/native_threads/libhpi.so /opt/dtrace/dvm/build/i386/lib/libdvmti.so /opt/java/jdk1.5.0_11/jre/lib/i386/libjava_crw_demo.so /lib/libelf.so.1 /opt/java/jdk1.5.0_11/jre/lib/i386/libverify.so /opt/java/jdk1.5.0_11/jre/lib/i386/libjava.so /opt/java/jdk1.5.0_11/jre/lib/i386/libzip.so /opt/java/jdk1.5.0_11/jre/lib/i386/libawt.so /opt/java/jdk1.5.0_11/jre/lib/i386/libmlib_image.so /opt/java/jdk1.5.0_11/jre/lib/i386/motif21/libmawt.so /usr/dt/lib/libXm.so.4 /usr/openwin/lib/libXp.so.1 /usr/openwin/lib/libXt.so.4 /usr/openwin/lib/libXext.so.0 /usr/X11/lib/libXtst.so.1 /usr/openwin/lib/libX11.so.4 /usr/X11/lib/libXpm.so.4 /usr/openwin/lib/libXtsol.so.1 /lib/libtsol.so.2 /lib/libsecdb.so.1 /usr/X11/lib/libXau.so.6 /usr/openwin/lib/libSM.so.6 /usr/openwin/lib/libICE.so.6 /opt/java/jdk1.5.0_11/jre/lib/i386/libfontmanager.so /opt/java/jdk1.5.0_11/jre/lib/i386/libjpeg.so /opt/java/jdk1.5.0_11/jre/lib/i386/libnet.so /opt/java/jdk1.5.0_11/jre/lib/i386/libnio.so /lib/librt.so.1 /lib/libsendfile.so.1 /opt/java/jdk1.5.0_11/jre/lib/i386/libdcpr.so /opt/java/jdk1.5.0_11/jre/lib/i386/libcmm.so My application works very slow after loading the dvm agent You have noticed that your application is starting slower and somehow is slower after using: the JAVA_TOOL_OPTIONS=-Xrundvmti:all - Is this normal ? Yes, depending the number of probes you've enabled during startup the application will automatically take into use. By default the DVM agent is active meaning the probes are activated as fast as you start the Java application. To minimize the probe effect for large applications, which run on an application server you could try a number of things: A). Load only what you really want: export JAVA_TOOL_OPTIONS=-Xrundvmti:allocs export JAVA_TOOL_OPTIONS=-Xrundvmti:allocs,methods export JAVA_TOOL_OPTIONS=-Xrundvmti:stats B). Dynamic DVM loading You can disable for certain period of time the DVM tracing. A number of steps are needed: - create a named pipe: mknod /path_to_your_app/dvmpipe p chmod 600 /path_to_your_app/dvmpipe p - by default disable the DVM tracing: echo d >> /path_to_your_app/dvmpipe - start your application from another terminal: export JAVA_TOOL_OPTIONS="-Xrundvmti:all,dynamic=/path_to_your_app/dvmpipe" java -jar myapplication.jar & - when ready to activate tracing, try to: echo d >> /path_to_your_app/dvmpipe

  Next, we will try to write simple DTrace scripts or even one liners which can help us to understand how resources inside the JVM are used. For more complicated things like: how many times my Java application uses that method, or what are the most common methods called D scripts are required. We will use for this example a nice Java application, called JAlbum which lets you create nice photo albums. The application is delivered as a JAR package.

  1. What can we enable, what probes !? It is very important to know what we really want to look after when we are dynamic tracing an application. A provider can offer many points of instrumentation so we should develop a way of thinking to focus on what we really want: the most called methods, or when a thread has been created or destroyed, object allocation etc. So lets see what the dvmti provider is offering us: $ dtrace -l -m libdvmti.so ID PROVIDER MODULE FUNCTION NAME 84740 dvm2223 libdvmti.so cbClassFileLoadHook class-load 84741 dvm2223 libdvmti.so cbObjectFree class-unload 84742 dvm2223 libdvmti.so cbExceptionCatch exception-catch 84743 dvm2223 libdvmti.so cbException exception-throw 84744 dvm2223 libdvmti.so cbGarbageCollectionFinish gc-finish 84745 dvm2223 libdvmti.so cbGarbageCollectionStart gc-start 84746 dvm2223 libdvmti.so gc_finish_worker gc-stats 84747 dvm2223 libdvmti.so _method_entry method-entry 84748 dvm2223 libdvmti.so _method_exit method-return 84749 dvm2223 libdvmti.so cbMonitorContendedEnter monitor-contended-enter 84750 dvm2223 libdvmti.so cbMonitorContendedEntered monitor-contended-entered 84751 dvm2223 libdvmti.so cbMonitorWait monitor-wait 84752 dvm2223 libdvmti.so cbMonitorWaited monitor-waited 84753 dvm2223 libdvmti.so track_allocation object-alloc 84754 dvm2223 libdvmti.so cbObjectFree object-free 84755 dvm2223 libdvmti.so cbThreadEnd thread-end 84756 dvm2223 libdvmti.so cbThreadStart thread-start 84757 dvm2223 libdvmti.so cbVMDeath vm-death 84758 dvm2223 libdvmti.so cbVMInit vm-init 2. Count on default probes offered by DVM: Run the next command and try to create a new album in JAlbum. you can see the report about the most called probes for this action. $ dtrace -n 'dvm$target::: { @[probename] = count(); }' -p 2223 dtrace: description 'dvm$target::: ' matched 19 probes ^C thread-end 3 thread-start 6 gc-finish 15 gc-start 15 gc-stats 15 class-load 90 exception-catch 557 exception-throw 557 monitor-waited 625 monitor-wait 627 monitor-contended-enter 2633 monitor-contended-entered 2633 object-free 140524 object-alloc 142971 method-return 2766241 method-entry 2767435 3. What methods are used when I really create a new album ? Focus: method-entry Im interested to know what are the most common Java methods used when Im trying to create a new album. As well I would like to have a report about their number, so an aggregation would be handy here. I want only to display top 25 ! A simple D script called, count-methods.d: dvm$target:::method-entry { @[copyinstr(arg0),copyinstr(arg1)] = count(); } dtrace:::END { trunc(@, 25) } $ dtrace -s count-methods.d -p 2223 dtrace: script 'count-methods.d' matched 2 probes ^C CPU ID FUNCTION:NAME 0 2 :END java/lang/String indexOf 19497 java/awt/Component getTreeLock 20610 sun/awt/AppContext get 20787 java/lang/Character toLowerCase 22327 sun/awt/AppContext getAppContext 23922 java/util/HashMap get 24157 sun/font/FontDesignMetrics getLatinCharWidth 26104 java/lang/reflect/Method getName 26569 javax/swing/UIManager getLAFState 26607 javax/swing/UIDefaults get 28352 javax/swing/UIDefaults getFromHashtable 28352 java/util/EventObject getSource 31285 java/util/HashMap oldHash 33996 java/util/HashMap indexFor 34568 java/util/HashMap hash 36044 java/util/Hashtable get 36896 java/awt/Component getParent 37492 java/awt/Component getParent_NoClientCode 37526 java/lang/String equals 41993 java/lang/String equalsIgnoreCase 44748 java/lang/String hashCode 47586 java/lang/String length 51942 sun/reflect/ByteVectorImpl add 54315 sun/reflect/ClassFileAssembler emitByte 54315 java/lang/String charAt 137375 4. Java applications can be multithreading. What about my application ? Focus: thread-start We are interested to check what is happening when we create a new project, would the application generate a new thread for each new project !? A simple D script called, threads.d: dvm$target:::thread-start { printf (" tid=%d, thread-start: %s ", tid, copyinstr(arg0)); } $ dtrace -s threads.d -p 2223 dtrace: script 'threads.d' matched 1 probe CPU ID FUNCTION:NAME 0 84756 cbThreadStart:thread-start tid=91, thread-start: Thread-20 0 84756 cbThreadStart:thread-start tid=92, thread-start: Basic L&F File Loading Thread 0 84756 cbThreadStart:thread-start tid=93, thread-start: Basic L&F File Loading Thread 0 84756 cbThreadStart:thread-start tid=94, thread-start: Basic L&F File Loading Thread 5. What about when I close the project, whats really happening ? Focus: method-entry We will run here the same script, count-methods.d. These are simple examples which can be adjusted on your application as well. $ dtrace -s count-methods.d -p 2223 dtrace: script 'count-methods.d' matched 2 probes ^C CPU ID FUNCTION:NAME 0 2 :END java/lang/CharacterDataLatin1 toLowerCase 9373 java/util/HashMap get 9427 java/lang/String getChars 9668 sun/awt/AppContext get 9776 java/lang/AbstractStringBuilder append 10473 sun/awt/AppContext getAppContext 11483 java/lang/Character toUpperCase 11862 javax/swing/UIManager getLAFState 13888 java/util/HashMap oldHash 14421 javax/swing/UIDefaults get 14686 javax/swing/UIDefaults getFromHashtable 14686 java/util/HashMap indexFor 14798 java/lang/String equals 15300 java/lang/CharacterDataLatin1 getProperties 15502 java/util/HashMap hash 15593 java/lang/String length 15909 java/util/Hashtable get 16818 java/util/EventObject getSource 17052 java/lang/Character toLowerCase 17414 java/awt/Component getParent 22602 java/awt/Component getParent_NoClientCode 22631 java/lang/String hashCode 22666 java/lang/reflect/Method getName 24973 java/lang/String charAt 35026 java/lang/String equalsIgnoreCase 44579 6. What about object allocation, how objects are allocated and freed ? Focus: object-alloc, object-free A simple script, called: objects.d: dvm$target:::object-alloc { @objectsA[copyinstr(arg0),arg1] = count (); } dtrace:::END { trunc(@objectsA,25); } We are aggregating here on the number of object being allocated when we create a new project in JAlbum: $ dtrace -s objects.d -p 2223 dtrace: script 'objects.d' matched 2 probes ^C CPU ID FUNCTION:NAME 0 2 :END [C 24 1581 java/util/Vector 24 1616 [C 32 1672 java/lang/Integer 16 1681 java/awt/Color 40 1740 [Ljava/lang/Object; 16 1854 java/lang/ref/WeakReference 24 1888 [C 56 2079 javax/swing/event/EventListenerList 16 2166 java/lang/reflect/Field 72 2526 java/lang/StringBuffer 16 2559 [C 40 2819 java/util/Hashtable$Entry 24 3396 [Ljava/lang/Object; 24 3540 java/awt/Rectangle 24 4027 java/lang/reflect/Method 80 4496 java/beans/PropertyChangeEvent 32 4793 [C 80 4843 java/awt/Insets 24 5344 java/lang/StringBuilder 16 7276 java/util/HashMap$Entry 24 8154 java/awt/Dimension 16 10098 [C 48 12086 java/util/StringTokenizer 40 12442 java/lang/String 24 19494 So we can easily see that 24 size String objects 19.500 times in less than 1 minute. You can easily understand this way what your application is doing. 7. Garbage Collection. Focus: gc-stats A simple way to debug how many objects are used when we create a simple new project and how much space do they take. A simple script, called: gcstats.d: dvm$target:::gc-stats { printf(" tid=%d, used objects: %d objects size: %d ", tid, arg0, arg1); } $ dtrace -s gcstats.d -p 2223 dtrace: script 'gcstats.d' matched 1 probe CPU ID FUNCTION:NAME 0 84746 gc_finish_worker:gc-stats tid=5, used objects: 199244 objects size: 11947360 0 84746 gc_finish_worker:gc-stats tid=5, used objects: 206368 objects size: 12452632 0 84746 gc_finish_worker:gc-stats tid=5, used objects: 204468 objects size: 12233448 0 84746 gc_finish_worker:gc-stats tid=5, used objects: 210370 objects size: 12528600 0 84746 gc_finish_worker:gc-stats tid=5, used objects: 220685 objects size: 12936112 0 84746 gc_finish_worker:gc-stats tid=5, used objects: 228727 objects size: 13220256 0 84746 gc_finish_worker:gc-stats tid=5, used objects: 239059 objects size: 13569992 0 84746 gc_finish_worker:gc-stats tid=5, used objects: 231586 objects size: 13377584 0 84746 gc_finish_worker:gc-stats tid=5, used objects: 230120 objects size: 13358624 0 84746 gc_finish_worker:gc-stats tid=5, used objects: 234443 objects size: 13545344 ^C

  
  
  
• Java 6: Hotspot provider
  N/A
  
  

Back to main Java homepage

This document is Copyright (c) 2007 Stefan Parvu
Document License: PDL