HTTP 500 error and Chunked encoding in OSB/WebLogic

Till recently, there was a strange issue seen in peak time with my production WebLogic Server. I have a bunch of Web Services deployed in CXF in WebLogic server. The message flow is as below: -

External Load balancer --> OSB --> External Load balancer --> (CXF in) Web Logic


While up to 95 to 98% of the requests sent to WebLogic had been processed successfully, the remaining requests were timed out in 30 seconds by WebLogic server. When I looked at the access log generated in the WebLogic server, all timed out requests had recorded with HTTP status code 500.  It took a while to understand, isolate and resolve the issue.

I did a thread dump analysis and saw several hogging threads with a kind of trace given below:


"[ACTIVE] ExecuteThread: '43' for queue: 'weblogic.kernel.Default (self-tuning)'" RUNNABLE native
         
                java.net.SocketInputStream.socketRead0(Native Method)
         
                java.net.SocketInputStream.read(SocketInputStream.java:129)
         
                weblogic.servlet.internal.PostInputStream.read(PostInputStream.java:142)
         
                weblogic.utils.http.HttpChunkInputStream.readChunkSize(HttpChunkInputStream.java:115)
         
                weblogic.utils.http.HttpChunkInputStream.initChunk(HttpChunkInputStream.java:74)
         
                weblogic.utils.http.HttpChunkInputStream.skip(HttpChunkInputStream.java:203)
         
                weblogic.utils.http.HttpChunkInputStream.skipAllChunk(HttpChunkInputStream.java:378)
         
                weblogic.servlet.internal.ServletInputStreamImpl.ensureChunkedConsumed(ServletInputStreamImpl.java:35)
         
                weblogic.servlet.internal.ServletRequestImpl.skipUnreadBody(ServletRequestImpl.java:194)
         
                weblogic.servlet.internal.ServletRequestImpl.reset(ServletRequestImpl.java:152)
         
                weblogic.servlet.internal.MuxableSocketHTTP.requeue(MuxableSocketHTTP.java:195)
         
                weblogic.servlet.internal.VirtualConnection.requeue(VirtualConnection.java:329)
         
                weblogic.servlet.internal.ServletResponseImpl.send(ServletResponseImpl.java:1538)
         
                weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1455)
         
                weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
         
                weblogic.work.ExecuteThread.run(ExecuteThread.java:173)
After further investigation, I found that the WebLogic server was not receiving the message within the default POST TIMEOUT (30 seconds) configured in the WebLogic server. Increasing the time out value to 45 or 60 seconds did not help. It only aggravated the performance issue.

Let's look at how the issue was resolved. When you define a business service in Oracle Service Bus (OSB), you would have seen a parameter namely "Use Chunked Streaming Mode" under "HTTP Transport Configuration" section. The default value was configured as "Enabled". Apparently, the load balancer was not able to handle requests with chuncked encoding in peak time. It was unable to transmit the request message to the WebLogic server within the configured post timeout period. It can be validated against the thread dump shown above. After changing the value from "Enabled" to "Disabled", the 500 error has been eliminated permanently and now the server is in good health.

Thanks for reading this post and hope you liked the tip. Please feel free to post your comment here.

Connecting to a remote Oracle database host using SQL Plus

A small but very useful tip on connecting to local and remote Oracle databases using SQL Plus

You must be already aware of this - how to connect to a local database using SQL plus. If not, it is very simple as given below: -
sqlplus user/pass@sidname

But, do you know how to connect to a database which is running on a different host.The following command will help you to achieve this.

sqlplus "user/pass@(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(Host=xxx.xxx.x.xxx)(Port=1521))(CONNECT_DATA=(SID=sidname)))"

Hope you find this tip useful.

WebLogic stuck threads and java.net.SocketInputStream.socketRead0

If you are a WebLogic developer or an administrator, you would have rarely missed a very common issue - Stuck threads. When a WebLogic thread is unable to finish a task within 10 minutes (which is default), the thread is marked as "STUCK". When there are too many stuck threads in a server instance, then the health of the server instance will go into "Warning" state. It will be tempting for one to increase the stuck thread time from 10 minutes to say 20 minutes to avoid stuck threads. But, it will not solve the issue, only help postponing the issue. Let me share my experience with stuck threads here.

When I was contacted for help by the developers/support folks in my company, I immediately looked at the health of the server. It was in "Warning" state. The reason for "Warning" state was "ThreadPool has stuck threads". This clearly indicated that there were stuck threads for some reasons.

The immediate step I remembered was to take the thread dump of the WebLogic server instance. If you are not aware, the thread dump can be taken in three ways (may be more, I know only 3 :-) ): a) Kill -3 b) jstack or c) WebLogic admin console. After collecting the thread dump, carefully look at the dump - you will be able to see all the threads and respective state. In my case, I found the following stuck thread.

