RFR: 8307425 - Socket input stream read burns CPU cycles with back-to-back poll(0) calls
Alan Bateman
alanb at openjdk.org
Thu May 4 17:14:18 UTC 2023
On Thu, 4 May 2023 10:42:02 GMT, olivergillespie <duke at openjdk.org> wrote:
> 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>
> 1ms timeout --^
> [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>
> 0ms timeout (tight loop begins) --^
> [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>
> 2ms timeout --^
> [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)
src/java.base/share/classes/sun/nio/ch/NioSocketImpl.java line 188:
> 186: // Round up any excess nanos to the nearest millisecond. Avoids
> 187: // parking for less than requested, especially when poll is
> 188: // called with zero millis, which would return immediately.
Rounding down to 0 was an oversight so thanks for fixing this. The comment is a bit excessive, can you reduce it down to "Round up any excess nanos to the nearest millisecond to avoid parking for less than requested".
-------------
PR Review Comment: https://git.openjdk.org/jdk/pull/13798#discussion_r1185291198
More information about the nio-dev
mailing list