Uploaded image for project: 'Undertow'
  1. Undertow
  2. UNDERTOW-345

High CPU Load in Response to Slow HTTPS Traffic

    XMLWordPrintable

Details

    • Bug
    • Resolution: Done
    • Major
    • 1.2.0.Beta6
    • 1.0.15.Final
    • SSL

    Description

      Servlets running on Wildfly struggle with high CPU load when reading data from the network. The behaviour seems somewhat paradoxical since the amount of CPU consumed increases when the speed of incoming data decreases. Only HTTPS connections are affected, HTTP works fine.

      Steps to reproduce the problem:

      The code snippet below shows the doPost method of a servlet which exhibits the behaviour described above:

      protected void doPost(HttpServletRequest request, HttpServletResponse response)
      throws ServletException, IOException
      {
      try (ServletInputStream is = request.getInputStream())
      {
      int i = 0;
      int n = 0;
      byte[] b = new byte[32 * 1024];
      while ((n = is.read(b)) != -1)

      { System.out.printf("doPost(%d,%d)%n", ++i, n); }

      }
      }

      When invoked, the method produces the following output:
      ...
      doPost(#=13,size=1,t=23 ms)
      doPost(#=14,size=4095,t=0 ms)
      doPost(#=15,size=1,t=17 ms)
      doPost(#=16,size=4095,t=1 ms)
      doPost(#=17,size=4096,t=10037 ms)
      doPost(#=18,size=4096,t=2 ms)
      doPost(#=19,size=1,t=10022 ms)
      doPost(#=20,size=4095,t=0 ms)
      doPost(#=21,size=1,t=1 ms)
      doPost(#=22,size=4095,t=0 ms)
      doPost(#=23,size=1,t=20 ms)
      doPost(#=24,size=4095,t=0 ms)
      doPost(#=25,size=1,t=10002 ms)
      doPost(#=26,size=4095,t=0 ms)
      doPost(#=27,size=1,t=12 ms)
      ...

      The periods exceeding 10s arise from intentional delays caused by the sender from the test harness. The call to the read method is blocked during these periods but the CPU load stays at a maximum (in contrast to when HTTP is used). In fact, Oracle's Flight Recorder reveals that

      io.undertow.servlet.spec.ServletInputStreamImpl.read(byte[])

      accounts for 99.5% of the time.

      Tracing the number of calls to the relevant methods shows how and where the CPU time is wasted. Annotated call tree:

      46 x javax.servlet.ServletInputStream.read (98.6%)
      46 x io.undertow.servlet.spec.ServletInputStreamImpl.read (98.6%)
      46 x io.undertow.servlet.spec.ServletInputStreamImpl.read (98.6%)
      46 x io.undertow.servlet.spec.ServletInputStreamImpl.readIntoBuffer (98.6%)
      46 x org.xnio.channels.Channels.readBlocking (98.6%) [HTTP 65x]
      3446249 x io.undertow.server.HttpServerExchange$ReadDispatchChannel.read (67.1%) [Equivalent HTTP request 126 x]
      3446203 x io.undertow.server.HttpServerExchange$ReadDispatchChannel.awaitReadable (29.1%) [Equivalent HTTP request 61 x]

      In fact readBlocking is forced into a busy wait by the channel.

      public static <C extends ScatteringByteChannel & SuspendableReadChannel>
      long readBlocking(C channel, ByteBuffer[] buffers, int offs, int len)
      throws IOException {
      long res;
      while ((res = channel.read(buffers, offs, len)) == 0)

      { channel.awaitReadable(); }

      return res;
      }

      Attachments

        Activity

          People

            sdouglas1@redhat.com Stuart Douglas
            eustachius_jira Eustachius Hamamelis (Inactive)
            Votes:
            2 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: