Java Runtime Concepts 1

(1)

Java Performance – Part 3

(2)

Java Concepts and Troubleshooting Agenda

■ Session 1 (October 17th, 11:00AM Eastern)

– Introduction to IBM Java Chris Bailey, Java Service Architect

– Java Memory Management Peter Shipton, JVM Technology Lead – Garbage Collection Peter Shipton, JVM Technology Lead

■ Session 2 (October 19th, 11:00AM Eastern)

– Java Tooling Overview Venkat L, Java Service Technical Lead – Java Performance Part 1 Michael Tunnicliffe, Java Service Engineer

■ Session 3: (October 21st, 11:00AM Eastern)

– Java Performance Part 2 Karl Taylor, Java VM Developer ■ Session 4: (October 24th, 11:00AM Eastern)

– Java Performance Part 3 Ian Partridge, Java Service Engineer ■ Session 5: (October 26th, 11:00AM Eastern)

– OutOfMemoryErrors Matthew Kilner, Java Service Team Lead

■ Feedback!

(3)

3

3 Important Disclaimers

THE INFORMATION CONTAINED IN THIS PRESENTATION IS PROVIDED FOR INFORMATIONAL PURPOSES ONLY. WHILST EFFORTS WERE MADE TO VERIFY THE COMPLETENESS AND ACCURACY OF THE INFORMATION

CONTAINED IN THIS PRESENTATION, IT IS PROVIDED “AS IS”, WITHOUT WARRANTY OF ANY KIND, EXPRESS OR IMPLIED.

ALL PERFORMANCE DATA INCLUDED IN THIS PRESENTATION HAVE BEEN GATHERED IN A CONTROLLED ENVIRONMENT. YOUR OWN TEST RESULTS MAY VARY BASED ON HARDWARE, SOFTWARE OR

INFRASTRUCTURE DIFFERENCES.

ALL DATA INCLUDED IN THIS PRESENTATION ARE MEANT TO BE USED ONLY AS A GUIDE.

IN ADDITION, THE INFORMATION CONTAINED IN THIS PRESENTATION IS BASED ON IBM’S CURRENT PRODUCT PLANS AND STRATEGY, WHICH ARE SUBJECT TO CHANGE BY IBM, WITHOUT NOTICE.

IBM AND ITS AFFILIATED COMPANIES SHALL NOT BE RESPONSIBLE FOR ANY DAMAGES ARISING OUT OF THE USE OF, OR OTHERWISE RELATED TO, THIS PRESENTATION OR ANY OTHER DOCUMENTATION.

NOTHING CONTAINED IN THIS PRESENTATION IS INTENDED TO, OR SHALL HAVE THE EFFECT OF:

- CREATING ANY WARRANT OR REPRESENTATION FROM IBM, ITS AFFILIATED COMPANIES OR ITS OR THEIR SUPPLIERS AND/OR LICENSORS

(4)

What is Java Performance?

■ Java performance problems are grouped into 4 main scenarios: – System resource contention/starvation

– Garbage Collection performance – Application code performance – External delays

(5)

Application Code Performance

■ Three particular problem areas: – High CPU usage

– Synchronized Resource Contention – External Delays

(6)

High CPU Usage of Application

■ Could be the cause of a hang:

– Single thread “spinning” and taking all CPU time

■ Could be inefficient code

■ High CPU will be seen in topas and perfmon performance counters as seen previously

■ First step is to understand whether CPU cost is specific to any given thread, or collection of threads ■ And then to understand what those threads are doing

(7)

Profiling CPU Usage: AIX

■ Use of: tprof –skex sleep 60:

■ Shows percentage of CPU in each process and used by each thread

– “Shared” is shared libraries, “Other” is the JVM interpreter and JITed code – TID is in decimal and needs to be convered to hex, eg. 688211 = 0xA8053

(8)

(9)

Profiling CPU Usage: Windows

■ Use of Thread “Processor Time” and “ID Thread” counters in perfmon

■ Use report option rather than graph to see ID Thread value:

■ “ID Thread” is in decimal and needs to be converted to hex – ie, Thread 10 has “ID Thread” 9652, which is 0x25B4

(10)

(11)

Profiling the Methods

■ A series of javacore.txt files provides a rough idea of what the threads are doing – For a single thread using 100% CPU, the stack track should be sufficient – For a group of threads, it shows some of the methods being executed ■ Thread and Monitor Dump Analyzer helps with multi-javacore analysis

■ However method profiling provides a much more accurate picture – Shows complete set of methods being executed

– Provides call graphs

(12)

Health Center

■ Live monitoring tool with very low overhead – Goal of <2% of application throughput

■ Understand how your application is behaving

– Monitor Class loading, File I/O, Environment settings, Garbage Collection, Method Profiling, Locking, Native memory use

■ Diagnose potential problems, with recommendations ■ Suitable for all Java applications

■ Developed, maintained and supported by IBM Java Tools team

