The developments of this issue are now described unequivocally in this new question: Why does the JVM show more latency for the same block of code after a busy spin pause?
I'm including below the source codes of a simple server and client that demonstrate and isolate the problem. Basically I'm timing the latency of a ping-pong (client-server-client) message. I start by sending one message every 1 millisecond. I wait for 200k messages to be sent so the HotSpot has a chance to optimize the code. Then I change my pause time from 1 millisecond to 30 seconds. For my surprise my write and read operation become considerably slower.
I don't think it is a JIT/HotSpot problem. I was able to pinpoint the slower method to the native JNI calls to write (write0) and read. It looks like the longer you pause the slower it becomes.
I'm looking for pointers on how to debug, understand, explain or fix this problem.
Server.java:
import java.io.IOException;
import java.net.InetSocketAddress;
import java.nio.ByteBuffer;
import java.nio.channels.ServerSocketChannel;
import java.nio.channels.SocketChannel;
public class Server {
private final ServerSocketChannel serverSocketChannel;
private final ByteBuffer readBuffer = ByteBuffer.allocateDirect(1024);
private final int port;
private final int msgSize;
public Server(int port, int msgSize) throws IOException {
this.serverSocketChannel = ServerSocketChannel.open();
this.port = port;
this.msgSize = msgSize;
}
public void start() throws IOException {
serverSocketChannel.socket().bind(new InetSocketAddress(port));
final SocketChannel socketChannel = serverSocketChannel.accept(); // blocking mode...
System.out.println("Client accepted!");
socketChannel.configureBlocking(false);
socketChannel.socket().setTcpNoDelay(true);
Thread t = new Thread(new Runnable() {
@Override
public void run() {
try {
while(true) {
int bytesRead = socketChannel.read(readBuffer);
if (bytesRead == -1) {
System.out.println("Client disconnected!");
return;
} else if (bytesRead > 0) {
if (readBuffer.position() == msgSize) {
// have a full message there...
readBuffer.flip();
int bytesSent = socketChannel.write(readBuffer);
if (bytesSent != msgSize) throw new RuntimeException("Could not send full message out: " + bytesSent);
readBuffer.clear();
}
}
}
} catch(Exception e) {
throw new RuntimeException(e);
}
}
});
t.start();
serverSocketChannel.close();
}
public static void main(String[] args) throws Exception {
Server s = new Server(9999, 8);
s.start();
}
}
Client.java:
import java.io.IOException;
import java.net.InetSocketAddress;
import java.nio.ByteBuffer;
import java.nio.channels.SocketChannel;
public class Client implements Runnable {
private static final int WARMUP = 200000;
private final SocketChannel socketChannel;
private final String host;
private final int port;
private final ByteBuffer outBuffer;
private final ByteBuffer inBuffer = ByteBuffer.allocateDirect(1024);
private final int msgSize;
private final StringBuilder sb = new StringBuilder(1024);
private int interval;
private int totalMessagesSent;
private long timeSent;
private int mod;
public Client(String host, int port, int msgSize) throws IOException {
this.socketChannel = SocketChannel.open();
this.host = host;
this.port = port;
this.outBuffer = ByteBuffer.allocateDirect(msgSize);
this.msgSize = msgSize;
for(int i = 0; i < msgSize; i++) outBuffer.put((byte) i);
outBuffer.flip();
this.interval = 1;
this.mod = 20000;
}
public static long busySleep(long t) {
long x = 0;
for(int i = 0; i < t * 20000; i++) {
x += System.currentTimeMillis() / System.nanoTime();
}
return x;
}
public void start() throws Exception {
this.socketChannel.configureBlocking(false);
this.socketChannel.socket().setTcpNoDelay(true);
this.socketChannel.connect(new InetSocketAddress(host, port));
while(!socketChannel.finishConnect()) {
System.out.println("Waiting to connect");
Thread.sleep(1000);
}
System.out.println("Please wait as output will appear every minute or so. After " + WARMUP + " messages you will see the problem.");
Thread t = new Thread(this);
t.start();
}
private final void printResults(long latency, long timeToWrite, long timeToRead, long zeroReads, long partialReads, long realRead) {
sb.setLength(0);
sb.append(new java.util.Date().toString());
sb.append(" Results: totalMessagesSent=").append(totalMessagesSent);
sb.append(" currInterval=").append(interval);
sb.append(" latency=").append(latency);
sb.append(" timeToWrite=").append(timeToWrite);
sb.append(" timeToRead=").append(timeToRead);
sb.append(" realRead=").append(realRead);
sb.append(" zeroReads=").append(zeroReads);
sb.append(" partialReads=").append(partialReads);
System.out.println(sb);
}
@Override
public void run() {
try {
while(true) {
busySleep(interval);
outBuffer.position(0);
timeSent = System.nanoTime();
int bytesSent = socketChannel.write(outBuffer);
long timeToWrite = System.nanoTime() - timeSent;
if (bytesSent != msgSize) throw new IOException("Can't write message: " + bytesSent);
inBuffer.clear();
long zeroReads = 0;
long partialReads = 0;
long timeToRead = System.nanoTime();
long realRead = 0;
while(inBuffer.position() != msgSize) {
realRead = System.nanoTime();
int bytesRead = socketChannel.read(inBuffer);
if (bytesRead == 0) {
zeroReads++;
} else if (bytesRead == -1) {
System.out.println("Other side disconnected!");
return;
} else if (bytesRead != msgSize) {
partialReads++;
realRead = -1;
} else {
realRead = System.nanoTime() - realRead;
}
}
long now = System.nanoTime();
timeToRead = now - timeToRead;
long latency = now - timeSent;
if (++totalMessagesSent % mod == 0 || totalMessagesSent == 1) {
printResults(latency, timeToWrite, timeToRead, zeroReads, partialReads, realRead);
}
if (totalMessagesSent == WARMUP) {
this.interval = 30000;
this.mod = 1;
}
}
} catch(Exception e) {
throw new RuntimeException(e);
}
}
public static void main(String[] args) throws Exception {
Client client = new Client("localhost", 9999, 8);
client.start();
}
}
I execute java -server -cp . Server and java -server -cp . Client. The output of the client is:
Per @dunni request, changing to 1 second delay instead of 30 second delay. Same problem:
