7 Powerful Linux Commands To Debug Java Performance Issue

Linux operating system is very powerful and if we know the correct tools to debug its much easier then any other operating system. Sometimes it gets very difficult to investigate issues on production system where we can use a very little debugging tools. This tutorial contains few good operating system commands to be used while debugging Java processes on Linux/Unix environment.



  1. lsof Command - Check for open file descriptors
  2. This command lists the open file descriptors by a process on unix operating system. Here is short description from man output of lsof. An open file may be a regular file, a directory, a block special file, a character special file, an executing text reference, a library, a stream or a network file (Internet socket, NFS file or UNIX domain socket.) A specific file or all the files in a file system may be selected by path. This command is really useful when you are facing third-party library related issues and you can not make out which library is being used by your program. The output of the command shows the complete path of library files it has opened. In fact its interesting to see that lots of libraries are not loaded until required by your application. Below is a sample output of lsof command for a java process.
    $ lsof -p 
    
    java 10258 i5 mem REG 253,3 22068 1246769 /usr/local/apache-tomcat-5.5.20/server/lib/servlets-webdav.jar
    java 10258 i5 mem REG 253,3 19146 1246778 /usr/local/apache-tomcat-5.5.20/server/lib/tomcat-coyote.jar
    java 10258 i5 mem REG 253,3 64804 1246780 /usr/local/apache-tomcat-5.5.20/server/lib/catalina-storeconfig.jar
    java 10258 i5 mem REG 253,3 167142 1246770 /usr/local/apache-tomcat-5.5.20/server/lib/tomcat-ajp.jar
    java 10258 i5 mem REG 253,3 88222 1246771 /usr/local/apache-tomcat-5.5.20/server/lib/tomcat-http.jar
    java 10258 i5 mem REG 253,3 23326 1246774 /usr/local/apache-tomcat-5.5.20/server/lib/catalina-ant-jmx.jar
    java 10258 i5 mem REG 253,3 18301 1246779 /usr/local/apache-tomcat-5.5.20/server/lib/servlets-default.jar
    java 10258 i5 mem REG 253,3 26354 1246776 /usr/local/apache-tomcat-5.5.20/server/lib/catalina-ant.jar
    java 10258 i5 mem REG 253,3 115344 1246768 /usr/local/apache-tomcat-5.5.20/server/lib/catalina-optional.jar
    java 10258 i5 mem REG 253,3 25161 1246781 /usr/local/apache-tomcat-5.5.20/server/lib/tomcat-apr.jar
    

    How this can be used?

    If you look at the output above, this command shows the exact details of open files with absolute path. If there is an incorrect jar file in CLASSPATH being used by your java program then you can easily figure out the issue by looking at this output.

  3. pstack - Check for process stack trace
  4. This command gives the light weight process stack for a process. This is a really helpful command if you are debugging some issues like process run away or deadlock on production. Here is a sample output of a java process pstack.
    $ pstack 
    
    Thread 209 (Thread 818031520 (LWP 26203)):
    #0 0xb7fe87a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2
    #1 0xb7fd3f7c in pthread_cond_timedwait@@GLIBC_2.3.2 ()
    #2 0xb7fd43f5 in pthread_cond_timedwait@GLIBC_2.0 ()
    #3 0xb78ee95c in os::Linux::safe_cond_timedwait ()
    #4 0xb78d5e41 in Monitor::wait ()
    #5 0xb79d1e8b in VMThread::loop ()
    #6 0xb79d1af0 in VMThread::run ()
    #7 0xb78ef6f8 in _start ()
    #8 0xb7fd13cc in start_thread () from /lib/tls/libpthread.so.0
    #9 0xb7f6396e in clone () from /lib/tls/libc.so.6
    

    How this can be used?

    • I have found this command really useful in case when we are trying to debug a java program with Multiple threads. Most of deadlock will be visible in the output of this command.








    • Many times when we were doing CPU utilization issue debugging this command really helped. The thread, which eats most of the CPU cycle would be seen in running state in output and other threads may be waiting.

  5. jstack - Java process thread stack trace
  6. This a Java 1.5 addition for getting the thread stack trace of a running java process. This can be helpful when you are debugging issues which are difficult to reproduce. Like deadlocks, High CPU Utilization. Read more about this at Sun Site Below is a sample output of a java process jstack
    $jstack 
    
    Attaching to process ID 24776, please wait...
    Debugger attached successfully.
    Server compiler detected.
    JVM version is 1.5.0_16-b02
    Thread 25010: (state = IN_NATIVE)
    - java.net.SocketInputStream.socketRead0(java.io.FileDescriptor, byte[], int, int, int) @bci=0 (Compiled frame; information may be imprecise)
    - java.net.SocketInputStream.read(byte[], int, int) @bci=84, line=129 (Compiled frame)
    - com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(com.sun.net.ssl.internal.ssl.InputRecord, boolean) @bci=44, line=782 (Interpreted frame)
    - com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(com.sun.net.ssl.internal.ssl.InputRecord) @bci=15, line=739 (Interpreted frame)
    - com.sun.net.ssl.internal.ssl.AppInputStream.read(byte[], int, int) @bci=30, line=75 (Interpreted frame)
    - org.apache.coyote.http11.InternalInputBuffer.fill() @bci=59, line=738 (Interpreted frame)
    - org.apache.coyote.http11.InternalInputBuffer.parseRequestLine() @bci=16, line=399 (Compiled frame)
    - org.apache.coyote.http11.Http11Processor.process(java.io.InputStream, java.io.OutputStream) @bci=327, line=828 (Compiled frame)
    

    How this can be used?

    This is really a powerful command as this can give you the exact java class and method names, just like a exception stack-trace. If you are debugging High CPU Utilization issue, then take 2-3 snapshot of your process and you will find the class and method call being repeated in your snapshot for the thread which is eating most CPU cycles.

  7. ps with "-L" option
  8. The "ps" command is commonly used command. The -L option for this command is not used by many people though. This option can list down all the lightweight processes in Linux operating system. The process ids in this command can be matched with the jstack command output to do detailed analysis. Below is a sample output of a java process with ps -L option
    $ ps -aefL | grep java | more
    host 10258 1 10258 0 94 Dec23 ? 00:00:25 /usr/java/jdk/bin/java -Xms1024M -Xmx1536M -XX:-UseParallelGC -Djava.util.logging.manager=org.apac
    he.juli.ClassLoaderLogManager -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties -Djava.endorsed.dirs=/usr/local/tomcat/common/endorse
    d -classpath :/usr/local/tomcat/bin/bootstrap.jar:/usr/local/tomcat/bin/commons-logging-api.jar -Dcatalina.base=/usr/local/tomcat -Dcatalina.home=/usr/local/
    tomcat -Djava.io.tmpdir=/usr/local/tomcat/temp org.apache.catalina.startup.Bootstrap start
    host 10258 1 10259 0 94 Dec23 ? 00:03:15 /usr/java/jdk/bin/java -Xms1024M -Xmx1536M -XX:-UseParallelGC -Djava.util.logging.manager=org.apac
    he.juli.ClassLoaderLogManager -Djava.util.logging.config.file=/usr/local/tomcat/conf/logging.properties -Djava.endorsed.dirs=/usr/local/tomcat/common/endorse
    d -classpath :/usr/local/tomcat/bin/bootstrap.jar:/usr/local/tomcat/bin/commons-logging-api.jar -Dcatalina.base=/usr/local/tomcat -Dcatalina.home=/usr/local/
    tomcat -Djava.io.tmpdir=/usr/local/tomcat/temp org.apache.catalina.startup.Bootstrap start
    
    

    How this can be used?

    This command can be used in combination with pstack & jstack. The pstack and jstack commands use a thread id in the output, and using "ps -L" command you can see the light weight processes (unix threads) for your java process. This can help you to point to exact thread, which is causing problems.

  9. jmap - Check java heap allocationj
  10. The jmap Command is part of JDK5 can be used to connect to live java process. so just like jstack this command can also be used on a already running process to get the memory footprint details (JVM heap allocation details). The jmap command syntax is $ jmap [pid] Below is a sample output of it
    $ /usr/java/jdk/bin/jmap 4477
    Attaching to process ID 4477, please wait...
    Debugger attached successfully.
    Server compiler detected.
    JVM version is 1.5.0_16-b02
    0x08048000 62K /usr/java/jdk1.5.0_16/bin/java
    0x477ae000 343K /usr/java/jdk1.5.0_16/jre/lib/i386/libcmm.so
    0x4923b000 77K /lib/libresolv-2.3.4.so
    0x4924e000 21K /lib/libnss_dns-2.3.4.so
    0x49257000 22K /usr/java/jdk1.5.0_16/jre/lib/i386/libmanagement.so
    0x4b9ed000 71K /usr/java/jdk1.5.0_16/jre/lib/i386/libnet.so
    0x4c310000 156K /usr/java/jdk1.5.0_16/jre/lib/i386/libjpeg.so
    0xb741e000 63K /usr/java/jdk1.5.0_16/jre/lib/i386/libzip.so
    0xb742f000 133K /usr/java/jdk1.5.0_16/jre/lib/i386/libjava.so
    0xb7452000 47K /usr/java/jdk1.5.0_16/jre/lib/i386/libverify.so
    0xb745e000 46K /lib/libnss_files-2.3.4.so
    0xb7469000 97K /lib/libnsl-2.3.4.so
    0xb748a000 206K /lib/tls/libm-2.3.4.so
    0xb74ae000 26K /usr/java/jdk1.5.0_16/jre/lib/i386/native_threads/libhpi.so
    0xb74b7000 7275K /usr/java/jdk1.5.0_16/jre/lib/i386/server/libjvm.so
    0xb7e98000 1502K /lib/tls/libc-2.3.4.so
    0xb7fc7000 14K /lib/libdl-2.3.4.so
    0xb7fcc000 103K /lib/tls/libpthread-2.3.4.so
    0xb7fe8000 108K /lib/ld-2.3.4.so
    

    How this can be used?

    I have found this useful while debugging OutOfMemory issues on java processes. Read more details on JDK commands at Sun Troubleshooting Tips for Linux/Solaris

  11. strace - System call trace command on linux
  12. If you are interested to trace/monitor at system call level then this command can be used to see all system calls a process makes on Linux operating system. This is closest equivalent of "truss" command on the Solaris platform. System administrators, diagnosticians and troubleshooters will find it useful for solving problems with programs for which the source is not readily available since they do not need to be recompiled in order to trace them. I have taken a simple example of TestStrace.java, which has just a System.out.println statement as shown below.
    public class TestStrace {
    public static void main(String[] args) {
    System.out.println("Just checking strace command!");
    }
    }
    
    You can run strace on this java class like below
    $ strace -o /tmp/strace.java.out java TestStrace
    
    The output of strace command is usually big, here are few lines from the output for this command
    execve("/usr/java/jdk/bin/java", ["java", "TestStrace"], [/* 24 vars */]) = 0
    uname({sys="Linux", node="streep.playstation.sony.com", ...}) = 0
    brk(0) = 0x8059000
    access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
    open("/etc/ld.so.cache", O_RDONLY) = 3
    fstat64(3, {st_mode=S_IFREG|0644, st_size=40429, ...}) = 0
    old_mmap(NULL, 40429, PROT_READ, MAP_PRIVATE, 3, 0) = 0x501000
    close(3) = 0
    open("/lib/tls/libpthread.so.0", O_RDONLY) = 3
    read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0PH\0\0004\0\0\0"..., 512) = 512
    fstat64(3, {st_mode=S_IFREG|0755, st_size=105824, ...}) = 0
    old_mmap(NULL, 70108, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xa91000
    old_mmap(0xa9f000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0xd000) = 0xa9f000
    old_mmap(0xaa1000, 4572, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xaa1000
    close(3) = 0
    open("/lib/libdl.so.2", O_RDONLY) = 3
    read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\260\v\0\0004\0\0\0"..., 512) = 512
    fstat64(3, {st_mode=S_IFREG|0755, st_size=15032, ...}) = 0
    old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x1ba000
    old_mmap(NULL, 12388, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0x337000
    old_mmap(0x339000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0x339000
    close(3) = 0
    open("/lib/tls/libc.so.6", O_RDONLY) = 3
    read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\340N\1\0004\0\0\0"..., 512) = 512
    fstat64(3, {st_mode=S_IFREG|0755, st_size=1539036, ...}) = 0
    old_mmap(NULL, 1240284, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xbfe000
    old_mmap(0xd27000, 16384, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x128000) = 0xd27000
    old_mmap(0xd2b000, 7388, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xd2b000
    close(3) = 0
    old_mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb5a000
    mprotect(0xd27000, 8192, PROT_READ) = 0
    mprotect(0x339000, 4096, PROT_READ) = 0
    mprotect(0xa9f000, 4096, PROT_READ) = 0
    mprotect(0xa4e000, 4096, PROT_READ) = 0
    set_thread_area({entry_number:-1 -> 6, base_addr:0xb5a6c0, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
    munmap(0x501000, 40429) = 0
    set_tid_address(0xb5a708) = 31688
    rt_sigaction(SIGRTMIN, {0xa95380, [], SA_RESTORER|SA_SIGINFO, 0xa9ca90}, NULL, 8) = 0
    
    
    If you are interested to see few specific system calls then it can also be done by command option as shown below
    strace -e trace=open,close,read,write -o /tmp/strace.java.out.1 java TestStrace
    
    See below output for the same TestStrace.java file. The output has only those system calls which we specified in the trace=[options]
    open("/etc/ld.so.cache", O_RDONLY) = 3
    close(3) = 0
    open("/lib/tls/libpthread.so.0", O_RDONLY) = 3
    read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0PH\0\0004\0\0\0"..., 512) = 512
    close(3) = 0
    open("/lib/libdl.so.2", O_RDONLY) = 3
    read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\260\v\0\0004\0\0\0"..., 512) = 512
    close(3) = 0
    open("/lib/tls/libc.so.6", O_RDONLY) = 3
    read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\340N\1\0004\0\0\0"..., 512) = 512
    close(3) = 0
    open("/usr/java/jdk1.5.0_16/jre/lib/i386/jvm.cfg", O_RDONLY) = 3
    read(3, "#\n# @(#)jvm.cfg\t1.8 04/02/02\n# \n"..., 4096) = 689
    read(3, "", 4096) = 0
    close(3) = 0
    open("/etc/mtab", O_RDONLY) = 3
    read(3, "/dev/sda2 / ext3 rw 0 0\nnone /pr"..., 4096) = 787
    close(3) = 0
    open("/proc/meminfo", O_RDONLY) = 3
    read(3, "MemTotal: 2074628 kB\nMemFre"..., 1024) = 670
    close(3) = 0
    open("/etc/mtab", O_RDONLY) = 3
    read(3, "/dev/sda2 / ext3 rw 0 0\nnone /pr"..., 4096) = 787
    close(3) = 0
    open("/proc/stat", O_RDONLY) = 3
    read(3, "cpu 200648 0 351689 271594094 3"..., 1024) = 814
    read(3, "", 1024) = 0
    close(3) = 0
    open("/usr/java/jdk1.5.0_16/jre/lib/i386/server/tls/i686/sse2/libpthread.so.0", O_RDONLY) = -1 ENOENT (No such file or directory)
    open("/usr/java/jdk1.5.0_16/jre/lib/i386/server/tls/i686/libpthread.so.0", O_RDONLY) = -1 ENOENT (No such file or directory)
    open("/usr/java/jdk1.5.0_16/jre/lib/i386/server/tls/sse2/libpthread.so.0", O_RDONLY) = -1 ENOENT (No such file or directory)
    open("/usr/java/jdk1.5.0_16/jre/lib/i386/server/tls/libpthread.so.0", O_RDONLY) = -1 ENOENT (No such file or directory)
    

    How this can be used?

    1. System administrators, diagnosticians and troubleshooters can use this to debug programs for which source is not available. 2. If you are interested to know details of system calls made during Java process execution then this could be really helpful. The full strace output of TestStrace.java had 2963 lines in output, which can be a interesting thing to study and understand behavior of JVM system calls.

  13. Top with Shift+H does the thread magic
  14. Top command is very commonly used for identifying the high resource consuming processes. It also has a option which can identify the linux thread (lightweight process id) which is consuming the most resource. To do this run the top command and press SHIF+H key. This is the function of SHIFT+H option from linux man pages
    -H : Threads toggle Starts top with the last remembered 'H' state reversed. When this toggle is On, all individual threads will be displayed. Otherwise, top displays a summation of all threads in a process.

    How this can be used?

    This command output can be used with jstack command output to find out the Java thread consuming most CPU. To do that you need follow these steps
    1. Note the Java lightweight process id (thread id) value from the top command.
    2. Convert this value to HEX value. This is required since the jstack output shows the thread ids (named nid in jstack output) in hex values. You can easily do it using the decimal to hexadecimal converter
    3. Now try to find the hexadecimal value inside the jstack output. This will show you the exact thread taking up the most CPU.

Hope you found this tutorial useful. You may already be aware that there are many performance and memory analysis tools available for recent versions of java and one of my favorite is VisualVM.
What tools are you using to debug java performance issues?

A collection of really powerful unix/linux commands for a Java Developer to empower while debugging on Unix flavor operating systems like Linux(Ubuntu, RedHat,Fedora), Solaris etc. Debug Java on Linux, Debugging Java Linux, Debug Java Linux command, Debug Java Linux commands, Debug Java unix, Debug Java Sun Solaris, Powerful Linux commands for java developers, Simple Debug commands for Java on Linux, how to Debug Java process on Linux platform. Java on Linux commands, Java on unix commands,
debug Java,Java for unix,jstack analysis, pstack analysis, lsof analysis java, jmap analysis, Java process analysis unix,strace analysis java unix, ps analysis Java unix, Analyzing java process on unix, jstak for JVM threads analysis, strace JVM analysis,lsof JVM analysis, strace JMV debug on unix, truss linux, linux process management, linux cpu utilization, top command linux, linux monitoring tools, monitor linux server, linux monitors, linux monitoring software,ubuntu truss, top grep, top command

Related

Tips 3677504275675077702

Post a Comment Default Comments

item