JDK-6968351 : httpserver clashes with delayed TCP ACKs for low Content-Length
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.net
  • Affected Version: 6u21,11,17,19
  • Priority: P3
  • Status: Closed
  • Resolution: Fixed
  • OS: windows_2008
  • CPU: x86
  • Submitted: 2010-07-12
  • Updated: 2024-07-10
  • Resolved: 2024-05-07
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 23
23 b22Fixed
Related Reports
Duplicate :  
Relates :  
Relates :  
Relates :  
Sub Tasks
JDK-8331847 :  
Description
FULL PRODUCT VERSION :
java version "1.6.0_21"
Java(TM) SE Runtime Environment (build 1.6.0_21-b06)
Java HotSpot(TM) Client VM (build 17.0-b16, mixed mode)

ADDITIONAL OS VERSION INFORMATION :
Windows Server 2008 64bit Standard SP2
Windows Server 2003 64bit Standard SP2

EXTRA RELEVANT SYSTEM CONFIGURATION :
Standard TCP settings (esp. no registry entry for TcpAckFrequency)

A DESCRIPTION OF THE PROBLEM :
Httpserver slows down to about requests/minute when accessing URLs with small Contents-Length (<= 1000, typically, depending on headers).

This is due to the use of nio together with the fact that nttp server wites to the output channel twice, once to write the headers and once to write the response body. This clashes with the Windows TCP-Stack implementation and RFC1122.

On the TCP level, this can be seen as follows:

(1) Server writes out one TCP packet for the headers (with PSH).
(2) Client receives the packet but does not send ACK because it had received only ONE packet (RFC1122).
(3) Server applications writes to the channel, but OS does not send TCP packet for the response body, because there is no ACK and the internal write buffer still holds less than the MSS (typ. 1460 bytes), see RFC 1122, sect. 4.2.3.4.
(4) Over 100ms later, Client OS sends delayed ACK
(5) Server OS responds with response TCP packet (with PSH)

This can be ameliorated by setting TcpAckFrequency=1 on the client side, but this is not an option for a production environment.

FIX: Write the whole HTTP response message in one write to the channel.

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Clear from description

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
Performance should scale like the RTT of the network path.
ACTUAL -
Performance is dominated by delayed ACT timer, i.e 100-200ms per request.

REPRODUCIBILITY :
This bug can be reproduced always.

CUSTOMER SUBMITTED WORKAROUND :
No workaround for httpserver. Setting TCP_NODELAY on the socket does not help, but this seems to be another general problem.

Comments
> Hello Matthias [~mbaesken], I think we should create a new JBS issue track it along with the details including some of the thread dumps that are posted in this issue. I created https://bugs.openjdk.org/browse/JDK-8333864 .
10-06-2024

IIRC that test uses a short timeout - which could probably be increased. For that we would need to figure out whether the test would reliably fail without the fix if we increased the timeout. [~mbaesken] if you could experiment increasing the timeout on the `@run` line and see if there's a value that makes the test reliably pass on the slow machine that would also be helpful. We would then have to verify that the test would reliably fail with that value and without the fix. 45s (with timeoutFactor 9) seems a lot though. But it would still be worthwhile to figure out whether the test would pass with a greater value.
07-06-2024

> We had 10 timeouts in the test com/sun/net/httpserver/TcpNoDelayNotRequired.java on Alpine Linux since the test was added in May. Hello Matthias [~mbaesken], I think we should create a new JBS issue track it along with the details including some of the thread dumps that are posted in this issue.
07-06-2024

From what I see in the logs, we currently run jdk :tier2 on this Linux Alpine with "timeoutFactor:9" . From an example log of one of the observed timeouts, I get this : "java' timed out (timeout set to 45000ms, elapsed time including timeout handling was 47297ms)." Should we go higher because this test seems to be sometimes extremely slow ? This increased timeout works well for other tests, so I really wonder if there is something wrong or 'special' with this test .
07-06-2024

Hi [~mbaesken], when testing on slow machines, you should really set the timeout factor https://github.com/openjdk/jdk/blob/master/doc/testing.md#timeout_factor-1; that's what the option was intended for.
07-06-2024

