[teiid-issues] [JBoss JIRA] (TEIID-5185) JDBC client intermittently hangs when processing multi-batch result sets from VIPped Teiid server
Steven Hawkins (JIRA)
issues at jboss.org
Thu Jan 4 10:20:49 EST 2018
[ https://issues.jboss.org/browse/TEIID-5185?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13509385#comment-13509385 ]
Steven Hawkins commented on TEIID-5185:
---------------------------------------
Krum, do you have any updates on this? Even if it's caused by VIP, I would like to see if we can add make the protocol/client more resilient to this scenario.
> JDBC client intermittently hangs when processing multi-batch result sets from VIPped Teiid server
> -------------------------------------------------------------------------------------------------
>
> Key: TEIID-5185
> URL: https://issues.jboss.org/browse/TEIID-5185
> Project: Teiid
> Issue Type: Bug
> Components: JDBC Driver, Server
> Affects Versions: 9.3.4
> Environment: JDBC client was run through Apache JMeter, on a 64-bit Windows 7 Enterprise SP1 machine, using 64-bit JDK 8;
> Teiid Server runs on Linux.
> Reporter: Krum Bakalsky
> Assignee: Steven Hawkins
>
> We have a server-side application that is powered by Teiid version 9.3.4, and that exposes a Teiid JDBC endpoint to its clients.
> A couple of app instances are configured to sit behind a VIP load balancer, that works on the TCP level.
> We have been experiencing intermittently following problem, when we run Teiid 9.3.4 client to execute multi-batch queries to the server:
> * client successfully fetches few batches from server;
> * client hangs and its thread blocks on waiting for the next batch to be delivered on the network;
> * after 1 hour client throws exceptions that Socket is closed.
> When building up the JDBC connection URL the client refers directly to the server's VIP, and does not list particular server hosts:
> jdbc:teiid:<Application>@mm://<VIP's DNS name>:<port>
> Client thread's call stack:
> {code}
> "Thread Group 1-1" #41 prio=6 os_prio=0 tid=0x000000005e03a800 nid=0x17bc runnable [0x00000000623ae000]
> java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.socketRead(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.net.SocketInputStream.read(Unknown Source)
> at java.io.BufferedInputStream.fill(Unknown Source)
> at java.io.BufferedInputStream.read(Unknown Source)
> - locked <0x00000000f5f32420> (a org.teiid.core.util.AccessibleBufferedInputStream)
> at java.io.DataInputStream.readInt(Unknown Source)
> at org.teiid.netty.handler.codec.serialization.ObjectDecoderInputStream.readObjectOverride(ObjectDecoderInputStream.java:97)
> at java.io.ObjectInputStream.readObject(Unknown Source)
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.read(OioOjbectChannelFactory.java:117)
> at org.teiid.net.socket.SocketServerInstanceImpl.read(SocketServerInstanceImpl.java:324)
> at sun.reflect.GeneratedMethodAccessor22.invoke(Unknown Source)
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source)
> at java.lang.reflect.Method.invoke(Unknown Source)
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98)
> at com.sun.proxy.$Proxy21.read(Unknown Source)
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler$1.get(SocketServerInstanceImpl.java:427)
> at org.teiid.jdbc.ResultSetImpl.getResults(ResultSetImpl.java:449)
> at org.teiid.jdbc.ResultSetImpl.requestBatch(ResultSetImpl.java:382)
> at org.teiid.jdbc.BatchResults.requestBatchAndWait(BatchResults.java:227)
> at org.teiid.jdbc.BatchResults.requestNextBatch(BatchResults.java:142)
> at org.teiid.jdbc.BatchResults.hasNext(BatchResults.java:253)
> at org.teiid.jdbc.ResultSetImpl.hasNext(ResultSetImpl.java:510)
> at org.teiid.jdbc.ResultSetImpl.next(ResultSetImpl.java:259)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.commons.dbcp2.DelegatingResultSet.next(DelegatingResultSet.java:191)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.getStringFromResultSet(AbstractJDBCTestElement.java:535)
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:174)
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84)
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491)
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425)
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254)
> at java.lang.Thread.run(Unknown Source)
> Locked ownable synchronizers:
> - None
> {code}
> Client side exception after 1 hour:
> {code}
> 2017-12-19 13:17:07,160 WARN o.a.j.p.j.AbstractJDBCTestElement: Error closing ResultSet
> org.teiid.jdbc.TeiidSQLException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:135) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.TeiidSQLException.create(TeiidSQLException.java:71) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:168) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.commons.dbcp2.DelegatingResultSet.close(DelegatingResultSet.java:170) ~[commons-dbcp2-2.1.1.jar:2.1.1]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.close(AbstractJDBCTestElement.java:607) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.AbstractJDBCTestElement.execute(AbstractJDBCTestElement.java:176) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.protocol.jdbc.sampler.JDBCSampler.sample(JDBCSampler.java:84) [ApacheJMeter_jdbc.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:491) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:425) [ApacheJMeter_core.jar:3.2 r1790748]
> at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:254) [ApacheJMeter_core.jar:3.2 r1790748]
> at java.lang.Thread.run(Unknown Source) [?:1.8.0_121]
> Caused by: org.teiid.core.TeiidComponentException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.client.util.ExceptionUtil.convertException(ExceptionUtil.java:65) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:445) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: org.teiid.net.socket.SingleInstanceCommunicationException: TEIID20013 java.net.SocketException: Socket closed
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:217) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.util.concurrent.ExecutionException: java.net.SocketException: Socket closed
> at org.teiid.client.util.ResultsFuture.convertResult(ResultsFuture.java:104) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.client.util.ResultsFuture.get(ResultsFuture.java:99) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:214) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> Caused by: java.net.SocketException: Socket closed
> at java.net.SocketOutputStream.socketWrite(Unknown Source) ~[?:1.8.0_121]
> at java.net.SocketOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at java.io.DataOutputStream.write(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.core.util.MultiArrayOutputStream.writeTo(MultiArrayOutputStream.java:94) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.netty.handler.codec.serialization.ObjectEncoderOutputStream.writeObjectOverride(ObjectEncoderOutputStream.java:70) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at java.io.ObjectOutputStream.writeObject(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.OioOjbectChannelFactory$OioObjectChannel.write(OioOjbectChannelFactory.java:136) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerInstanceImpl.send(SocketServerInstanceImpl.java:213) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at sun.reflect.GeneratedMethodAccessor24.invoke(Unknown Source) ~[?:?]
> at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source) ~[?:1.8.0_121]
> at java.lang.reflect.Method.invoke(Unknown Source) ~[?:1.8.0_121]
> at org.teiid.net.socket.SocketServerConnectionFactory$ShutdownHandler.invoke(SocketServerConnectionFactory.java:98) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy21.send(Unknown Source) ~[?:?]
> at org.teiid.net.socket.SocketServerInstanceImpl$RemoteInvocationHandler.invoke(SocketServerInstanceImpl.java:433) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at org.teiid.net.socket.SocketServerConnection$1.invoke(SocketServerConnection.java:293) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> at com.sun.proxy.$Proxy24.closeRequest(Unknown Source) ~[?:?]
> at org.teiid.jdbc.ResultSetImpl.close(ResultSetImpl.java:164) ~[teiid-9.3.4-jdbc.jar:9.3.4]
> ... 9 more
> {code}
> Server-side log excerpt, after raising logger levels to Debug:
> {code}
> 2017-12-15 12:00:45.625 [NIO36 ] DEBUG - processing message:MessageHolder: key=550774 contents=Invoke interface org.teiid.client.DQP.executeRequest
> 2017-12-15 12:00:47.730 [ocessorQueue14017479] DEBUG - send message: MessageHolder: key=550774 contents=ResultsMessage rowCount=256 finalRow=-1
> 2017-12-15 12:00:47.737 [NIO36 ] DEBUG - processing message:MessageHolder: key=550776 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.738 [ocessorQueue14017553] DEBUG - send message: MessageHolder: key=550776 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:47.755 [NIO36 ] DEBUG - processing message:MessageHolder: key=550777 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:47.756 [ocessorQueue14017554] DEBUG - send message: MessageHolder: key=550777 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.389 [NIO36 ] DEBUG - processing message:MessageHolder: key=550778 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.389 [ocessorQueue14017556] DEBUG - send message: MessageHolder: key=550778 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.825 [NIO36 ] DEBUG - processing message:MessageHolder: key=550779 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.826 [ocessorQueue14017557] DEBUG - send message: MessageHolder: key=550779 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:00:48.932 [NIO36 ] DEBUG - processing message:MessageHolder: key=550780 contents=Invoke interface org.teiid.client.DQP.processCursorRequest
> 2017-12-15 12:00:48.933 [ocessorQueue14017558] DEBUG - send message: MessageHolder: key=550780 contents=ResultsMessage rowCount=2048 finalRow=-1
> 2017-12-15 12:02:18.386 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:05:55.327 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:09:29.545 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:13:08.903 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:16:41.864 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:20:16.875 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:23:57.860 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:27:30.273 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:31:07.795 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:34:46.439 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:38:23.325 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:41:59.227 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:45:35.526 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:49:14.088 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:52:46.177 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 12:56:24.407 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:03.109 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - TEIID40114 Unhandled exception, closing client instance: Connection reset by peer
> java.io.IOException: Connection reset by peer
> at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
> at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
> at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
> at sun.nio.ch.IOUtil.read(IOUtil.java:192)
> at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
> at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)
> at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)
> at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)
> at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)
> at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
> at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
> at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
> at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)
> at java.lang.Thread.run(Thread.java:745)
> 2017-12-15 13:00:52.143 [NIO36 ] DEBUG - Channel closed
> 2017-12-15 13:03:34.811 [NIO36 ] DEBUG - Channel closed
> {code}
> Legend:
> * 'Channel closed' is logged from org.teiid.transport.SSLAwareChannelHandler class, and its channelInactive method;
> * 'MessageHolder' logs are from org.teiid.net.socket.Message;
> * the log lines that contain rowCount, finalRow, etc. are coming from org.teiid.transport.SocketClientInstance.
> The problem is rarely reproducible, but it happens a few times every day, while running the JMeter tests full day.
> We are also running JMeter in a scenario where the client is referring directly to a server URL, therefore skipping the VIP. We haven't been able to reproduce the problem in this setting so far, which suggests that the issue has something to do with the VIP setup.
--
This message was sent by Atlassian JIRA
(v7.5.0#75005)
More information about the teiid-issues
mailing list