0 Replies Latest reply on Nov 18, 2014 4:05 AM by Eustachius Hamamelis

    High CPU Load in Response to Slow HTTPS Traffic

    Eustachius Hamamelis Newbie

      The observation applies to these environments:

       

      OS: Linux, Windows

      AS platform: wildlfy-8.1 0.Final, wildfly-9.0.0.Alpha1

      Java: jdk1.7.0_67, jdk.1.8.0_25

       

      But not all combinations have been examined.

       

      Symptom 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;

      }