When a Java application is experiencing performance issues like slowness, or it’s being unresponsive, we usually check the following things in order to troubleshoot.
- Threads consuming high CPU
- Threads marked as BLOCKED
- GC pause times
- Connection pool
- Application log
If our Java application makes http(s) requests to an external site or if our application depends on a database, then the issues and the delays from these remote resources affect directly our application response time. In these scenarios, although the thread is effectively “blocked” waiting for the network response, the JVM reports it as RUNNABLE because it can’t track the internal state of a native method. In Java, native threads are execution units managed directly by the underlying operating system (OS) kernel.
The following shows what a Java thread that is waiting for a response from a remote https site looks like (‘org.apache.http.*‘ tells us that it’s http protocol, and ‘sun.security.ssl.*‘ tells us that it’s over SSL, so it’s a https connection). A thread stuck in ‘socketRead0‘ indicates that the JVM has delegated a network read operation to the operating system, and the thread is now waiting for data to arrive from a remote source.
"http-nio-8080-exec-5" #42 daemon prio=5 os_prio=0 tid=0x00007f901c00b000 nid=0x2b03 runnable [0x00007f8ff4cfd000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:115)
at java.net.SocketInputStream.read(SocketInputStream.java:170)
at java.net.SocketInputStream.read(SocketInputStream.java:140)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
at sun.security.ssl.InputRecord.read(InputRecord.java:503)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:973)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:930)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:281)
at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138)
...
at com.example.service.RemoteClient.sendRequest(RemoteClient.java:54)In the same way, a thread that is waiting a response/data from a MySQL server shows as follows. Notice again ‘socketRead0‘. The ‘com.mysql.cj.*‘ indicates that it’s using MySQL JDBC driver, so it’s a connection to a MySQL database.
"mysql-query-worker-1" #31 prio=5 os_prio=0 tid=0x00007f80e0a51200 nid=0x2c03 runnable [0x000070000a2db000]
java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:64)
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)
at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52)
at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41)
at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:565)
at com.mysql.cj.protocol.a.NativeProtocol.checkErrorPacket(NativeProtocol.java:731)
at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:670)
at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:1010)
at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1072)
at com.mysql.cj.jdbc.ClientPreparedStatement.executeInternal(ClientPreparedStatement.java:948)
at com.mysql.cj.jdbc.ClientPreparedStatement.executeQuery(ClientPreparedStatement.java:1014)
at com.example.dao.UserDao.findUserById(UserDao.java:45)And below, the same scenario with a SFTP connection. Notice the ‘socketRead0‘ and the ‘net.schmizz.sshj.*‘.
"sftp reader" Id=231425 WAITING on net.schmizz.sshj.common.Buffer$PlainBuffer@295a188a
- waiting on net.schmizz.sshj.common.Buffer$PlainBuffer@295a188a
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:502)
at net.schmizz.sshj.connection.channel.ChannelInputStream.read(ChannelInputStream.java:106)
at net.schmizz.sshj.sftp.PacketReader.readIntoBuffer(PacketReader.java:51)
at net.schmizz.sshj.sftp.PacketReader.getPacketLength(PacketReader.java:59)
at net.schmizz.sshj.sftp.PacketReader.readPacket(PacketReader.java:75)
at net.schmizz.sshj.sftp.PacketReader.run(PacketReader.java:87)
...
"reader" Id=231423 RUNNABLE (in native)
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at net.schmizz.sshj.transport.Reader.run(Reader.java:49)
...On a ‘socketRead0‘ method, the network connection is in ESTABLISHED state. If a firewall is blocking (dropping) the connection, then you may see the thread stuck in method ‘socketConnect‘ (network connection is in SYN_SENT state).
In summary, it’s worth monitoring RUNNABLE threads that are stuck in method ‘socketRead0‘ for several seconds. Once we find this trace, then we will have to investigate why the remote source is taking a long time to reply (for example, if the remote source is a database then check what queries are being running on that database, check if there are locks at DB/table level, …). Besides that, it’s also interesting to monitor RUNNABLE threads stuck in method ‘java.io.*.readBytes‘ which could mean that there is a bottleneck on disk IO.
Adib Ahmed Akhtar