Linux is preferred an operating system of most programmers and hackers mainly due to its robustness.
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 linux commands to be used while debugging Java processes on Linux/Unix environment.
Even before you try to get deeper into these commands check out the basic linux commands you should know as a beginner Linux user.
- lsof Command – Check for open file descriptors
- pstack – Check for process stack trace
- 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.
- jstack – Java process thread stack trace
- ps with “-L” option
- jmap – Check java heap allocationj
- strace – System call trace command on linux
- Top with Shift+H does the thread magic
- Note the Java lightweight process id (thread id) value from the top command.
- 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
- Now try to find the hexadecimal value inside the jstack output. This will show you the exact thread taking up the most CPU.
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.
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?
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.
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.
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 Troubleshooting Tips for Linux/Solaris
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, "177ELF111331PH004"..., 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, "177ELF111331260v004"..., 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, "177ELF111331340N1004"..., 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, "177ELF111331PH004"..., 512) = 512
close(3) = 0
open("/lib/libdl.so.2", O_RDONLY) = 3
read(3, "177ELF111331260v004"..., 512) = 512
close(3) = 0
open("/lib/tls/libc.so.6", O_RDONLY) = 3
read(3, "177ELF111331340N1004"..., 512) = 512
close(3) = 0
open("/usr/java/jdk1.5.0_16/jre/lib/i386/jvm.cfg", O_RDONLY) = 3
read(3, "#n# @(#)jvm.cfgt1.8 04/02/02n# n"..., 4096) = 689
read(3, "", 4096) = 0
close(3) = 0
open("/etc/mtab", O_RDONLY) = 3
read(3, "/dev/sda2 / ext3 rw 0 0nnone /pr"..., 4096) = 787
close(3) = 0
open("/proc/meminfo", O_RDONLY) = 3
read(3, "MemTotal: 2074628 kBnMemFre"..., 1024) = 670
close(3) = 0
open("/etc/mtab", O_RDONLY) = 3
read(3, "/dev/sda2 / ext3 rw 0 0nnone /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.
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
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?
Article Updates
- Updated on May 2019: Minor changes and updates to the introduction section. Images are updated to HTTPS.
Thanks , great post!!!
Great link. Very helpful
Just encountered this blog post about how to drill down to Java thread level using top command should be a great help too. Identifying java thread Consuming CPU
Goooooooooooooooooooooooood
Very Useful information!!!!
Thanks for
Thank you. It helps me a lot to optimizing batch processes.
very good….