Thursday, November 7, 2013

Nausea with Tomcat after biting too much?

About an year back I wrote a post "Does Tomcat bite more than it can chew" about how Tomcat accepts more TCP connections that it can handle, and resets them later on. I also wrote a follow-up post "How to stop biting, when you cant chew more.." and explained how the UltraESB does it using Apache HttpComponents NIO underneath. I raised the issue on the Tomcat mailing list too, but found that most of the folks over there did not like what I had to say, and refused to change Tomcat.

This week one of our clients was running a load test using the UltraESB in front of a Tomcat instance, and wanted to measure the performance of the UltraESB to use WS-Security signatures over a Tomcat service. However, at 1000 concurrent users, the UltraESB started to report an XML parse exception with a "Premature end of file" for the responses.

After detailed investigations to reproduce the issue in our environment, we found the culprit to be Tomcat. However, proof of the issue was not that simple, and we used a standalone Java client to issue fixed sized asynchronous HTTP post requests to Tomcat, and measured the size of the responses received. The message size used was 5120 bytes, and thus a response of equal size was expected.

However, under load, Tomcat accepted a 5K request, but replied with an HTTP status code of 200, but without any payload. It sent the Content-Length header value as "0". Here is what Wireshark reported:

Here are the response headers that Tomcat sent back:
HTTP/1.1 200 OK
Server: Apache-Coyote/1.1
Content-Length: 0
Date: Thu, 07 Nov 2013 10:15:14 GMT
Connection: close
It's also interesting to note that Tomcat sometimes returns error responses which states that an internal error occurred; but with a HTTP status code of 200, instead of the expected 500 error code. Here is an example of such a payload returned:
<html><head><title>Apache Tomcat/7.0.28 - Error report</title><style><!--H1 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:22px;} H2 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:16px;} H3 {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;font-size:14px;} BODY {font-family:Tahoma,Arial,sans-serif;color:black;background-color:white;} B {font-family:Tahoma,Arial,sans-serif;color:white;background-color:#525D76;} P {font-family:Tahoma,Arial,sans-serif;background:white;color:black;font-size:12px;}A {color : black;}A.name {color : black;}HR {color : #525D76;}--></style> </head><body><h1>HTTP Status 500 - </h1><HR size="1" noshade="noshade"><p><b>type</b> Status report</p><p><b>message</b> <u></u></p><p><b>description</b> <u>The server encountered an internal error () that prevented it from fulfilling this request.</u></p><HR size="1" noshade="noshade"><h3>Apache Tomcat/7.0.28</h3></body></html>
It would have been so much better for many, if Tomcat did not bite fast, when it cannot chew!

Monday, October 14, 2013

ESB Performance Testing - Round 7 Published!

We have just published the results for the long awaited Round 7 - of ESB performance benchmarking. This round compares 4 of the leading free and open source ESBs, Mule CE 3.4.0, Talend ESB SE 5.3.1, WSO2 ESB 4.7.0 and the UltraESB 2.0.0
Although at first glance the above image may indicate that the WSO2 ESB and the UltraESB have very similar performance characteristics, the Devil is indeed in the detail.

During the testing we discovered several issues with the previously published article Round 6.5 from WSO2, including a severe response corruption for messages over 16,384 bytes when the default pass-through transport is being used. However, what's most surprising is that this issue remains in versions 4.6.0 and 4.7.0 of the WSO2 ESB, as well as the latest Milestone 4 of the soon to be released version 4.8.0.

Sadly, the WSO2 engineers conducting the Round 6.5 also failed to notice a complete failure of all of the XSLT test cases, but nevertheless published numbers obtained for the failed test cases as high performance numbers over the other ESBs.

Read about these and other flaws of the Round 6.5 in the article Why the Round 6.5 results published by WSO2 is flawed

Tuesday, August 27, 2013

UltraESB 2.0.0 is released!

Yeah, its been quite sometime since we did a major release of the UltraESB! Although the last GA release was extremely stable and widely used, we've made significant improvements for the long awaited 2.0.0 release.

Since the beginning, we have been privileged to work closely with some of the best architects actually using our software in production. The suggestions and improvements proposed by them helped us implement key features that set the UltraESB apart. These were real requirements that meant a lot for large scale production deployments running 24 x 7 x 365 with zero downtime. For the 2.0.0 release, we've implemented many features that have been similarly inspired by the requirements of a top Fortune #10 company. These include a built-in metrics management and alerting functionality, and a programmatic instance management capability - coupled with annotation driven extensibility, especially for custom message interception at various stages.

Ruwan has already blogged about some of the metrics graphs generated by the UConsole in the 2.0.0 release, and you could find more documentation at http://docs.adroitlogic.org The 2.0.0 release also migrates to Apache HttpComponents/Core 4.2.4 and Spring framework / Spring security 3.1.1 and introduces a concept of a 'Deployment Unit' that can be deployed/updated or removed at runtime. Deployment units now has the ability to re-load dependency JAR files into the runtime as well, and support atomic updates as before, which allows all changes to be deployed into ESB nodes servicing client requests - without causing inconsistencies.

The Mediation API has also been cleaned up and streamlined with the introduction of 'Support Interfaces'. While being backwards compatible, the changes will help users utilize the UltraESB mediation API more easily.

Check out the full news release here, and refer to the documentation to get started!

Saturday, February 23, 2013

What drives talent out?


A few days back I saw the famous presentation from Netflix about its culture, and three interesting slides from it was about what drives talent out of a company.


Today I came across a poster created by හිච්චි කොලුවා which shows another aspect from a more Sri Lankan point of view, and it says its the 'තිත්ත ඇත්ත' .. interesting points to think about!



PS: If you aim the moon, believe that you WILL get there. If a planes' limit is the clouds.. get onto a rocket.. do not deviate from achieving your goal!

Monday, November 5, 2012

How to stop biting, when you cant chew more..

This is a follow up to my earlier post 'Does Tomcat bite more than it can chew?' and illustrates a pure Java program that utilizes Java NIO to stop accepting new messages when one is not able to handle the load, without any dependence on the TCP backlog etc.

Program Implementation

We open a selector, and invoke the startListening() method, that opens a ServerSocketChannel and then binds it to port 8280. The channel is configured as non-blocking, and finally we register our interest in OP_ACCEPT to handle incoming connections.

    private void startListening() throws IOException {
        server = ServerSocketChannel.open();
        server.socket().bind(new InetSocketAddress(8280), 0);
        server.configureBlocking(false);
        server.register(selector, SelectionKey.OP_ACCEPT);
        System.out.println("\nI am ready to listen for new messages now..");
    }


If you telnet to the port via a command line after the server starts up, you would see a message "Hi there! type a word". The server accepts the incoming connection as a non-blocking connection, and registers OP_READ to read the content typed in.


To illustrate how the server can prevent another client from connecting to it while it serves the currently connected client, it prints "I accepted this one.. but not any more now" on its console, cancels the SelectionKey and closes the channel.

A new telnet session will see the "Connection refused" error as expected.

Next, I would type a small word into the first telnet session, and the server would print it in its console, and close the connection.

At the same time, it prints the message "I am ready to listen for new messages now.." on its console, and invokes the above startListening() method again - making it ready to listen and accept a new client.

We re-try the connection from the same command prompt that received the 'Connection refused' earlier, and as expected are greeted with the welcome message again.

What did we learn?

A low level NIO server can stop accepting new connections, if it can determine that its not able to serve new clients. Once it stops accepting connections this way, any client connection attempt will see a 'Connection Refused' error. This may not be the case if our server was implemented differently (See my last article and its example and how Tomcat behaves under load).

Complete source code

import java.io.IOException;
import java.net.InetSocketAddress;
import java.nio.ByteBuffer;
import java.nio.channels.SelectionKey;
import java.nio.channels.Selector;
import java.nio.channels.ServerSocketChannel;
import java.nio.channels.SocketChannel;
import java.util.Iterator;

public class TestAccept2 {

    private ServerSocketChannel server = null;
    private Selector selector = null;

    public static void main(String[] args) throws Exception {
        new TestAccept2().run();
    }

    private void run() throws Exception {
        selector = Selector.open();
        startListening();

        while (true) {
            selector.select();

            for (Iterator i = selector.selectedKeys().iterator(); i.hasNext(); ) {
                SelectionKey key = i.next();
                i.remove();
                if (key.isAcceptable()) {
                    SocketChannel client = server.accept();
                    client.configureBlocking(false);
                    client.socket().setTcpNoDelay(true);
                    client.register(selector, SelectionKey.OP_READ);

                    System.out.println("I accepted this one.. but not any more now");
                    key.cancel();
                    key.channel().close();
                    sayHello(client);

                } else if (key.isReadable()) {
                    readDataFromSocket(key);
                }
            }
        }
    }

    private void startListening() throws IOException {
        server = ServerSocketChannel.open();
        server.socket().bind(new InetSocketAddress(8280), 0);
        server.configureBlocking(false);
        server.register(selector, SelectionKey.OP_ACCEPT);
        System.out.println("\nI am ready to listen for new messages now..");
    }

    private void sayHello(SocketChannel channel) throws Exception {
        channel.write(ByteBuffer.wrap("Hi there! type a word\r\n".getBytes()));
    }

    private void readDataFromSocket(SelectionKey key) throws Exception {
        SocketChannel socketChannel = (SocketChannel) key.channel();
        ByteBuffer buffer = ByteBuffer.allocate(32);
        if (socketChannel.read(buffer) > 0) {
            buffer.flip();
            byte[] bytearr = new byte[buffer.remaining()];
            buffer.get(bytearr);
            System.out.print(new String(bytearr));
            socketChannel.close();

            startListening();
        }
    }

}


Wednesday, October 31, 2012

Does Tomcat bite more than it can chew?

This is an interesting blog post for me, since its about the root cause for an issue we saw with Tomcat back in May 2011, which remained unresolved. Under high concurrency and load, Tomcat would reset (i.e. TCP level RST) client connections, without refusing to accept them - as one would expect. I posted this again to the Tomcat user list a few days back, but then wanted to find out the root cause for myself, since it would surely come up again in the future.

Background

This issue initially became evident when we ran high concurrency load tests at a customer location in Europe, where the customer had back-end services deployed on multiple Tomcat instances, and wanted to use the UltraESB for routing messages with load balancing and fail-over. For the ESB Performance Benchmark, we had been using an EchoService written over the Apache HttpComponents/Core NIO library that scaled extremely well and behaved well at the TCP level, even under load. However, at the client site, they wanted the test run against real services deployed on Tomcat - to analyse a more realistic scenario. We used a Java based clone of ApacheBench called the 'Java Bench' which is also a part of the Apache HttpComponents project, to generate load. The client would go up-to concurrency levels of 2560, pushing as many messages as possible through the ESB, to back end services deployed over Tomcat.

Under high load, the ESB would start to see errors while talking to Tomcat, and the cause would be IO errors such as "Connection reset by peer". Now the problem to the ESB is that it had already started to send out an HTTP request / payload over an accepted TCP connection, and thus it does not know if it can fail-over safely by default to another node, since the backend service might have  performed some processing over the request it may have already received. Of-course, the ESB could be configured to retry on such errors as well, but our default behaviour was to fail-over only on the safer connection refused or connect timeout errors (i.e. a connection could not be established within the allocated time) - which ensures correct operation, even for non-idempotent services.

Recent Observations

We recently experienced the same issue with Tomcat when a customer wanted to perform a load test scenario where a back-end service would block for 1-5 seconds randomly, to simulate realistic behaviour. Here, again we saw that Tomcat was resetting accepted TCP connections, and we were able to capture this with Wireshark as follows, using JavaBench directly against a Tomcat based servlet


As can be seen in the trace, the client initiated a TCP connection with the source port 9386, and Tomcat running on port 9000 accepted the connection - note “1”. The client kept sending packets of a 100K request, and Tomcat kept acknowledging them. The last such case is annotated with note “2”. Note that the request payload was not complete at this time from the client – note “3”. Suddenly, Tomcat resets the connection – note “4”

Understanding the root cause

After failing to locate any code in the Tomcat source code that resets established connections, I wanted to simulate the behaviour with a very simple Java program. Luckily the problem was easy to reproduce with a simple program as follows:

import java.net.ServerSocket;
import java.net.Socket;

public class TestAccept1 {

    public static void main(String[] args) throws Exception {
        ServerSocket serverSocket = new ServerSocket(8280, 0);
        Socket socket = serverSocket.accept();
        Thread.sleep(3000000); // do nothing
    }
}


We just open a server socket on port 8280, with a backlog of 0 and start listening for connections. Since the backlog is 0, one could assume that only one client connection would be allowed - BUT, I could open more than that via telnet as follows, and even send some data afterwards by typing it in and pressing the enter key.

telnet localhost 8280
hello world

A netstat command now confirms that more than one connection is opene:

netstat -na | grep 8280
tcp        0      0 127.0.0.1:34629         127.0.0.1:8280          ESTABLISHED
tcp        0      0 127.0.0.1:34630         127.0.0.1:8280          ESTABLISHED
tcp6       0      0 :::8280                 :::*                    LISTEN    
tcp6      13      0 127.0.0.1:8280          127.0.0.1:34630         ESTABLISHED
tcp6      13      0 127.0.0.1:8280          127.0.0.1:34629         ESTABLISHED

However, the Java program has only accepted ONE socket, although at the OS level, two would appear. It seems like the OS also allows more than two connections to be opened, even when the backlog is specified as 0. On Ubuntu 12.04 x64, the netstat command would not show me the actual listen queue length - but I believe it was not 0. However, before and after this test, I did not see a difference in the reported statistics for "listen queue" overflow, which I could see with the "netstat -sp tcp | fgrep listen" command

Next I used the JavaBench from the SOA ToolBox and issued a small payload at concurrency 1024, with a single iteration against the same port 8280


As expected, all requests failed, but my Wireshark trace on port 8280 did not detect any connection resets. Pushing the concurrency to 2560 and the iterations to 10 started to show tcp level RSTs - which were similar to those seen on Tomcat, though not exactly the same.

 

Can Tomcat do better?

Yes, Possibly .. What an end user would expect from Tomcat is that it refuses to accept new connections when under load, and not to accept connections and then reset them halfway through. But one would ask if that is achievable? Especially considering the behaviour seen with the simple Java example we discussed.

Well, the solution could be to perform better handling of the low level HTTP connections and the sockets, and this is already done by the free and open source high performance Enterprise Service Bus UltraESB, which utilizes the excellent Apache HttpComponents project underneath.

How does the UltraESB behave

One could easily test this by using the 'stopNewConnectionsAt' property of our NIO listener. If you set it to 2, you wont be able to even open a Telnet session to the socket beyond 2.

The first would work, the second too
But the third would see a "Connection refused"
And the UltraESB would report the following on its logs:

  INFO HttpNIOListener HTTP Listener http-8280 paused  
  WARN HttpNIOListener$EventLogger Enter maintenance mode as open connections reached : 2

Although it refuses to accept new connections, already accepted connections executes without any hindrance to completion. Thus a hardware level load balancer in front of an UltraESB cluster can safely load balance if an UltraESB node is loaded beyond its configured limits, without having to deal with any connection resets. Once a connection slot becomes free, the UltraESB will start accepting new connections as applicable.

Analysing a corresponding TCP dump

To analyse the corresponding behaviour, we wrote a simple Echo proxy service on the UltraESB, that also slept for 1 to 5 seconds before it replied, and tested this with the same JavaBench under 2560 concurrent users, each trying to push 10 messages in iteration.

Out of the 25600 requests, 7 completed successfully, while 25593 failed, as expected. We also saw many tcp level RSTs on the Wireshark dump - which must have been issued by the underlying operating system.


However, what's interesting to note is the difference - the RSTs occur immediately on receiving the SYN packet from the client - and are not established HTTP or TCP connections, but elegant "Connection Refused" errors - which would be what the client can expect. Thus the client can safely fail-over to another node without any doubt, overhead or delay.

Appendix : Supporting high concurrency in general

During testing we also saw that the Linux OS could detect the opening of many concurrent connections at the same time as a SYN flood attack, and then start using SYN cookies. You would see messages such as 
-->
Possible SYN flooding on port 9000. Sending cookies

displayed on the output of a "sudo dmesg", if this happens. Hence, for a real load, it would be better to disable SYN cookies by turning it off as follows as the root user
-->
# echo 0 > /proc/sys/net/ipv4/tcp_syncookies

To make the change persist over reboots, add the following line to your /etc/sysctl.conf
-->
net.ipv4.tcp_syncookies = 0

To allow the Linux OS to accept more connections, its also recommended that the 'net.core.somaxconn' be increased - as it usually defaults to 128 or so. This could be performed by the root user as follows,
-->
# echo 1024 > /proc/sys/net/core/somaxconn

To persist the change, append the following to the /etc/sysctl.conf
-->
net.core.somaxconn = 1024


Kudos!

The UltraESB could not have behaved gracefully without the support of the underlying Apache HttpComponents library, and the help and support received from that project community, especially by Oleg Kalnichevski - whose code and help has always fascinated me!



Friday, September 7, 2012