– https://www.ibm.com/developerworks/java/jdk/tools/healthcenter/

■ Available with in ISA:

– http://www-306.ibm.com/software/support/isa/

■ Provides live monitoring of all IBM JVMs from Java 5 – AIX, Linux, IBM i, Windows, z/OS

(13)

Health Center

■ Java Heap/Garbage Collection: – Heap usage over time

– Garbage Collection performance – “Large” object allocations

■ Method Profiling:

– (Very) low overhead method profiling – Call paths to show code flow

– Timelines to show changes in behaviour

■ Lock/Synchronized code profiling: – Highly contended locks

– Lock contention rates and hold times – Both Java application and JVM locks

(14)

Synchronized Resource Contention

■ The contention of multiple threads on one of more synchronized resources ■ Applications that do not “scale” well

■ Normally manifests as:

– Low CPU usage for most/all threads – Noticeable responsiveness delays

(15)

Javacore.txt Monitor Report

■ Many threads trying to enter an owned lock

(16)

Profiling Synchronized Resources

■ The “hold time” of a lock could be measured using Method Trace – Must know which lock is of interest

– Must select a relevant method to measure the lock hold time from

■ All locks can be profiled most easily using Health Center

(17)

Health Center Sample Report

■ Functionality includes:

– Counters associated with contended locks – Total number of successful acquires

– Recursive acquires – times a thread acquires a lock it already owns

– Number of times a thread blocks because a monitor is already owned

(18)

(19)

External Delays

■ The low performance of an application due to waiting on IO with external resources: – May be database, other application, file IO etc

■ Normally manifests as:

– Low CPU usage for most/all threads – Noticeable responsiveness delays

■ First step is to look for threads waiting in the javacore.txt file – Especially in networking or database connection code

(20)

■ Thread is in state:CW which means it is waiting

■ Multiple Threads waiting on the same resource is usually an issue ■ Can profile how long the waits are using Method Trace

(21)

IBM JVM Trace Engine

■ Thousands of tracepoints throughout VM native code

■ Can capture Java Methods data also

■ Many different operation modes to aid debugging and problem diagnosis

■ Limited “Flight Recorder” trace set is always on in Java 5.0 ■ Including GCLogger tracing to store most recent GC activity

(22)

Controlling Trace

■ The Trace Engine can be controlled through a number of mechanisms: – Through the -Xtrace command-line option

– Using a trace properties file

– Dynamically using Java code through the com.ibm.jvm.Trace API – Using trace trigger events

– From an external agent using the C-based JVM RAS Interface (JVMRI)

(23)

Basics of activating trace

■ Determine is the destination to which the trace output should be directed – minimal Trace identifier and timestamp only to in-core buffer.

– maximal Trace id, timestamp and associated data (parameters) to in-core buffer. – count Report the number of times a selected tracepoint is called

– print Trace selected tracepoints to stderr with no indentation. – iprint Trace selected tracepoints to stderr with indentation. – external Route selected tracepoints to a JVMRI listener.

– exception Trace selected tracepoints to an in-core buffer reserved for exceptions.

■ The value of each keyword is then set to the trace points required

– -Xtrace:maximal=all traces all of the information available from all JVM trace points to internal wrapping buffers.

– -Xtrace:iprint=awt traces all of the JVM internal AWT trace points to stderr, with indentations on entry and exit.

– -Xtrace:iprint=mt activates method trace and set the output to stderr with indentations

(24)

Method Trace

■ Instrumentation free tracing of: – Any Java Methods:

– Core Java API, Middleware, 3rd party code, Customer code

■ Detailed information:

– Entry and Exit points, with thread information and microsecond time stamps

■ Two part invocation:

– 1) Add methods keyword as a token to –Xtrace

– 2) Use of mt as value to destination keyword (eg. maximal, print)

■ Method selection by class name or method name

