Client JBOSS Communication takes long time on threaded remote calls

[pankti.joshipura]

We are running a kind of OLTP system. Currently we are facing the issue in client jboss communication. It takes average 30 ms in just sending a call to Session Bean. We have pooled the remote objects of EJB3 at client end. But still it takes this much time in just sending the request. We are not performing any processing further and just looping back the response to client. We have applied all the slimming and tunnings points described on https://community.jboss.org/wiki/JBoss5xTuningSlimming. Currently we are sending 100 requests per second. Our target is to reach 1000 requests per second that too with application logic. The maximum total response time accepted (with application logic) is 20 ms. We just have one session bean that is all.

Please throw light on this, it would help us a lot.

[pankti.joshipura]

Hello!!!

Anyone is there to help me out. I can share all configuration or code required as further detail.

[hardikshah]

I am also facing the similar issue.

Below is sample statistics for a load testing i executed.

Milli Second	Number of Request	Percentage with respect to total request
<=1	9215	8.99
>1 and <=2	30016	29.28
>2 and <=5	41046	40.04
>5 and <=10	18899	18.44
>10	3324	3.24
Total Request	102500

I have also created a client program which makes RMI call to my JBoss application. I have commented my business logic in Session Bean and just giving success response directly from Session Bean.

From client, i am sending a packet with event timestamp value and in session bean i am comparing the timestamp received and current timestamp.

Through above I am calculating the time taken in milli seconds for request to reach my session bean. And same I am printting in log. (only one log per request)

So above statistics clearly shows that more than 60% of requests taking more than 2 milli second, which is not acceptable for my kind of application.

Please guide me as well for the solution.

[wdfink]

How do you test? Do you have a test on the same system?

How your client code looks like?

Maybe you have a network latency.

[pankti.joshipura]

We are conducting the test on the same server.

For your information we are using PooledInvoker and transport type is Socket. If you need I can share JBOSS config files also

[hardikshah]

Thank you for your response.

My client program and jboss resides on the same server, so there should not be any network latency issue.

Below is just to provide the idea about how i execute and calculate my test result.

Client Program:

LongAttribute nanoTime = new LongAttribute();

nanoTime.setID(54);

nanoTime.setLongValue(System.nanoTime()); //setting the timestamp value on client side.

requestPacket.addAttribute(nanoTime);

responsePacket = SessionBeanRemote.onlineService(requestPacket);

Server Side:

ArrayList<IRatingAttribute> Attribute = requestPacket.getAttribute(CommunicationConstant.RequestPacketAttributes.QUEUE_WAIT.getAttributeId());

double waitInQueue = 0;

String sessionID = null;

if(Attribute != null && Attribute.size()>0){

          waitInQueue = Math.ceil(((System.nanoTime() - ((LongAttribute)Attribute.get(0)).getLongValue()) / 1000000d));

}

if(Logger.isWarnEnabled()) Logger.logWarn(MODULE,"Wait In Que : " + waitInQueue);

[wdfink]

What JBoss version and OS you use?

AFAIK the calculation of nanos might be not exact depend on the OS and JVM , maybe you test it with a simple java program.

I've test the 'communication overhead' simple by using a dummy SLSB and the client call it 1.000.* times (with one and more threads) to have an idea of the average.

Also the duration depends on the payload (size of method parameter and return values).

[hardikshah]

What JBoss version and OS you use?

OS - Red Hat Enterprise Linux Server release 5.3 (Tikanga)

JBoss - 5.1.0.GA

AFAIK the calculation of nanos might be not exact depend on the OS and JVM , maybe you test it with a simple java program.

Sorry i did not get you on this, but both java client program and server is on same machine. So it should return same nanoTime.

I've test the 'communication overhead' simple by using a dummy SLSB and the client call it 1.000.* times (with one and more threads) to have an idea of the average.

Also the duration depends on the payload (size of method parameter and return values).

What was the performance you were getting?

[wdfink]

I observed that the nanos are calculated in slices, mean if measured you will see i.e.100/100/100/200 so it looks like that it is not real-time, but this is a bit in the past with earlier Java 1.6.

The performance I've seen was around 1.000 calls/sec with a single thread client on a blade system with Linux (I can't remember the exact configuration). If I find time I'll run a simple test

[pankti.joshipura]

Wolf thanks for your suggestions.

To rephrase the suggestion... you mean we should calculate the time straight away in millis via ... System.getCurrentTimeinMillis()...

[wdfink]

I don't trust the time's too much. If I do such test I will use a big number of retries as stress test and look to the avg. in total.

If you do so the variation of timestamps is negligible.

[hardikshah]

Wolf, I agree with you that stress test will come up with good avg. over all.

This will look perfectly all right if application is used for off-line processing or some dealy, some time is accepatable.

But the system I am working on is online processing system where each req has to be responded back in maximum 20 milli second.

The statistics table which I put earlier was only 5 concurrent requests. But when i try for 50 concurrent requests, result go very bad.

So just thinking, if I have not tunned my jboss correctly to handle such load. My traget is to achieve 200 TPS.

[hardikshah]

I was just debugging the jboss trace logs. I am not sure how to measure them but i just saw lot of time going in this activities.

1.

2012-02-17 19:06:57,041 TRACE [org.jboss.util.threadpool.RunnableTaskWrapper] (JBoss System Threads(1)-3) Begin run, wrapper=org.jboss.util.threadpool.RunnableTaskWrapper@493d73f3

2012-02-17 19:06:57,043 TRACE [org.jboss.util.threadpool.RunnableTaskWrapper] (JBoss System Threads(1)-3) End run, wrapper=org.jboss.util.threadpool.RunnableTaskWrapper@493d73f3

2012-02-17 19:06:57,265 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] (AcceptorThread[ServerSocket[addr=/0.0.0.0,port=0,localport=3873]]) Thread[AcceptorThread[ServerSocket[addr=/0.0.0.0,port=0,localport=3873]],5,jboss] accepted Socket[addr=/192.168.14.104,port=64630,localport=3873]

2012-02-17 19:06:57,266 TRACE [org.jboss.remoting.transport.socket.SocketServerInvoker] (AcceptorThread[ServerSocket[addr=/0.0.0.0,port=0,localport=3873]]) SocketServerInvoker[rac2:3873] trying to get a worker thread from threadpool for processing

2.

2012-02-17 19:06:57,388 TRACE [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[192.168.14.104:64630]) WorkerThread#0[192.168.14.104:64630] blocking to read version from input stream

2012-02-17 19:06:57,397 TRACE [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[192.168.14.104:64630]) WorkerThread#0[192.168.14.104:64630] read version 22 from input stream

3.

2012-02-17 19:07:16,804 TRACE [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[192.168.14.104:64630]) WorkerThread#0[192.168.14.104:64630] blocking to read version from input stream

2012-02-17 19:07:17,770 TRACE [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[192.168.14.104:64630]) WorkerThread#0[192.168.14.104:64630] read version -1 from input stream