1s Delay in HttpServer since Java 7

Question

We are using the internal HttpServer class in a project to exchange data between a client and a server over HTTP. As we switched to Java 7, we realized a delay in the delivery of the results. We could reduce the problem to the following sample:

Class EchoServer creates the context /echo which simply returns the current date and the request URI upon each request. This service is then invoked by a client in a loop.

import java.io.IOException;
import java.io.OutputStream;
import java.net.InetSocketAddress;
import java.util.Date;

import com.sun.net.httpserver.HttpExchange;
import com.sun.net.httpserver.HttpHandler;
import com.sun.net.httpserver.HttpServer;

public class EchoServer {

    public static void main(String[] args) throws IOException {
        HttpServer server = HttpServer.create(new InetSocketAddress(80), 0);
        server.createContext("/echo", new EchoHandler());
        server.start();
    }

    static class EchoHandler implements HttpHandler {
        public void handle(HttpExchange httpExchange) throws IOException {
            httpExchange.getResponseHeaders().add("Content-type", "text/html");
            String response = "<b>" + new Date() + "</b> for "  + httpExchange.getRequestURI();
            httpExchange.sendResponseHeaders(200, response.length());
            OutputStream os = httpExchange.getResponseBody();
            os.write(response.getBytes());
            os.close();
        }
    }
}

The following client invokes the service in an infinite loop using class URL and prints the first character from the returned stream (which will be the < sign). In addition, the client prints the current time.

import java.io.BufferedReader;
import java.io.InputStreamReader;
import java.net.URL;

public class EchoClient {

    public static void main(String[] args) throws Exception{
        while(true) {
            URL url = new URL("http://localhost:80/echo");

            BufferedReader rd = new BufferedReader(new InputStreamReader(url.openStream()));
            int res = rd.read();
            System.out.println((char)res);
            System.out.println(System.currentTimeMillis());
        }
    }
}

If this code is executed on Java6, everything works fine and a result is printed approx. every 5 ms.

% java -version
java version "1.6.0_24"
Java(TM) SE Runtime Environment (build 1.6.0_24-b07)
Java HotSpot(TM) 64-Bit Server VM (build 19.1-b02, mixed mode)

% java EchoClient
<
1362515635677
<
1362515635682
<
1362515635687
<
1362515635691

If the code is executed on Java7, then each request uses 1000ms approx.

% java -version
java version "1.7.0_17"
Java(TM) SE Runtime Environment (build 1.7.0_17-b02)
Java HotSpot(TM) 64-Bit Server VM (build 23.7-b01, mixed mode)

% java EchoClient
<
1362517297845
<
1362517298844
<
1362517299845
<
1362517300845

It seems that a timeout of 1000ms is hidden somewhere. If the character is read on the InputStreamReader instead over the BufferedReader, the same delay happens. If a byte is read from the input stream directly, then no delay can be seen. On the other hand, if the EchoClient program is run against a servlet, then everything works fine, independent of whether the BufferedReader or the InputStreamReader is used.

It seems, that class InputStreamReader is expecting something from the server which is no longer delivered by the Java 7 implementation of HttpServer. Do you have an idea what exactly happens here and how this problem could be resolved? A workaround? Or is this a bug?

Thanks!

---

I have added further timings to the client code:

public static void main(String[] args) throws Exception{
    while(true) {
        System.out.println("0: "+System.currentTimeMillis());
        URL url = new URL("http://localhost:80/echo");
        System.out.println("1: "+System.currentTimeMillis());
        InputStream in = url.openStream();
        System.out.println("2: "+System.currentTimeMillis());
        InputStreamReader isr = new InputStreamReader(in);
        System.out.println("3: "+System.currentTimeMillis());
        char res = (char)isr.read(); // character read is `<`
        System.out.println(res + ": "+System.currentTimeMillis());
    }
}

with the following result:

% java EchoClient
0: 1362532555535
1: 1362532555537
2: 1362532555608
3: 1362532555609
<: 1362532555611
0: 1362532555612
1: 1362532555613
2: 1362532556608
3: 1362532556609
<: 1362532556610
0: 1362532556611
1: 1362532556612
2: 1362532557609
3: 1362532557610
<: 1362532557611
0: 1362532557612
1: 1362532557613

The first invocation of openStream takes some time (70ms), but all further invocations of openStream take much longer (996ms approx).

Whistling

Actually, com.sun.net.httpserver is not part of the Java API, and I think it shouldn't be used in mission-critical projects. You can try alternatives such as NanoHTTPD: elonen.iki.fi/code/nanohttpd – Tatman

This is very interesting but hard to believe. Can you insert more timestamp debugging to find our exactly which part of code takes 1 sec? – Milky

it is the call to url.openStream() which takes 1000ms, but only at its second (and later) invocation in the loop, and only if later an InputStreamReader is generated and used to read a byte. Thus, the BufferedReader seems to be innocent. – Whistling

to be even more precise: it is the invocation of getInputStream on class sun.net.www.protocol.http.HttpURLConnection. – Whistling

@Whistling can you use a debugger to find out where exact the application is stuck at during the 1000ms? – Milky