– use of wildcards, along with the not operator, !, allowing for complex selection criteria. – -Xtrace:print=mt,methods={*.*,!java/lang/*.*}

• Write method trace to stderr for all methods and for all classes except those in the java.lang package.

– -Xtrace:maximal=mt,output=trace.out,methods={tests/mytest/*.*}

(25)

Triggering

■ Trace can produce significant amounts of data ■ The ability is provided to trigger on trace events

– Provides ability to create targeted trace output

– Provides ability to also generate dumps on trace points ■ Following actions available as value of trigger keyword

– suspend Suspend all tracing

– resume Resume all tracing (except for threads suspended by resumecount property and Trace.suspendThis() calls).

– suspendthis Increment the suspendcount/decrement the resumecount for this thread. – resumethis Decrement the suspendcount/increment the resumecount for this thread. – sysdump Produce a non-destructive system dump.

– javadump Produce a Java dump. – heapdump Produce a heap dump.

– snap Snap all active trace buffers to a file in the current working directory. – resumecount Tracing is disabled if count > 0

(26)

Triggering Examples

■ Following format used to specify triggers in method events:

– trigger=method{method spec,entry action,exit action,delay count,match count}

– On entering any method that matches the method spec indicated, the entry action is executed.

– When exiting the method, the exit action is performed.

– If the delay count is specified, the entry and exit actions are only carried out when entry and exit have occurred more times than the delay count.

– If the match count is specified, the actions are only carried out a maximum of that many times.

■ Examples:

■ -Xtrace:trigger=method{java/lang/StackOverflowError*, sysdump}

– create a system dump on the first (and only the first) instance of a StackOverflowError method being called - which is the <clinit> method.

■ -Xtrace:resumecount=1

-Xtrace:trigger=method{HelloWorld.main,resume,suspend}

– trace all threads once HelloWorld.main() is called and stop tracing when HelloWorld.main() returns.

(27)

Triggering and Method Trace in Action

■ -Xtrace: iprint=mt, methods={myapp/MyTime*}, resumecount=1, trigger=method{myapp/MyTime.main,resume,suspend} 21:05:47.992*0x806cb00 mt.3 > myapp/MyTime.main([Ljava/lang/String;)V Bytecode static method

21:05:47.994 0x806cb00 mt.19 - Static method arguments: ([L@55D8CB98)

21:05:47.994 0x806cb00 mt.0 > myapp/MyTime.<init>()V Bytecode method, This = 809baec

21:05:47.994 0x806cb00 mt.18 - Instance method receiver: myapp/MyTime@55D8CBA8 arguments: ()

21:05:47.994 0x806cb00 mt.6 < myapp/MyTime.<init>()V Bytecode method

21:05:47.994 0x806cb00 mt.0 > myapp/MyTime.test()V Bytecode method, This = 809baf0

21:05:47.994 0x806cb00 mt.18 - Instance method receiver: myapp/MyTime@55D8CBA8 arguments: ()

21:05:48.079 0x806cb00 mt.6 < myapp/MyTime.test()V Bytecode method

21:05:48.079 0x806cb00 mt.9 < myapp/MyTime.main([Ljava/lang/String;)V Bytecode static method

(28)

Triggering and Method Trace in Action

■ Could now drill down into MyTime.test():

– Extend scope of methods traced, and reduce scope of tracing into MyTime.test() ■ -Xtrace:

iprint=mt,

methods={myapp/*}, resumecount=1,

trigger=method{myapp/MyTime.test,resume,suspend}

21:07:14.968*0x806cb00 mt.0 > myapp/MyTime.test()V Bytecode method, This = 809baf0 21:07:14.970 0x806cb00 mt.18 - Instance method receiver: myapp/MyTime@55D8CBA8 arguments: ()

21:07:15.067 0x806cb00 mt.3 > myapp/MyTimer.getTime()V Bytecode static method 21:07:15.067 0x806cb00 mt.19 - Static method arguments: ()

21:07:15.067 0x806cb00 mt.9 < myapp/MyTimer.getTime()V Bytecode static method 21:07:15.069 0x806cb00 mt.6 < myapp/MyTime.test()V Bytecode method

(29)

Profiling Thread Waits

■ Delayed method is com.ibm.as400.access.AS400ThreadedServer.receive

■ Can profile calls to this method via method trace with the following: ■ -Xtrace:maximal=mt,output=mtrace#.out,10m,10,V

– Trace methods to 10 files named mtrace#.out each sized at 10MB ■ Vmethods={com/ibm/as400/access/AS400ThreadedServer.receive}

(30)

Summary

■ Lots of different performance problem causes: – System level resources

– Java and middleware tuning – Application code

– External resources

■ A number of capabilities provided at each level to help diagnose: – Operating System tools

– Java debug capabilities: Verbose GC, Javacore.txt, Method Trace

(31)

(32)

32

32 References

■ Get Products and Technologies: – IBM Developer Kits for Java:

• https://www.ibm.com/developerworks/java/jdk/

– IBM Monitoring and Diagnostic Tools for Java:

• https://www.ibm.com/developerworks/java/jdk/tools/

■ Learn:

– IBM Java InfoCenters:

• https://www.ibm.com/developerworks/java/jdk/docs.html

■ Discuss:

– IBM Java Runtimes and SDKs Forum:

• http://www.ibm.com/developerworks/forums/forum.jspa?forumID=367&start=0

– IBM Java Technology Community:

• https://www.ibm.com/developerworks/mydeveloperworks/groups/service/html/communityview? communityUuid=738b7897-cd38-4f24-9f05-48dd69116837

– IBM on Troubleshooting Java Applications Blog:

(33)

33

33 Copyright and Trademarks

IBM, the IBM logo, and ibm.com are trademarks or registered trademarks of International Business Machines Corp., and registered in many jurisdictions worldwide.

Other product and service names might be trademarks of IBM or other companies.

A current list of IBM trademarks is available on the Web – see the IBM “Copyright and trademark information” page at URL: www.ibm.com/legal/copytrade.shtml