RFR: 8307425 - Socket input stream read burns CPU cycles with back-to-back poll(0) calls

[olivergillespie]

As described in https://bugs.openjdk.org/browse/JDK-8307425, fix two places where nanoseconds are rounded *down* to milliseconds, leading to expensive tight poll/read loops in some scenarios.


import java.io.InputStream;
import java.net.Socket;

public class ReadSingle {
    public static void main(String[] args) throws Exception {
        Socket s = new Socket("httpbin.org", 443);
        s.setSoTimeout(2); s.getOutputStream().write(1);
        InputStream is = s.getInputStream();
        System.out.println("Starting single byte read");
        is.read();
        s.close();
    }
}


Before (first poll with 1ms timeout, then tight loop of poll/read for the remainder):

strace -ftT -e trace=poll,read java ReadSingle
...
Starting single byte read
[pid 20963] 10:38:04 read(5, 0x7fd14c191cb0, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000017>
[pid 20963] 10:38:04 poll([{fd=5, events=POLLIN}], 1, 1) = 0 (Timeout) <0.001071>
[pid 20963] 10:38:04 read(5, 0x7fd14c191cb0, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000014>
[pid 20963] 10:38:04 poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout) <0.000013>
[pid 20963] 10:38:04 read(5, 0x7fd14c191cb0, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000013>
[pid 20963] 10:38:04 poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout) <0.000013>
[pid 20963] 10:38:04 read(5, 0x7fd14c191cb0, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000013>
[pid 20963] 10:38:04 poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout) <0.000013>
[pid 20963] 10:38:04 read(5, 0x7fd14c191cb0, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000013>
[pid 20963] 10:38:04 poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout) <0.000014>
[pid 20963] 10:38:04 read(5, 0x7fd14c191cb0, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000013>
[pid 20963] 10:38:04 poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout) <0.000013>
[pid 20963] 10:38:04 read(5, 0x7fd14c191cb0, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000013>
[pid 20963] 10:38:04 poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout) <0.000013>
[pid 20963] 10:38:04 read(5, 0x7fd14c191cb0, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000014>
[pid 20963] 10:38:04 poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout) <0.000014>
[pid 20963] 10:38:04 read(5, 0x7fd14c191cb0, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000014>
[pid 20963] 10:38:04 poll([{fd=5, events=POLLIN}], 1, 0) = 0 (Timeout) <0.000014>
[pid 20963] 10:38:04 read(5, 0x7fd14c191cb0, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000013>
Exception in thread "main" java.net.SocketTimeoutException: Read timed out
	at java.base/sun.nio.ch.NioSocketImpl.timedRead(NioSocketImpl.java:273)
	at java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:299)
	at java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:341)
	at java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:791)
	at java.base/java.net.Socket$SocketInputStream.read(Socket.java:1099)
	at java.base/java.net.Socket$SocketInputStream.read(Socket.java:1093)
	at ReadSingle.main(ReadSingle.java:10)


After (single poll with 2ms timeout):

strace -ftT -e trace=poll,read java ReadSingle
...
Starting single byte read
[pid 21831] 10:39:13 read(5, 0x7fae1c199a10, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000014>
[pid 21831] 10:39:13 poll([{fd=5, events=POLLIN}], 1, 2) = 0 (Timeout) <0.002072>
[pid 21831] 10:39:13 read(5, 0x7fae1c199a10, 1) = -1 EAGAIN (Resource temporarily unavailable) <0.000012>
Exception in thread "main" java.net.SocketTimeoutException: Read timed out
	at java.base/sun.nio.ch.NioSocketImpl.timedRead(NioSocketImpl.java:279)
	at java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:305)
	at java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:347)
	at java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:797)
	at java.base/java.net.Socket$SocketInputStream.read(Socket.java:1099)
	at java.base/java.net.Socket$SocketInputStream.read(Socket.java:1093)
	at ReadSingle.main(ReadSingle.java:10)

-------------

Commit messages:
 - Fix whitespace
 - Tweak comment
 - Fix import
 - Also include SelChImpl
 - 8307425 - NioSocketImpl.timedRead burns CPU cycles with back-to-back poll(0) calls

Changes: https://git.openjdk.org/jdk/pull/13798/files
 Webrev: https://webrevs.openjdk.org/?repo=jdk&pr=13798&range=00
  Issue: https://bugs.openjdk.org/browse/JDK-8307425
  Stats: 13 lines in 2 files changed: 13 ins; 0 del; 0 mod
  Patch: https://git.openjdk.org/jdk/pull/13798.diff
  Fetch: git fetch https://git.openjdk.org/jdk.git pull/13798/head:pull/13798

PR: https://git.openjdk.org/jdk/pull/13798