here is the timeout info for one of the failing tests, collected by jstack. Maybe this helps a bit to find out more about these timeouts on Alpine Linux. ----------------------------------------------- Timeout information: Running jstack on process 8016 2024-06-03 03:38:36 Full thread dump OpenJDK 64-Bit Server VM (23-internal-adhoc.jenkinstest.jdk mixed mode, sharing): Threads class SMR info: _java_thread_list=0x00007f0b7fb3aaa0, length=19, elements={ 0x00007f0bdec0d070, 0x00007f0bcb077730, 0x00007f0bcb0786b0, 0x00007f0bcb078ea0, 0x00007f0bcb07ae80, 0x00007f0bcb07be70, 0x00007f0bcb07c630, 0x00007f0bcb04a810, 0x00007f0b855e7010, 0x00007f0b84ff2800, 0x00007f0b85417000, 0x00007f0b837fa800, 0x00007f0b82446e80, 0x00007f0b8482e000, 0x00007f0b8482f020, 0x00007f0b848227d0, 0x00007f0b83fe97b0, 0x00007f0b83feef00, 0x00007f0b7fb3b750 } _java_thread_list_alloc_cnt=52, _java_thread_list_free_cnt=50, _java_thread_list_max=21, _nested_thread_list_max=0 _tlh_cnt=18462, _tlh_times=147, avg_tlh_time=0.01, _tlh_time_max=68 _deleted_thread_cnt=16, _deleted_thread_times=0, avg_deleted_thread_time=0.00, _deleted_thread_time_max=0 _delete_lock_wait_cnt=0, _delete_lock_wait_max=0 _to_delete_list_cnt=0, _to_delete_list_max=1 "main" #1 [8018] prio=5 os_prio=0 cpu=613.68ms elapsed=50.15s tid=0x00007f0bdec0d070 nid=8018 in Object.wait() [0x00007f0be7766000] java.lang.Thread.State: WAITING (on object monitor) Thread: 0x00007f0bdec0d070 [0x1f52] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.Object.wait0(java.base@23-internal/Native Method) - waiting on <0x00000000d0026920> (a java.lang.Thread) at java.lang.Object.wait(java.base@23-internal/Object.java:374) at java.lang.Thread.join(java.base@23-internal/Thread.java:2017) - locked <0x00000000d0026920> (a java.lang.Thread) at java.lang.Thread.join(java.base@23-internal/Thread.java:2093) at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:85) "Reference Handler" #9 [8037] daemon prio=10 os_prio=0 cpu=3.33ms elapsed=49.78s tid=0x00007f0bcb077730 nid=8037 waiting on condition [0x00007f0b85efc000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0bcb077730 [0x1f65] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.ref.Reference.waitForReferencePendingList(java.base@23-internal/Native Method) at java.lang.ref.Reference.processPendingReferences(java.base@23-internal/Reference.java:246) at java.lang.ref.Reference$ReferenceHandler.run(java.base@23-internal/Reference.java:208) "Finalizer" #10 [8038] daemon prio=8 os_prio=0 cpu=0.33ms elapsed=49.77s tid=0x00007f0bcb0786b0 nid=8038 in Object.wait() [0x00007f0b85df9000] java.lang.Thread.State: WAITING (on object monitor) Thread: 0x00007f0bcb0786b0 [0x1f66] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.Object.wait0(java.base@23-internal/Native Method) - waiting on <0x00000000d0028338> (a java.lang.ref.NativeReferenceQueue$Lock) at java.lang.Object.wait(java.base@23-internal/Object.java:374) at java.lang.Object.wait(java.base@23-internal/Object.java:348) at java.lang.ref.NativeReferenceQueue.await(java.base@23-internal/NativeReferenceQueue.java:48) at java.lang.ref.ReferenceQueue.remove0(java.base@23-internal/ReferenceQueue.java:166) at java.lang.ref.NativeReferenceQueue.remove(java.base@23-internal/NativeReferenceQueue.java:89) - locked <0x00000000d0028338> (a java.lang.ref.NativeReferenceQueue$Lock) at java.lang.ref.Finalizer$FinalizerThread.run(java.base@23-internal/Finalizer.java:173) "Signal Dispatcher" #11 [8039] daemon prio=9 os_prio=0 cpu=0.84ms elapsed=49.75s tid=0x00007f0bcb078ea0 nid=8039 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0bcb078ea0 [0x1f67] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked "Service Thread" #12 [8040] daemon prio=9 os_prio=0 cpu=1.68ms elapsed=49.73s tid=0x00007f0bcb07ae80 nid=8040 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0bcb07ae80 [0x1f68] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked "Monitor Deflation Thread" #13 [8041] daemon prio=9 os_prio=0 cpu=3.27ms elapsed=49.72s tid=0x00007f0bcb07be70 nid=8041 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0bcb07be70 [0x1f69] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked "C2 CompilerThread0" #14 [8042] daemon prio=9 os_prio=0 cpu=10556.64ms elapsed=49.72s tid=0x00007f0bcb07c630 nid=8042 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0bcb07c630 [0x1f6a] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_in_native Compiling: 3615 ! 4 jdk.internal.net.http.Http1AsyncReceiver::flush (382 bytes) "C1 CompilerThread0" #17 [8043] daemon prio=9 os_prio=0 cpu=8209.00ms elapsed=49.71s tid=0x00007f0bcb04a810 nid=8043 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0bcb04a810 [0x1f6b] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_in_native Compiling: 4187 ! 3 sun.security.ssl.SSLEngineInputRecord::decodeInputRecord (821 bytes) "Common-Cleaner" #18 [8046] daemon prio=8 os_prio=0 cpu=7.24ms elapsed=49.33s tid=0x00007f0b855e7010 nid=8046 waiting on condition [0x00007f0b855d1000] java.lang.Thread.State: TIMED_WAITING (parking) Thread: 0x00007f0b855e7010 [0x1f6e] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked at jdk.internal.misc.Unsafe.park(java.base@23-internal/Native Method) - parking to wait for <0x00000000d00276e0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.parkNanos(java.base@23-internal/LockSupport.java:269) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@23-internal/AbstractQueuedSynchronizer.java:1852) at java.lang.ref.ReferenceQueue.await(java.base@23-internal/ReferenceQueue.java:79) at java.lang.ref.ReferenceQueue.remove0(java.base@23-internal/ReferenceQueue.java:151) at java.lang.ref.ReferenceQueue.remove(java.base@23-internal/ReferenceQueue.java:229) at jdk.internal.ref.CleanerImpl.run(java.base@23-internal/CleanerImpl.java:140) at java.lang.Thread.runWith(java.base@23-internal/Thread.java:1588) at java.lang.Thread.run(java.base@23-internal/Thread.java:1575) at jdk.internal.misc.InnocuousThread.run(java.base@23-internal/InnocuousThread.java:186) "Notification Thread" #19 [8048] daemon prio=9 os_prio=0 cpu=0.13ms elapsed=49.02s tid=0x00007f0b84ff2800 nid=8048 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0b84ff2800 [0x1f70] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked "MainThread" #20 [8050] prio=5 os_prio=0 cpu=11469.48ms elapsed=48.68s tid=0x00007f0b85417000 nid=8050 runnable [0x00007f0b84ec6000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0b85417000 [0x1f72] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked at sun.security.ssl.Authenticator.toLong(java.base@23-internal/Authenticator.java:631) at sun.security.ssl.OutputRecord.t13Encrypt(java.base@23-internal/OutputRecord.java:433) at sun.security.ssl.OutputRecord.encrypt(java.base@23-internal/OutputRecord.java:341) at sun.security.ssl.SSLEngineOutputRecord.encode(java.base@23-internal/SSLEngineOutputRecord.java:286) at sun.security.ssl.SSLEngineOutputRecord.encode(java.base@23-internal/SSLEngineOutputRecord.java:189) at sun.security.ssl.SSLEngineImpl.encode(java.base@23-internal/SSLEngineImpl.java:305) at sun.security.ssl.SSLEngineImpl.writeRecord(java.base@23-internal/SSLEngineImpl.java:251) at sun.security.ssl.SSLEngineImpl.wrap(java.base@23-internal/SSLEngineImpl.java:146) at sun.security.ssl.SSLEngineImpl.wrap(java.base@23-internal/SSLEngineImpl.java:123) at javax.net.ssl.SSLEngine.wrap(java.base@23-internal/SSLEngine.java:564) at jdk.internal.net.http.common.SSLFlowDelegate$Writer.wrapBuffers(java.net.http@23-internal/SSLFlowDelegate.java:898) at jdk.internal.net.http.common.SSLFlowDelegate$Writer.processData(java.net.http@23-internal/SSLFlowDelegate.java:813) at jdk.internal.net.http.common.SSLFlowDelegate$Writer$WriterDownstreamPusher.run(java.net.http@23-internal/SSLFlowDelegate.java:721) at jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(java.net.http@23-internal/SequentialScheduler.java:149) at jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(java.net.http@23-internal/SequentialScheduler.java:207) at jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(java.net.http@23-internal/SequentialScheduler.java:280) at jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(java.net.http@23-internal/SequentialScheduler.java:233) at jdk.internal.net.http.common.SSLFlowDelegate$Writer.incoming(java.net.http@23-internal/SSLFlowDelegate.java:745) at jdk.internal.net.http.common.SubscriberWrapper.incomingCaller(java.net.http@23-internal/SubscriberWrapper.java:438) at jdk.internal.net.http.common.SubscriberWrapper.onNext(java.net.http@23-internal/SubscriberWrapper.java:379) at jdk.internal.net.http.common.SubscriberWrapper.onNext(java.net.http@23-internal/SubscriberWrapper.java:57) at jdk.internal.net.http.common.SSLTube.onNext(java.net.http@23-internal/SSLTube.java:662) at jdk.internal.net.http.common.SSLTube.onNext(java.net.http@23-internal/SSLTube.java:68) at jdk.internal.net.http.Http1Exchange$Http1Publisher$WriteTask.run(java.net.http@23-internal/Http1Exchange.java:846) at jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(java.net.http@23-internal/SequentialScheduler.java:182) at jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(java.net.http@23-internal/SequentialScheduler.java:149) at jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(java.net.http@23-internal/SequentialScheduler.java:207) at jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(java.net.http@23-internal/SequentialScheduler.java:280) at jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(java.net.http@23-internal/SequentialScheduler.java:233) at jdk.internal.net.http.Http1Exchange.appendToOutgoing(java.net.http@23-internal/Http1Exchange.java:637) at jdk.internal.net.http.Http1Exchange.appendToOutgoing(java.net.http@23-internal/Http1Exchange.java:631) at jdk.internal.net.http.Http1Exchange.lambda$sendHeadersAsync$4(java.net.http@23-internal/Http1Exchange.java:355) at jdk.internal.net.http.Http1Exchange$$Lambda/0x00007f0b8b0fe078.apply(java.net.http@23-internal/Unknown Source) at java.util.concurrent.CompletableFuture.uniComposeStage(java.base@23-internal/CompletableFuture.java:1187) at java.util.concurrent.CompletableFuture.thenCompose(java.base@23-internal/CompletableFuture.java:2341) at jdk.internal.net.http.Http1Exchange.sendHeadersAsync(java.net.http@23-internal/Http1Exchange.java:337) at jdk.internal.net.http.Exchange.lambda$responseAsyncImpl0$8(java.net.http@23-internal/Exchange.java:567) at jdk.internal.net.http.Exchange$$Lambda/0x00007f0b8b0e7030.apply(java.net.http@23-internal/Unknown Source) at jdk.internal.net.http.Exchange.checkFor407(java.net.http@23-internal/Exchange.java:447) at jdk.internal.net.http.Exchange.lambda$responseAsyncImpl0$9(java.net.http@23-internal/Exchange.java:571) at jdk.internal.net.http.Exchange$$Lambda/0x00007f0b8b0f5b28.apply(java.net.http@23-internal/Unknown Source) at java.util.concurrent.CompletableFuture.uniHandle(java.base@23-internal/CompletableFuture.java:934) at java.util.concurrent.CompletableFuture.uniHandleStage(java.base@23-internal/CompletableFuture.java:950) at java.util.concurrent.CompletableFuture.handle(java.base@23-internal/CompletableFuture.java:2372) at jdk.internal.net.http.Exchange.responseAsyncImpl0(java.net.http@23-internal/Exchange.java:571) at jdk.internal.net.http.Exchange.responseAsyncImpl(java.net.http@23-internal/Exchange.java:423) at jdk.internal.net.http.Exchange.responseAsync(java.net.http@23-internal/Exchange.java:415) at jdk.internal.net.http.MultiExchange.responseAsyncImpl(java.net.http@23-internal/MultiExchange.java:445) at jdk.internal.net.http.MultiExchange.lambda$responseAsync0$2(java.net.http@23-internal/MultiExchange.java:365) at jdk.internal.net.http.MultiExchange$$Lambda/0x00007f0b8b0e6000.apply(java.net.http@23-internal/Unknown Source) at java.util.concurrent.CompletableFuture$UniCompose.tryFire(java.base@23-internal/CompletableFuture.java:1150) at java.util.concurrent.CompletableFuture.postComplete(java.base@23-internal/CompletableFuture.java:510) at java.util.concurrent.CompletableFuture$AsyncSupply.run(java.base@23-internal/CompletableFuture.java:1773) at jdk.internal.net.http.HttpClientImpl$DelegatingExecutor.execute(java.net.http@23-internal/HttpClientImpl.java:178) at java.util.concurrent.CompletableFuture.completeAsync(java.base@23-internal/CompletableFuture.java:2719) at jdk.internal.net.http.MultiExchange.responseAsync(java.net.http@23-internal/MultiExchange.java:318) at jdk.internal.net.http.HttpClientImpl.sendAsync(java.net.http@23-internal/HttpClientImpl.java:1052) at jdk.internal.net.http.HttpClientImpl.send(java.net.http@23-internal/HttpClientImpl.java:934) at jdk.internal.net.http.HttpClientFacade.send(java.net.http@23-internal/HttpClientFacade.java:133) at TcpNoDelayNotRequired.testHttpServer(TcpNoDelayNotRequired.java:102) at TcpNoDelayNotRequired.main(TcpNoDelayNotRequired.java:82) at java.lang.invoke.LambdaForm$DMH/0x00007f0b8b002c00.invokeStatic(java.base@23-internal/LambdaForm$DMH) at java.lang.invoke.LambdaForm$MH/0x00007f0b8b004000.invoke(java.base@23-internal/LambdaForm$MH) at java.lang.invoke.Invokers$Holder.invokeExact_MT(java.base@23-internal/Invokers$Holder) at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.base@23-internal/DirectMethodHandleAccessor.java:154) at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(java.base@23-internal/DirectMethodHandleAccessor.java:103) at java.lang.reflect.Method.invoke(java.base@23-internal/Method.java:580) at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138) at java.lang.Thread.runWith(java.base@23-internal/Thread.java:1588) at java.lang.Thread.run(java.base@23-internal/Thread.java:1575) "idle-timeout-task" #37 [8573] daemon prio=5 os_prio=0 cpu=0.85ms elapsed=29.53s tid=0x00007f0b837fa800 nid=8573 in Object.wait() [0x00007f0b83a58000] java.lang.Thread.State: TIMED_WAITING (on object monitor) Thread: 0x00007f0b837fa800 [0x217d] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked at java.lang.Object.wait0(java.base@23-internal/Native Method) - waiting on <0x00000000e291fd50> (a java.util.TaskQueue) at java.lang.Object.wait(java.base@23-internal/Object.java:374) at java.util.TimerThread.mainLoop(java.base@23-internal/Timer.java:569) - locked <0x00000000e291fd50> (a java.util.TaskQueue) at java.util.TimerThread.run(java.base@23-internal/Timer.java:522) "HTTP-Dispatcher" #38 [8574] prio=5 os_prio=0 cpu=375.96ms elapsed=29.47s tid=0x00007f0b82446e80 nid=8574 runnable [0x00007f0b837bb000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0b82446e80 [0x217e] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_in_native at sun.nio.ch.EPoll.wait(java.base@23-internal/Native Method) at sun.nio.ch.EPollSelectorImpl.doSelect(java.base@23-internal/EPollSelectorImpl.java:121) at sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@23-internal/SelectorImpl.java:130) - locked <0x00000000e2937308> (a sun.nio.ch.Util$2) - locked <0x00000000e2920150> (a sun.nio.ch.EPollSelectorImpl) at sun.nio.ch.SelectorImpl.select(java.base@23-internal/SelectorImpl.java:142) at sun.net.httpserver.ServerImpl$Dispatcher.run(jdk.httpserver@23-internal/ServerImpl.java:474) at java.lang.Thread.runWith(java.base@23-internal/Thread.java:1588) at java.lang.Thread.run(java.base@23-internal/Thread.java:1575) "HttpClient-2-SelectorManager" #39 [8575] daemon prio=5 os_prio=0 cpu=446.83ms elapsed=29.45s tid=0x00007f0b8482e000 nid=8575 runnable [0x00007f0b836b8000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0b8482e000 [0x217f] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_in_native at sun.nio.ch.EPoll.wait(java.base@23-internal/Native Method) at sun.nio.ch.EPollSelectorImpl.doSelect(java.base@23-internal/EPollSelectorImpl.java:121) at sun.nio.ch.SelectorImpl.lockAndDoSelect(java.base@23-internal/SelectorImpl.java:130) - locked <0x00000000e290b5e0> (a sun.nio.ch.Util$2) - locked <0x00000000e290b590> (a sun.nio.ch.EPollSelectorImpl) at sun.nio.ch.SelectorImpl.select(java.base@23-internal/SelectorImpl.java:142) at jdk.internal.net.http.HttpClientImpl$SelectorManager.run(java.net.http@23-internal/HttpClientImpl.java:1375) "HttpClient-2-Worker-0" #40 [8578] daemon prio=5 os_prio=0 cpu=2100.00ms elapsed=29.25s tid=0x00007f0b8482f020 nid=8578 waiting on condition [0x00007f0b8359f000] java.lang.Thread.State: TIMED_WAITING (parking) Thread: 0x00007f0b8482f020 [0x2182] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked at jdk.internal.misc.Unsafe.park(java.base@23-internal/Native Method) - parking to wait for <0x00000000e29a6e18> (a java.util.concurrent.SynchronousQueue$Transferer) at java.util.concurrent.locks.LockSupport.parkNanos(java.base@23-internal/LockSupport.java:410) at java.util.concurrent.LinkedTransferQueue$DualNode.await(java.base@23-internal/LinkedTransferQueue.java:452) at java.util.concurrent.SynchronousQueue$Transferer.xferLifo(java.base@23-internal/SynchronousQueue.java:194) at java.util.concurrent.SynchronousQueue.xfer(java.base@23-internal/SynchronousQueue.java:235) at java.util.concurrent.SynchronousQueue.poll(java.base@23-internal/SynchronousQueue.java:338) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@23-internal/ThreadPoolExecutor.java:1069) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@23-internal/ThreadPoolExecutor.java:1130) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@23-internal/ThreadPoolExecutor.java:642) at java.lang.Thread.runWith(java.base@23-internal/Thread.java:1588) at java.lang.Thread.run(java.base@23-internal/Thread.java:1575) "pool-2-thread-1" #41 [8749] prio=5 os_prio=0 cpu=3105.05ms elapsed=13.63s tid=0x00007f0b848227d0 nid=8749 waiting on condition [0x00007f0b81f98000] java.lang.Thread.State: TIMED_WAITING (parking) Thread: 0x00007f0b848227d0 [0x222d] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked at jdk.internal.misc.Unsafe.park(java.base@23-internal/Native Method) - parking to wait for <0x00000000e290b6d0> (a java.util.concurrent.SynchronousQueue$Transferer) at java.util.concurrent.locks.LockSupport.parkNanos(java.base@23-internal/LockSupport.java:410) at java.util.concurrent.LinkedTransferQueue$DualNode.await(java.base@23-internal/LinkedTransferQueue.java:452) at java.util.concurrent.SynchronousQueue$Transferer.xferLifo(java.base@23-internal/SynchronousQueue.java:194) at java.util.concurrent.SynchronousQueue.xfer(java.base@23-internal/SynchronousQueue.java:235) at java.util.concurrent.SynchronousQueue.poll(java.base@23-internal/SynchronousQueue.java:338) at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@23-internal/ThreadPoolExecutor.java:1069) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@23-internal/ThreadPoolExecutor.java:1130) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@23-internal/ThreadPoolExecutor.java:642) at java.lang.Thread.runWith(java.base@23-internal/Thread.java:1588) at java.lang.Thread.run(java.base@23-internal/Thread.java:1575) "C2 CompilerThread1" #15 [8832] daemon prio=9 os_prio=0 cpu=1791.31ms elapsed=7.47s tid=0x00007f0b83fe97b0 nid=8832 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0b83fe97b0 [0x2280] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_in_native Compiling: 3997 % 4 sun.net.httpserver.Request::headers @ 128 (499 bytes) "C2 CompilerThread2" #16 [8833] daemon prio=9 os_prio=0 cpu=1744.06ms elapsed=7.44s tid=0x00007f0b83feef00 nid=8833 runnable [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0b83feef00 [0x2281] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked Compiling: 4185 4 jdk.internal.net.http.Http1HeaderParser::parse (194 bytes) "Attach Listener" #42 [9006] daemon prio=9 os_prio=0 cpu=0.46ms elapsed=0.13s tid=0x00007f0b7fb3b750 nid=9006 waiting on condition [0x0000000000000000] java.lang.Thread.State: RUNNABLE Thread: 0x00007f0b7fb3b750 [0x232e] State: _at_safepoint _at_poll_safepoint 0 JavaThread state: _thread_blocked "GC Thread#7" os_prio=0 cpu=36.72ms elapsed=39.14s tid=0x00007f0b82e85e60 nid=8372 runnable "GC Thread#6" os_prio=0 cpu=58.28ms elapsed=39.14s tid=0x00007f0b82e85a70 nid=8371 runnable "GC Thread#5" os_prio=0 cpu=48.89ms elapsed=39.14s tid=0x00007f0b82e85680 nid=8370 runnable "GC Thread#4" os_prio=0 cpu=72.92ms elapsed=39.14s tid=0x00007f0b82e85290 nid=8369 runnable "GC Thread#3" os_prio=0 cpu=60.74ms elapsed=39.14s tid=0x00007f0b82e84ea0 nid=8368 runnable "GC Thread#2" os_prio=0 cpu=58.00ms elapsed=39.14s tid=0x00007f0b82e84ab0 nid=8367 runnable "GC Thread#1" os_prio=0 cpu=65.74ms elapsed=39.14s tid=0x00007f0b82e846c0 nid=8366 runnable "VM Thread" os_prio=0 cpu=18.83ms elapsed=49.84s tid=0x00007f0bcb0b72d0 nid=8036 runnable "VM Periodic Task Thread" os_prio=0 cpu=72.05ms elapsed=49.97s tid=0x00007f0bcb3a87c0 nid=8026 waiting on condition "G1 Service" os_prio=0 cpu=1.94ms elapsed=50.03s tid=0x00007f0bcb5bbac0 nid=8024 runnable "G1 Refine#0" os_prio=0 cpu=0.11ms elapsed=50.05s tid=0x00007f0bcb5bb060 nid=8023 runnable "G1 Conc#0" os_prio=0 cpu=0.10ms elapsed=50.08s tid=0x00007f0bcf9e3740 nid=8022 runnable "G1 Main Marker" os_prio=0 cpu=0.11ms elapsed=50.08s tid=0x00007f0bce17f0c0 nid=8021 runnable "GC Thread#0" os_prio=0 cpu=85.01ms elapsed=50.09s tid=0x00007f0bcf9e3350 nid=8020 runnable JNI global refs: 22, weak refs: 49 --- Timeout information end.
07-06-2024

We had 10 timeouts in the test com/sun/net/httpserver/TcpNoDelayNotRequired.java on Alpine Linux since the test was added in May. Any ideas why? The Alpine test machine might be indeed a little slow (and fastdebug binaries are used in those CI tests). Should we set a higher timeout value for this test to avoid issues on Alpine ?
07-06-2024

Changeset: 02c95a6d Author: robertengels <robaho@me.com> Committer: Daniel Fuchs <dfuchs@openjdk.org> Date: 2024-05-07 13:18:24 +0000 URL: https://git.openjdk.org/jdk/commit/02c95a6d7eb77ed17ae64d0f585197e87a67cc4a
07-05-2024

A pull request was submitted for review. URL: https://git.openjdk.org/jdk/pull/18667 Date: 2024-04-06 23:35:48 +0000
18-04-2024

To prevent this issue, the HttpServer (Java process) can be started by passing the following system property: -Dsun.net.httpserver.nodelay=true This will cause the HttpServer code to set the TCP_NODELAY socket option on the socket accept()ed by the server from a client connection. Doing so prevents the delays in receiving the response content.
30-09-2022

This affects Linux too as noticed in https://bugs.openjdk.org/browse/JDK-8294610
30-09-2022