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

[olivergillespie]

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)

This pull request has now been integrated.

Changeset: 73ac7105
Author:    Oli Gillespie <ogillesp at amazon.com>
Committer: Alan Bateman <alanb at openjdk.org>
URL:       https://git.openjdk.org/jdk/commit/73ac710533a45bf5ba17f308aa49556b877b8bf9
Stats:     22 lines in 3 files changed: 20 ins; 0 del; 2 mod

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

Reviewed-by: alanb

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

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