"[STUCK] ExecuteThread: '14' for queue: 'weblogic.kernel.Default (self-tuning)'" RUNNABLE native
java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:129)
oracle.net.ns.Packet.receive(Packet.java:293)
oracle.net.ns.DataPacket.receive(DataPacket.java:92)
oracle.net.ns.NetInputStream.getNextPacket(NetInputStream.java:174)
oracle.net.ns.NetInputStream.read(NetInputStream.java:119)
oracle.net.ns.NetInputStream.read(NetInputStream.java:94)
oracle.net.ns.NetInputStream.read(NetInputStream.java:79)
oracle.jdbc.driver.T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:122)
oracle.jdbc.driver.T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:78)
oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1040)
oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1016)
oracle.jdbc.driver.T4C8TTILob.receiveReply(T4C8TTILob.java:847)
oracle.jdbc.driver.T4C8TTIClob.read(T4C8TTIClob.java:227)
oracle.jdbc.driver.T4CConnection.getChars(T4CConnection.java:2652)
oracle.sql.CLOB.getChars(CLOB.java:288)
oracle.jdbc.driver.OracleClobReader.needChars(OracleClobReader.java:178)
oracle.jdbc.driver.OracleClobReader.read(OracleClobReader.java:141)
oracle.xml.parser.v2.XMLCharReader.fillBuffer(XMLCharReader.java:183)
oracle.xml.parser.v2.XMLByteReader.saveBuffer(XMLByteReader.java:450)
oracle.xml.parser.v2.XMLReader.fillBuffer(XMLReader.java:2363)
oracle.xml.parser.v2.XMLReader.tryRead(XMLReader.java:1087)
oracle.xml.parser.v2.XMLReader.scanXMLDecl(XMLReader.java:2922)
oracle.xml.parser.v2.XMLReader.pushXMLReader(XMLReader.java:269)
oracle.xml.parser.v2.XMLParser.parse(XMLParser.java:312)
oracle.xdb.XMLType.getDOM(XMLType.java:1806)
com.xxxxx.yyy.zzz.getAAAA(BBBBB.java:814)
com.xxxxx.businessdeligate.yyyyyy.getAAAA(BBBBBB.java:337)
sun.reflect.GeneratedMethodAccessor65.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
com.xxxxx.service.DDDDDD.processRequest(CCCCCC.java:33)
sun.reflect.GeneratedMethodAccessor64.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:124)
org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:82)
org.apache.cxf.jaxws.JAXWSMethodInvoker.invoke(JAXWSMethodInvoker.java:100)
org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:68)
org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:56)
org.apache.cxf.workqueue.SynchronousExecutor.execute(SynchronousExecutor.java:37)
org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:92)
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:207)
org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:73)
org.apache.cxf.transport.servlet.ServletDestination.doMessage(ServletDestination.java:79)
org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:256t)
org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160)
org.apache.cxf.transport.servlet.AbstractCXFServlet.invoke(AbstractCXFServlet.java:170)
org.apache.cxf.transport.servlet.AbstractCXFServlet.doPost(AbstractCXFServlet.java:148)
javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
weblogic.servlet.internal.StubSecurityHelper$ServletServiceAction.run(StubSecurityHelper.java:227)
weblogic.servlet.internal.StubSecurityHelper.invokeServlet(StubSecurityHelper.java:125)
weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:300)
weblogic.servlet.internal.ServletStubImpl.execute(ServletStubImpl.java:183)
weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.doIt(WebAppServletContext.java:3686)
weblogic.servlet.internal.WebAppServletContext$ServletInvocationAction.run(WebAppServletContext.java:3650)
weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:321)
weblogic.security.service.SecurityManager.runAs(SecurityManager.java:121)
weblogic.servlet.internal.WebAppServletContext.securedExecute(WebAppServletContext.java:2268)
weblogic.servlet.internal.WebAppServletContext.execute(WebAppServletContext.java:2174)
weblogic.servlet.internal.ServletRequestImpl.run(ServletRequestImpl.java:1446)
weblogic.work.ExecuteThread.execute(ExecuteThread.java:201)
weblogic.work.ExecuteThread.run(ExecuteThread.java:173)

The stuck thread could occur because of several reasons including the following: -

1. Remote server that you are accessing could be taking more time than expected
2. Network delay

In an ideal situation, you should talk to your remote service provider to reduce the response time (case 1) or network owner to check the latency issue (case 2). They should fix the issues at their end which will help you in turn to eliminate the stuck threads. For some reasons, the resolution might be time consuming and you may require to put an immediate stop to stuck threads as it would lead to thread exhaustion and higher system resource utilization. It is an unwanted situation. As a workaround, you can try with configuring time outs.