I ran the debugger with OpenJDK. It seems that the code hangs in SocketInputStream.socketRead0 which is native. This method is invoked from java.net.SocketInputStream.read(byte b[], int off, int length) with timeout = 0. – Whistling

@Whistling - use @ followed by user id (irreputable) or I won't receive your message. Can you provide the entire stacktrace when it's stuck? – Milky

It looks as though your issue is possibly from the client, which may have nothing to do with the HttpServer. Have you tried cross-calling from Java 6 to Java 7 and Java 7 to Java 6? You should run your code in a profiler and try to identify where it's getting stuck. It may help to actually add a sleep into the server portion so that you can actually see where the code is going. – Pentathlon

The internal HTTP server is shockingly bad, and it's used by stock Java web services (i.e. those web services not handled by an app server). It's slow, it seems gated (we were getting 5 req/s), just don't use it. – Motley

Answer 1

I experienced the same issue, but the comment by user1050755 points out the bug filled and it has one solution:

...this is not a problem when the server uses a threadpool, but for a single threaded server, this timeout gives rise to a bottleneck..

So, make a multi-threaded server:

        final Executor multi = Executors.newFixedThreadPool(10);
        final HttpServer server = HttpServer.create(new InetSocketAddress(s_HTTP_PORT), 5);
        //... do your REST bindings here
        server.setExecutor(multi);
        server.start();

Worked like a charm for me.

PS. comments like "com.sun.net.httpserver is awful" don't give any help - it's the same as "use Apache instead"

Secretariat

Answer 2

Just filed a bug report with Oracle. I'm getting a 38 ms delay here for both Java releases (SE 6 or 7).

/**
 * @test
 * @bug 
 * @summary  pipelining delay on Ubuntu 12.04.01 LTS / amd64
 */

import com.sun.net.httpserver.*;

import java.util.*;
import java.util.concurrent.*;
import java.io.*;
import java.net.*;

public class Bug {

    static int iterations = 20;
    static long requiredMinimumDelay = 10L;
    
    public static void main (String[] args) throws Exception {
        Handler handler = new Handler();
        InetSocketAddress addr = new InetSocketAddress (0);
        HttpServer server = HttpServer.create (addr, 0);
        HttpContext ctx = server.createContext ("/test", handler);
        ExecutorService executor = Executors.newCachedThreadPool();
        server.setExecutor (executor);
        server.start ();

        long minDelay = requiredMinimumDelay * 1000L;
        
        try {
            for(int i = 0; i < iterations; i++) {
                URL url = new URL ("http://localhost:"+server.getAddress().getPort()+"/test/foo.html");
                HttpURLConnection urlc = (HttpURLConnection)url.openConnection ();
                InputStream is = urlc.getInputStream();
                InputStreamReader isr = new InputStreamReader(is);
                BufferedReader br = new BufferedReader(isr);
                String res = br.readLine();
                br.close();
                
                // skip first few
                if(i < iterations/2) {
                    continue;
                }
                
                long delay = System.currentTimeMillis() - Long.parseLong(res);
                System.out.println("delay: "+delay+" ms");
                if(delay < minDelay) {
                    minDelay = delay;
                }
            }
        } catch (Exception ex) {}
        
        server.stop(2);
        executor.shutdown();
        
        if(minDelay > requiredMinimumDelay) {
            throw new Exception("minimum delay too large: "+minDelay);
        }
    }

    static class Handler implements HttpHandler {
        public void handle (HttpExchange t)
            throws IOException
        {
            InputStream is = t.getRequestBody();
            Headers map = t.getRequestHeaders();
            Headers rmap = t.getResponseHeaders();
            while (is.read () != -1) ;
            is.close();
            String response = Long.toString(System.currentTimeMillis())+"\n";
            t.sendResponseHeaders (200, response.length());
            OutputStream os = t.getResponseBody();
            os.write (response.getBytes());
            t.close();
        }
    }    
}

https://bugs.java.com/bugdatabase/view_bug?bug_id=8009548

Update: turns out Oracle classified it as "two different bugs" one for the 38ms (which they punted on?) and one for the 1000ms one, which they resolved here:

http://bugs.java.com/bugdatabase/view_bug.do?bug_id=8014254

So the 1000ms one hopefully fixed in versions "8b91" and "7u85" based on the backports linked.

Woodall

Answer 3

You don't seem to be closing the BufferedReader or the InputStream returned by url.openStream(). Not closing the stream might lead to problems with being able to reuse the connection on subsequent iterations (and is buggy behavior in general).

Do you have different results with explicit calls to rd.close() and stream.close()?

Fulmination

Calling rd.close() on the BufferedReader does not help, and neigher calling close on the input stream returned by the URL. – Whistling

Answer 4

A workaround (initially from user1050755) is adding this, before the sendResponseHeaders() method:

 httpExchange.getResponseHeaders().add("Connection", "close");

which basically disables "keep alive" functionality, but at least for me, made it go from 1000ms to 50ms per request, since I don't have the option of upgrading my JRE easily. Though it does lose "keep alive" functionality FWIW.

Synecdoche