Uploaded image for project: 'HttpComponents HttpCore'
  1. HttpComponents HttpCore
  2. HTTPCORE-599

Capacity feedback does not throttle AsyncDataConsumer.consume() for Http1

Details

    • Bug
    • Status: Resolved
    • Blocker
    • Resolution: Fixed
    • 5.0-beta8
    • 5.0-beta9
    • HttpCore NIO
    • None
    • macOS Mojave using the IntelliJ CE 2019.2.1 runtime

    Description

      The capacity window mechanism in AbstractHttp1StreamDuplexer does not appear to be throttling calls to AsyncDataConsumer.consume(). This affects both client and server asynchronous entity consumers.

      The attached test program implements a simple 5.0 asynchronous HTTP/1.1 server. Aside from boilerplate code, the significant parts are:

      1. Set the HTTP1 initial window size to 8192.
      2. Add an AsyncExchangeHandler that creates an empty response and logs the AsyncDataConsumer method calls to the console.
      3. Updating the capacity channel is intentionally omitted, effectively providing an infinitely slow consumer.

      To test, post data of more than 8 KB to the server (e.g. using curl). I expect to see in the log consume() calls totaling at least 8192 and nothing after that until the socket times out. Instead, what I see is consume() calls delivering all the data and then streamEnd().

      Here is sample output for uploading almost 32 KB. I have used my IDE to add a logging breakpoint to show the capacity window on this line:

      https://github.com/apache/httpcomponents-core/blob/a60528ea58877d55dab266bd2813e065aac6ff2c/httpcore5/src/main/java/org/apache/hc/core5/http/impl/nio/AbstractHttp1StreamDuplexer.java#L313

      so those are also included in the output below.

      Mon Sep 09, 2019 10:27:18.893 AM SlowConsumerTest main FINE: Listening on /0:0:0:0:0:0:0:0:8080
      Mon Sep 09, 2019 10:27:31.294 AM SlowConsumerTest$MyExchangeHandler handleRequest FINEST: handleRequest called
      Mon Sep 09, 2019 10:27:31.332 AM SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 8192
      AbstractHttp1StreamDuplexer:313 capacity=0
      Mon Sep 09, 2019 10:27:31.341 AM SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called
      Mon Sep 09, 2019 10:27:31.342 AM SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 16384
      AbstractHttp1StreamDuplexer:313 capacity=-8192
      Mon Sep 09, 2019 10:27:31.346 AM SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called
      Mon Sep 09, 2019 10:27:31.348 AM SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 24576
      AbstractHttp1StreamDuplexer:313 capacity=-16384
      Mon Sep 09, 2019 10:27:31.352 AM SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called
      Mon Sep 09, 2019 10:27:31.354 AM SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8150 total 32726
      AbstractHttp1StreamDuplexer:313 capacity=-24534
      Mon Sep 09, 2019 10:27:31.357 AM SlowConsumerTest$MyExchangeHandler streamEnd FINEST: streamEnd called

      Attachments

        1. SlowConsumerTest.java
          4 kB
          Roy Hashimoto

        Issue Links

          Activity

            rhashimoto The cause of the problem turns out the HTTP/1.1 protocol handler being a bit too greedy when reading data. It would not break the loop in the `readable ` event as long as it could read some data from the underlying channel, so cleared interest in read events would never get a change to take effect. This issue probably only really manifests itself in extreme scenarios with literally zero latency but it did not get around to verifying that assumption. 

            The fix was to moderate the protocol handler greed when interest in read events got disabled as a result of the actual message exchange running out of capacity. It however required some changes in the IOSession API that now acts as a ByteChannel and exercises extra control over read / write operations.

            Pull request coming soon.

            Oleg           

            olegk Oleg Kalnichevski added a comment - rhashimoto  The cause of the problem turns out the HTTP/1.1 protocol handler being a bit too greedy when reading data. It would not break the loop in the `readable ` event as long as it could read some data from the underlying channel, so cleared interest in read events would never get a change to take effect. This issue probably only really manifests itself in extreme scenarios with literally zero latency but it did not get around to verifying that assumption.  The fix was to moderate the protocol handler greed when interest in read events got disabled as a result of the actual message exchange running out of capacity. It however required some changes in the IOSession API that now acts as a ByteChannel and exercises extra control over read / write operations. Pull request coming soon. Oleg           
            rhashimoto Roy Hashimoto added a comment -

            The fix branch looks much better to me. It doesn't look quite as good with https as it does with http. I changed this line in Http1IntegrationTest.testSlowResponseConsumer():

            https://github.com/apache/httpcomponents-core/blob/6614b42f35e7511e9e582314c77ce0e5032cf44f/httpcore5-testing/src/test/java/org/apache/hc/core5/testing/nio/Http1IntegrationTest.java#L992

            to:

            client.start(Http1Config.custom().setBufferSize(256).setInitialWindowSize(256).build());

            to set the initial window size. Tracking the capacity at AbstractHttp1StreamDuplexer.java:313 when running this test looks like this for http:

            capacity = 5
            capacity = -251
            capacity = -16
            capacity = -37
            capacity = 221
            capacity = -35
            capacity = -104

            and like this for https:

            capacity = 5
            capacity = -251
            capacity = -507
            capacity = -763
            capacity = -768
            capacity = -11
            capacity = 490
            capacity = 421

            I would expect the capacity to stay between -256 and +256 as it does for http. Maybe there is extra buffering for the TLS socket? It is throttling with https, just not as rigidly, so maybe that's okay.

            Aside from that the fixed behavior looks as expected.

            rhashimoto Roy Hashimoto added a comment - The fix branch looks much better to me. It doesn't look quite as good with https as it does with http. I changed this line in Http1IntegrationTest.testSlowResponseConsumer(): https://github.com/apache/httpcomponents-core/blob/6614b42f35e7511e9e582314c77ce0e5032cf44f/httpcore5-testing/src/test/java/org/apache/hc/core5/testing/nio/Http1IntegrationTest.java#L992 to: client.start(Http1Config.custom().setBufferSize(256).setInitialWindowSize(256).build()); to set the initial window size. Tracking the capacity at AbstractHttp1StreamDuplexer.java:313 when running this test looks like this for http: capacity = 5 capacity = -251 capacity = -16 capacity = -37 capacity = 221 capacity = -35 capacity = -104 and like this for https: capacity = 5 capacity = -251 capacity = -507 capacity = -763 capacity = -768 capacity = -11 capacity = 490 capacity = 421 I would expect the capacity to stay between -256 and +256 as it does for http. Maybe there is extra buffering for the TLS socket? It is throttling with https, just not as rigidly, so maybe that's okay. Aside from that the fixed behavior looks as expected.

            rhashimoto

             Maybe there is extra buffering for the TLS socket

            Yes, indeed. There is an extra layer of buffering for read / write operations. SSL buffers also need to be configured to be below the initial window size for TLS connections to behave similarly to plain connections. I can look at the whole session buffer / initial window size / SSL configuration as the next step.

            Oleg

            olegk Oleg Kalnichevski added a comment - rhashimoto  Maybe there is extra buffering for the TLS socket Yes, indeed. There is an extra layer of buffering for read / write operations. SSL buffers also need to be configured to be below the initial window size for TLS connections to behave similarly to plain connections. I can look at the whole session buffer / initial window size / SSL configuration as the next step. Oleg

            Commit 44cab548cb4e15d56235aa12eaf0898d028351d0 in httpcomponents-core's branch refs/heads/master from Oleg Kalnichevski
            [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=44cab54 ]

            HTTPCORE-599: I/O sessions to stop reading from the underlying network channel of READ interest is disabled

            jira-bot ASF subversion and git services added a comment - Commit 44cab548cb4e15d56235aa12eaf0898d028351d0 in httpcomponents-core's branch refs/heads/master from Oleg Kalnichevski [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=44cab54 ] HTTPCORE-599 : I/O sessions to stop reading from the underlying network channel of READ interest is disabled

            Merged to master in as is. I am however considering a major refactoring of TLS/SSL buffering code as a separate work item.

            Oleg

            olegk Oleg Kalnichevski added a comment - Merged to master in as is. I am however considering a major refactoring of TLS/SSL buffering code as a separate work item. Oleg

            Commit 44cab548cb4e15d56235aa12eaf0898d028351d0 in httpcomponents-core's branch refs/heads/HTTPCORE-596 from Oleg Kalnichevski
            [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=44cab54 ]

            HTTPCORE-599: I/O sessions to stop reading from the underlying network channel of READ interest is disabled

            jira-bot ASF subversion and git services added a comment - Commit 44cab548cb4e15d56235aa12eaf0898d028351d0 in httpcomponents-core's branch refs/heads/ HTTPCORE-596 from Oleg Kalnichevski [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=44cab54 ] HTTPCORE-599 : I/O sessions to stop reading from the underlying network channel of READ interest is disabled

            Commit ad241d1cb1137f039eba0da6d9e435dec650fafb in httpcomponents-core's branch refs/heads/tls-nio from Oleg Kalnichevski
            [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=ad241d1 ]

            Simplification of HTTP/1.1 read event handling logic; better fix for HTTPCORE-599

            jira-bot ASF subversion and git services added a comment - Commit ad241d1cb1137f039eba0da6d9e435dec650fafb in httpcomponents-core's branch refs/heads/tls-nio from Oleg Kalnichevski [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=ad241d1 ] Simplification of HTTP/1.1 read event handling logic; better fix for HTTPCORE-599

            Commit d0876a971945061d91d208cccdd18613a9786e53 in httpcomponents-core's branch refs/heads/tls-nio from Oleg Kalnichevski
            [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=d0876a9 ]

            Simplification of HTTP/1.1 read event handling logic; better fix for HTTPCORE-599

            jira-bot ASF subversion and git services added a comment - Commit d0876a971945061d91d208cccdd18613a9786e53 in httpcomponents-core's branch refs/heads/tls-nio from Oleg Kalnichevski [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=d0876a9 ] Simplification of HTTP/1.1 read event handling logic; better fix for HTTPCORE-599
            rhashimoto Roy Hashimoto added a comment -

            It looks like the change broke the fix for HTTP and isn't obviously better for HTTPS.

            When I run my initial test attached to the original submission (which tests HTTP only) I get this output which doesn't seem to be throttling at all:

            {{2019-09-24 7:38:07.973 -0700 SlowConsumerTest main FINE: Listening on /0:0:0:0:0:0:0:0:8080 }}
            {{2019-09-24 7:42:15.085 -0700 SlowConsumerTest$MyExchangeHandler handleRequest FINEST: handleRequest called }}
            {{2019-09-24 7:42:15.110 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 8192 }}
            capacity = 0
            {{2019-09-24 7:42:15.116 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }}
            {{2019-09-24 7:42:15.118 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 16384 }}
            capacity = -8192
            {{2019-09-24 7:42:15.130 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }}
            {{2019-09-24 7:42:15.131 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 24576 }}
            capacity = -16384
            {{2019-09-24 7:42:15.137 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }}
            {{2019-09-24 7:42:15.138 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 32768 }}
            capacity = -24576
            {{2019-09-24 7:42:15.141 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }}
            {{2019-09-24 7:42:15.142 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 40960 }}
            capacity = -32768
            {{2019-09-24 7:42:15.147 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }}
            {{2019-09-24 7:42:15.148 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 49152 }}
            capacity = -40960
            {{2019-09-24 7:42:15.152 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }}
            {{2019-09-24 7:42:15.153 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 1882 total 51034 }}
            capacity = -42842
            2019-09-24 7:42:15.156 -0700 SlowConsumerTest$MyExchangeHandler streamEnd FINEST: streamEnd called

            I also reran the test described in my comment on the first fix:

            https://issues.apache.org/jira/browse/HTTPCORE-599?focusedCommentId=16926693&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-16926693

            It now looks worse for HTTP and about the same for HTTPS:

            HTTP

            capacity = 5
            capacity = -251
            capacity = -507
            capacity = -763
            capacity = -1017
            capacity = -1273
            capacity = -1344 

            HTTPS

            capacity = 0
            capacity = -240
            capacity = -496
            capacity = -752
            capacity = 0
            capacity = 496
            capacity = 432

             

            rhashimoto Roy Hashimoto added a comment - It looks like the change broke the fix for HTTP and isn't obviously better for HTTPS. When I run my initial test attached to the original submission (which tests HTTP only) I get this output which doesn't seem to be throttling at all: {{2019-09-24 7:38:07.973 -0700 SlowConsumerTest main FINE: Listening on /0:0:0:0:0:0:0:0:8080 }} {{2019-09-24 7:42:15.085 -0700 SlowConsumerTest$MyExchangeHandler handleRequest FINEST: handleRequest called }} {{2019-09-24 7:42:15.110 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 8192 }} capacity = 0 {{2019-09-24 7:42:15.116 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }} {{2019-09-24 7:42:15.118 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 16384 }} capacity = -8192 {{2019-09-24 7:42:15.130 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }} {{2019-09-24 7:42:15.131 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 24576 }} capacity = -16384 {{2019-09-24 7:42:15.137 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }} {{2019-09-24 7:42:15.138 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 32768 }} capacity = -24576 {{2019-09-24 7:42:15.141 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }} {{2019-09-24 7:42:15.142 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 40960 }} capacity = -32768 {{2019-09-24 7:42:15.147 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }} {{2019-09-24 7:42:15.148 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 8192 total 49152 }} capacity = -40960 {{2019-09-24 7:42:15.152 -0700 SlowConsumerTest$MyExchangeHandler updateCapacity FINEST: updateCapacity called }} {{2019-09-24 7:42:15.153 -0700 SlowConsumerTest$MyExchangeHandler consume FINEST: consume 1882 total 51034 }} capacity = -42842 2019-09-24 7:42:15.156 -0700 SlowConsumerTest$MyExchangeHandler streamEnd FINEST: streamEnd called I also reran the test described in my comment on the first fix: https://issues.apache.org/jira/browse/HTTPCORE-599?focusedCommentId=16926693&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-16926693 It now looks worse for HTTP and about the same for HTTPS: HTTP capacity = 5 capacity = -251 capacity = -507 capacity = -763 capacity = -1017 capacity = -1273 capacity = -1344  HTTPS capacity = 0 capacity = -240 capacity = -496 capacity = -752 capacity = 0 capacity = 496 capacity = 432  

            rhashimoto I reverted the change that affected the throttling. Many thanks for testing the PR!

            Oleg

            olegk Oleg Kalnichevski added a comment - rhashimoto I reverted the change that affected the throttling. Many thanks for testing the PR! Oleg
            rhashimoto Roy Hashimoto added a comment -

            I'm happy to help. Behavior now looks essentially identical to after the original fix, i.e. throttling works within buffer size / initial window for HTTP, and with some additional buffering for HTTPS.

            rhashimoto Roy Hashimoto added a comment - I'm happy to help. Behavior now looks essentially identical to after the original fix, i.e. throttling works within buffer size / initial window for HTTP, and with some additional buffering for HTTPS.

            Commit 4ac49aa03445e4c7b70f5403f2d49d80353120e1 in httpcomponents-core's branch refs/heads/tls-nio from Oleg Kalnichevski
            [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=4ac49aa ]

            Simplification of HTTP/1.1 read event handling logic; better fix for HTTPCORE-599

            jira-bot ASF subversion and git services added a comment - Commit 4ac49aa03445e4c7b70f5403f2d49d80353120e1 in httpcomponents-core's branch refs/heads/tls-nio from Oleg Kalnichevski [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=4ac49aa ] Simplification of HTTP/1.1 read event handling logic; better fix for HTTPCORE-599

            rhashimoto Could you please try out the latest revision from this branch and let me know if input throttling works as expected?

            https://github.com/apache/httpcomponents-core/tree/tls-nio

            Oleg

            olegk Oleg Kalnichevski added a comment - rhashimoto Could you please try out the latest revision from this branch and let me know if input throttling works as expected? https://github.com/apache/httpcomponents-core/tree/tls-nio Oleg
            rhashimoto Roy Hashimoto added a comment -

            Behavior looks the same as my previous comment - both HTTP and HTTPS throttle, with HTTPS using wider bounds. I don't know if that is "as expected" with the new code or not.

            HTTP

            capacity = 5
            capacity = -251
            capacity = -16
            capacity = -37
            capacity = 221
            capacity = -35
            capacity = -104 

            HTTPS

            capacity = 0
            capacity = -240
            capacity = -496
            capacity = -752
            capacity = 0
            capacity = 496
            capacity = 432

            rhashimoto Roy Hashimoto added a comment - Behavior looks the same as my previous comment - both HTTP and HTTPS throttle, with HTTPS using wider bounds. I don't know if that is "as expected" with the new code or not. HTTP capacity = 5 capacity = -251 capacity = -16 capacity = -37 capacity = 221 capacity = -35 capacity = -104  HTTPS capacity = 0 capacity = -240 capacity = -496 capacity = -752 capacity = 0 capacity = 496 capacity = 432

            rhashimoto This is still expected. Now that the buffering logic has been simplified and application data buffering moved to the protocol handling layer I can start working on making the behavior of the HTTP/1.1 capacity window more predictable. But this is something for post 5.0 GA releases.

            Oleg

            olegk Oleg Kalnichevski added a comment - rhashimoto  This is still expected. Now that the buffering logic has been simplified and application data buffering moved to the protocol handling layer I can start working on making the behavior of the HTTP/1.1 capacity window more predictable. But this is something for post 5.0 GA releases. Oleg

            Commit dac54708766ece837f2755b7928ef83e12f9e384 in httpcomponents-core's branch refs/heads/master from Oleg Kalnichevski
            [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=dac5470 ]

            Simplification of HTTP/1.1 read event handling logic; better fix for HTTPCORE-599

            jira-bot ASF subversion and git services added a comment - Commit dac54708766ece837f2755b7928ef83e12f9e384 in httpcomponents-core's branch refs/heads/master from Oleg Kalnichevski [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=dac5470 ] Simplification of HTTP/1.1 read event handling logic; better fix for HTTPCORE-599

            Commit dac54708766ece837f2755b7928ef83e12f9e384 in httpcomponents-core's branch refs/heads/development from Oleg Kalnichevski
            [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=dac5470 ]

            Simplification of HTTP/1.1 read event handling logic; better fix for HTTPCORE-599

            jira-bot ASF subversion and git services added a comment - Commit dac54708766ece837f2755b7928ef83e12f9e384 in httpcomponents-core's branch refs/heads/development from Oleg Kalnichevski [ https://gitbox.apache.org/repos/asf?p=httpcomponents-core.git;h=dac5470 ] Simplification of HTTP/1.1 read event handling logic; better fix for HTTPCORE-599

            People

              Unassigned Unassigned
              rhashimoto Roy Hashimoto
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 50m
                  50m