Query time out
In several cases, I have seen "Statement.execute" taking more time or sometime hanging infinitely because the database was not responding properly. You would want to time out these execute calls to save yourself from stuck thread. If you use WebLogic connection pool, you can configure statement time out parameter to a value which is acceptable to your application, say 15 seconds. The another way of doing this is to configure "Statement.setQueryTimeout" in the java code which will provide you fine control over timeout.

Read time out
In my case, after configuring query time out, the number of stuck threads has gone down drastically. But, not fully solved and still few were left. Further investigation shown me that the thread was hanging because of socket read operation. After searching entire Web, I found a useful WebLogic JVM parameter  - oracle.jdbc.ReadTimeout. The socket will wait till x seconds (as configured in the parameter) and then times out.

After configuring these two parameters, now my WebLogic server is free from any stuck threads. However, as I mentioned above, this should be used as a workaround and you should try to fix the real issue - network latency or the response time of the remote operation.

Thank for reading my post and please leave your comments or any further questions here.

How to use Percentile for subset of EXCEL data without using Pivot table

I thought twice before writing this post as it is not my usual stuff - Enterprise architecture/Integration/SOA/Web services. When I was analyzing the access logs of WebLogic application servers for a performance engineering project for an African customer, I had to spend some time on the excel. I wanted to share my experience as a useful tip here as it will be useful to someone in the globe.

I have been a big fan of Pivot table & Pivot chart for analyzing large set of records. Almost all the times,  my requirements - calculate minimum value, maximum value, average value, count of problematic/badly performing URLs - were same and done very easily using Pivot table. But this time, I got a new requirement - calculate the 90th percentile in addition to min, max, average and count statistics. Initially I thought it was a very easy task but believe me it took more than one full day.

See below sample records. (My original data was very different. For easy understanding, I am giving sample data here)



I want to calculate the 90% percentile for

1. Both animals
2. Only for Lion
3. Only for Tiger

Pivot table supports, by default, calculating min, max and average values but not percentile. The "percentile" function in Excel can be used to find 90th percentile of age for all kinds of animals (i.e., Tiger plus Lion) as mentioned below:

=PERCENTILE.INC($D$7:$D$16, 0.9)

Note: "C7 to C16" contains the kind and "D7 to D16" contains the age.

Next, we have to find the 90th percentile for Lion and Tiger separately. We have to extract the subset of given raw data and then apply percentile function. I choose to use "IF" function to extract the subset (i.e., records that belong only to "Lion" or "Tiger"). Now, my formule will look like below:

=PERCENTILE.INC(IF($C$7:$C$16="Lion",$D$7:$D$16), 0.9)

=PERCENTILE.INC(IF($C$7:$C$16="Tiger",$D$7:$D$16), 0.9)

Are we done? Not yet. In the result cell, I get "0" value instead of getting the expected value. This is where I actually spend most of times to resolve the issue. At last, one trick helped me - after typing the formula in the cell, instead of pressing "ENTER", we have to press "CTRL+SHIFT+ENTER". When we press "CTRL+SHIFT+ENTER", it puts a curly brace around the formula. Please see below new formule
{=PERCENTILE.INC(IF($C$7:$C$16="Lion",$D$7:$D$16), 0.9)} and {=PERCENTILE.INC(IF($C$7:$C$16="Tiger",$D$7:$D$16), 0.9)}


Now, I got the result which I expected (as given below):



There may be other way of doing this, but I wanted to share my experience. This has reduced my ongoing effort from few hours to few minutes and improved my productivity. If it saves your time too, I will be happy.

How to identify process id for a server (for example, Oracle Service Bus) that is listening on port number, say 8090

Young WebLogic/JBoss application server administrators in my company have asked me one question on several occasions - "There are several Java processes running in the Unix server. How do I identify the process id of an application server (for example, Oracle Service Bus) listening on port number 8090". I thought this tip may be required by many others in other parts of the world and hence this post.

In Linux:
It is little straight forward to find out the process id by using the following command.


[portalmid@SVRCBS59 ~]$ netstat -anp | grep 8090
(Not all processes could be identified, non-owned process info
will not be shown, you would have to be root to see it all.)
tcp 0 0 ::ffff:172.20.31.59:8090 :::* LISTEN 21962/java
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:39995 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:47691 ESTABLISHED 21962/java
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:42816 ESTABLISHED 21962/java
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:40047 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:48227 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:39825 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:52100 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:45243 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:44991 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:38068 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:33974 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:36778 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:55202 ESTABLISHED 21962/java
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:59590 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:57827 FIN_WAIT2 -
tcp 0 0 ::ffff:172.20.31.59:8090 ::ffff:172.20.31.60:43493 ESTABLISHED 21962/java
[portalmid@SVRCBS59 ~]$

Needless to explain, the process id is 21962.


In Solaris:
The above command does not work as such. I will write another post with example. Please wait for further update on this.

Thanks for reading my post and request you please to leave your comment here.