You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@ignite.apache.org by kellan <ke...@gmail.com> on 2019/04/05 20:53:32 UTC

DataStreamer: Failed to process selector key

I have a cluster that's using DataStreamers to write to cache. While I'm
writing, I get these messages periodically in my server logs:

The first on idx=3

	[20:16:28,249][SEVERE][grid-nio-worker-tcp-comm-0-#44][TcpCommunicationSpi]
Failed to process selector key [ses=GridSelectorNioSessionImpl
[worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=0,
bytesRcvd=108097202, bytesSent=274885774, bytesRcvd0=1858454,
bytesSent0=1052636, select=true, super=GridWorker
[name=grid-nio-worker-tcp-comm-0, igniteInstanceName=null, finished=false,
heartbeatTs=1554495387246, hashCode=1086027050, interrupted=false,
runner=grid-nio-worker-tcp-comm-0-#44]]],
writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
inRecovery=GridNioRecoveryDescriptor [acked=598656, resendCnt=0,
rcvCnt=665684, sentCnt=598679, reserved=true, lastAck=665664,
nodeLeft=false, node=TcpDiscoveryNode
[id=5a55e0b4-9200-4be6-be28-adf45abda7db, addrs=[0:0:0:0:0:0:0:1%lo,
100.96.4.1, 127.0.0.1, 172.17.0.1, 172.25.34.93],
sockAddrs=[/172.25.34.93:47500, ip-172-17-0-1.ec2.internal/172.17.0.1:47500,
/100.96.4.1:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
discPort=47500, order=2, intOrder=2, lastExchangeTime=1554492872746,
loc=false, ver=2.7.0#20181130-sha1:256ae401, isClient=false],
connected=true, connectCnt=1, queueLimit=4096, reserveCnt=2,
pairedConnections=false], outRecovery=GridNioRecoveryDescriptor
[acked=598656, resendCnt=0, rcvCnt=665684, sentCnt=598679, reserved=true,
lastAck=665664, nodeLeft=false, node=TcpDiscoveryNode
[id=5a55e0b4-9200-4be6-be28-adf45abda7db, addrs=[0:0:0:0:0:0:0:1%lo,
100.96.4.1, 127.0.0.1, 172.17.0.1, 172.25.34.93],
sockAddrs=[/172.25.34.93:47500, ip-172-17-0-1.ec2.internal/172.17.0.1:47500,
/100.96.4.1:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
discPort=47500, order=2, intOrder=2, lastExchangeTime=1554492872746,
loc=false, ver=2.7.0#20181130-sha1:256ae401, isClient=false],
connected=true, connectCnt=1, queueLimit=4096, reserveCnt=2,
pairedConnections=false], super=GridNioSessionImpl
[locAddr=/172.25.39.84:47100, rmtAddr=/172.25.34.93:16748,
createTime=1554495360665, closeTime=0, bytesSent=274869957,
bytesRcvd=108054028, bytesSent0=1052636, bytesRcvd0=1858454,
sndSchedTime=1554495360665, lastSndTime=1554495387216,
lastRcvTime=1554495387246, readsPaused=false,
filterChain=FilterChain[filters=[GridNioCodecFilter
[parser=o.a.i.i.util.nio.GridDirectParser@635f1c6d, directMode=true],
GridConnectionBytesVerifyFilter], accepted=true, markedForClose=true]]]
	java.io.IOException: Broken pipe
		at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
		at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
		at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
		at sun.nio.ch.IOUtil.write(IOUtil.java:51)
		at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
		at
org.apache.ignite.internal.util.nio.GridNioServer$DirectNioClientWorker.processWrite0(GridNioServer.java:1674)
		at
org.apache.ignite.internal.util.nio.GridNioServer$DirectNioClientWorker.processWrite(GridNioServer.java:1331)
		at
org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.processSelectedKeysOptimized(GridNioServer.java:2392)
		at
org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.bodyInternal(GridNioServer.java:2156)
		at
org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.body(GridNioServer.java:1797)
		at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120)
		at java.lang.Thread.run(Thread.java:748)

Then on idx=0

	[20:16:38,998][SEVERE][grid-nio-worker-tcp-comm-0-#44][TcpCommunicationSpi]
Failed to process selector key [ses=GridSelectorNioSessionImpl
[worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=0,
bytesRcvd=367438089, bytesSent=453177042, bytesRcvd0=13616308,
bytesSent0=9389157, select=true, super=GridWorker
[name=grid-nio-worker-tcp-comm-0, igniteInstanceName=null, finished=false,
heartbeatTs=1554495397987, hashCode=1129148649, interrupted=false,
runner=grid-nio-worker-tcp-comm-0-#44]]],
writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
inRecovery=GridNioRecoveryDescriptor [acked=765568, resendCnt=0,
rcvCnt=685485, sentCnt=765592, reserved=true, lastAck=685472,
nodeLeft=false, node=TcpDiscoveryNode
[id=28d08f11-fc1c-4f90-a71a-c33e2440533e, addrs=[0:0:0:0:0:0:0:1%lo,
100.96.3.1, 127.0.0.1, 172.17.0.1, 172.25.39.84],
sockAddrs=[/172.25.39.84:47500, ip-172-17-0-1.ec2.internal/172.17.0.1:47500,
/100.96.3.1:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
discPort=47500, order=4, intOrder=4, lastExchangeTime=1554492872631,
loc=false, ver=2.7.0#20181130-sha1:256ae401, isClient=false],
connected=false, connectCnt=2, queueLimit=4096, reserveCnt=3,
pairedConnections=false], outRecovery=GridNioRecoveryDescriptor
[acked=765568, resendCnt=0, rcvCnt=685485, sentCnt=765592, reserved=true,
lastAck=685472, nodeLeft=false, node=TcpDiscoveryNode
[id=28d08f11-fc1c-4f90-a71a-c33e2440533e, addrs=[0:0:0:0:0:0:0:1%lo,
100.96.3.1, 127.0.0.1, 172.17.0.1, 172.25.39.84],
sockAddrs=[/172.25.39.84:47500, ip-172-17-0-1.ec2.internal/172.17.0.1:47500,
/100.96.3.1:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
discPort=47500, order=4, intOrder=4, lastExchangeTime=1554492872631,
loc=false, ver=2.7.0#20181130-sha1:256ae401, isClient=false],
connected=false, connectCnt=2, queueLimit=4096, reserveCnt=3,
pairedConnections=false], super=GridNioSessionImpl
[locAddr=/172.25.46.90:63166, rmtAddr=/172.25.39.84:47100,
createTime=1554495300309, closeTime=0, bytesSent=453133874,
bytesRcvd=367422231, bytesSent0=9389157, bytesRcvd0=13616308,
sndSchedTime=1554495300309, lastSndTime=1554495397987,
lastRcvTime=1554495397987, readsPaused=false,
filterChain=FilterChain[filters=[GridNioCodecFilter
[parser=o.a.i.i.util.nio.GridDirectParser@20f8f42e, directMode=true],
GridConnectionBytesVerifyFilter], accepted=false, markedForClose=false]]]
	java.io.IOException: Connection reset by peer
		at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
		at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
		at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
		at sun.nio.ch.IOUtil.write(IOUtil.java:51)
		at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
		at
org.apache.ignite.internal.util.nio.GridNioServer$DirectNioClientWorker.processWrite0(GridNioServer.java:1674)
		at
org.apache.ignite.internal.util.nio.GridNioServer$DirectNioClientWorker.processWrite(GridNioServer.java:1331)
		at
org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.processSelectedKeysOptimized(GridNioServer.java:2392)
		at
org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.bodyInternal(GridNioServer.java:2156)
		at
org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.body(GridNioServer.java:1797)
		at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120)
		at java.lang.Thread.run(Thread.java:748)


These don't appear to be catchable errors, so I don't really know where
they're originating from. My DataStreamers are continuing to load data and
according to my metrics, which are based on results from the DataStreamer
futures, the DataStreamers aren't dropping rows. 

My question is, what exactly is going on here? Is it possible that I'm
losing data, and if not, is there some way to disable these messages, which
tend to clog up my logs and make troubleshooting real errors difficult.







--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

Re: DataStreamer: Failed to process selector key

Posted by Ilya Kasnacheev <il...@gmail.com>.
Hello!

I think they keep data on heap in hopes of further use which will not
happen.

Please make sure you close them explicitly.

Regards,
-- 
Ilya Kasnacheev


пн, 8 апр. 2019 г. в 20:49, kellan <ke...@gmail.com>:

> But are they actually affecting anything? Like are my DataStreamers
> dropping
> data, or is it being retried?
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>

Re: DataStreamer: Failed to process selector key

Posted by kellan <ke...@gmail.com>.
But are they actually affecting anything? Like are my DataStreamers dropping
data, or is it being retried?



--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/

Re: DataStreamer: Failed to process selector key

Posted by Ilya Kasnacheev <il...@gmail.com>.
Hello!

This likely means you have long GCs or network errors, so Ignite will not
get acknowledges on its messages and close connection.

You could try ncreasing TcpCommunicationSpi.connectionTimeout or
IgniteCofiguration.failureDetectionTimeout to make those go away, or to
make sure you don't have long GCs.

Regards,
-- 
Ilya Kasnacheev


пт, 5 апр. 2019 г. в 23:53, kellan <ke...@gmail.com>:

> I have a cluster that's using DataStreamers to write to cache. While I'm
> writing, I get these messages periodically in my server logs:
>
> The first on idx=3
>
>
> [20:16:28,249][SEVERE][grid-nio-worker-tcp-comm-0-#44][TcpCommunicationSpi]
> Failed to process selector key [ses=GridSelectorNioSessionImpl
> [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=0,
> bytesRcvd=108097202, bytesSent=274885774, bytesRcvd0=1858454,
> bytesSent0=1052636, select=true, super=GridWorker
> [name=grid-nio-worker-tcp-comm-0, igniteInstanceName=null, finished=false,
> heartbeatTs=1554495387246, hashCode=1086027050, interrupted=false,
> runner=grid-nio-worker-tcp-comm-0-#44]]],
> writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
> readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
> inRecovery=GridNioRecoveryDescriptor [acked=598656, resendCnt=0,
> rcvCnt=665684, sentCnt=598679, reserved=true, lastAck=665664,
> nodeLeft=false, node=TcpDiscoveryNode
> [id=5a55e0b4-9200-4be6-be28-adf45abda7db, addrs=[0:0:0:0:0:0:0:1%lo,
> 100.96.4.1, 127.0.0.1, 172.17.0.1, 172.25.34.93],
> sockAddrs=[/172.25.34.93:47500, ip-172-17-0-1.ec2.internal/
> 172.17.0.1:47500,
> /100.96.4.1:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=2, intOrder=2, lastExchangeTime=1554492872746,
> loc=false, ver=2.7.0#20181130-sha1:256ae401, isClient=false],
> connected=true, connectCnt=1, queueLimit=4096, reserveCnt=2,
> pairedConnections=false], outRecovery=GridNioRecoveryDescriptor
> [acked=598656, resendCnt=0, rcvCnt=665684, sentCnt=598679, reserved=true,
> lastAck=665664, nodeLeft=false, node=TcpDiscoveryNode
> [id=5a55e0b4-9200-4be6-be28-adf45abda7db, addrs=[0:0:0:0:0:0:0:1%lo,
> 100.96.4.1, 127.0.0.1, 172.17.0.1, 172.25.34.93],
> sockAddrs=[/172.25.34.93:47500, ip-172-17-0-1.ec2.internal/
> 172.17.0.1:47500,
> /100.96.4.1:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=2, intOrder=2, lastExchangeTime=1554492872746,
> loc=false, ver=2.7.0#20181130-sha1:256ae401, isClient=false],
> connected=true, connectCnt=1, queueLimit=4096, reserveCnt=2,
> pairedConnections=false], super=GridNioSessionImpl
> [locAddr=/172.25.39.84:47100, rmtAddr=/172.25.34.93:16748,
> createTime=1554495360665, closeTime=0, bytesSent=274869957,
> bytesRcvd=108054028, bytesSent0=1052636, bytesRcvd0=1858454,
> sndSchedTime=1554495360665, lastSndTime=1554495387216,
> lastRcvTime=1554495387246, readsPaused=false,
> filterChain=FilterChain[filters=[GridNioCodecFilter
> [parser=o.a.i.i.util.nio.GridDirectParser@635f1c6d, directMode=true],
> GridConnectionBytesVerifyFilter], accepted=true, markedForClose=true]]]
>         java.io.IOException: Broken pipe
>                 at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
>                 at
> sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
>                 at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
>                 at sun.nio.ch.IOUtil.write(IOUtil.java:51)
>                 at
> sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
>                 at
>
> org.apache.ignite.internal.util.nio.GridNioServer$DirectNioClientWorker.processWrite0(GridNioServer.java:1674)
>                 at
>
> org.apache.ignite.internal.util.nio.GridNioServer$DirectNioClientWorker.processWrite(GridNioServer.java:1331)
>                 at
>
> org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.processSelectedKeysOptimized(GridNioServer.java:2392)
>                 at
>
> org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.bodyInternal(GridNioServer.java:2156)
>                 at
>
> org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.body(GridNioServer.java:1797)
>                 at
> org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120)
>                 at java.lang.Thread.run(Thread.java:748)
>
> Then on idx=0
>
>
> [20:16:38,998][SEVERE][grid-nio-worker-tcp-comm-0-#44][TcpCommunicationSpi]
> Failed to process selector key [ses=GridSelectorNioSessionImpl
> [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=0,
> bytesRcvd=367438089, bytesSent=453177042, bytesRcvd0=13616308,
> bytesSent0=9389157, select=true, super=GridWorker
> [name=grid-nio-worker-tcp-comm-0, igniteInstanceName=null, finished=false,
> heartbeatTs=1554495397987, hashCode=1129148649, interrupted=false,
> runner=grid-nio-worker-tcp-comm-0-#44]]],
> writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
> readBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768],
> inRecovery=GridNioRecoveryDescriptor [acked=765568, resendCnt=0,
> rcvCnt=685485, sentCnt=765592, reserved=true, lastAck=685472,
> nodeLeft=false, node=TcpDiscoveryNode
> [id=28d08f11-fc1c-4f90-a71a-c33e2440533e, addrs=[0:0:0:0:0:0:0:1%lo,
> 100.96.3.1, 127.0.0.1, 172.17.0.1, 172.25.39.84],
> sockAddrs=[/172.25.39.84:47500, ip-172-17-0-1.ec2.internal/
> 172.17.0.1:47500,
> /100.96.3.1:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=4, intOrder=4, lastExchangeTime=1554492872631,
> loc=false, ver=2.7.0#20181130-sha1:256ae401, isClient=false],
> connected=false, connectCnt=2, queueLimit=4096, reserveCnt=3,
> pairedConnections=false], outRecovery=GridNioRecoveryDescriptor
> [acked=765568, resendCnt=0, rcvCnt=685485, sentCnt=765592, reserved=true,
> lastAck=685472, nodeLeft=false, node=TcpDiscoveryNode
> [id=28d08f11-fc1c-4f90-a71a-c33e2440533e, addrs=[0:0:0:0:0:0:0:1%lo,
> 100.96.3.1, 127.0.0.1, 172.17.0.1, 172.25.39.84],
> sockAddrs=[/172.25.39.84:47500, ip-172-17-0-1.ec2.internal/
> 172.17.0.1:47500,
> /100.96.3.1:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500],
> discPort=47500, order=4, intOrder=4, lastExchangeTime=1554492872631,
> loc=false, ver=2.7.0#20181130-sha1:256ae401, isClient=false],
> connected=false, connectCnt=2, queueLimit=4096, reserveCnt=3,
> pairedConnections=false], super=GridNioSessionImpl
> [locAddr=/172.25.46.90:63166, rmtAddr=/172.25.39.84:47100,
> createTime=1554495300309, closeTime=0, bytesSent=453133874,
> bytesRcvd=367422231, bytesSent0=9389157, bytesRcvd0=13616308,
> sndSchedTime=1554495300309, lastSndTime=1554495397987,
> lastRcvTime=1554495397987, readsPaused=false,
> filterChain=FilterChain[filters=[GridNioCodecFilter
> [parser=o.a.i.i.util.nio.GridDirectParser@20f8f42e, directMode=true],
> GridConnectionBytesVerifyFilter], accepted=false, markedForClose=false]]]
>         java.io.IOException: Connection reset by peer
>                 at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
>                 at
> sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
>                 at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
>                 at sun.nio.ch.IOUtil.write(IOUtil.java:51)
>                 at
> sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
>                 at
>
> org.apache.ignite.internal.util.nio.GridNioServer$DirectNioClientWorker.processWrite0(GridNioServer.java:1674)
>                 at
>
> org.apache.ignite.internal.util.nio.GridNioServer$DirectNioClientWorker.processWrite(GridNioServer.java:1331)
>                 at
>
> org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.processSelectedKeysOptimized(GridNioServer.java:2392)
>                 at
>
> org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.bodyInternal(GridNioServer.java:2156)
>                 at
>
> org.apache.ignite.internal.util.nio.GridNioServer$AbstractNioClientWorker.body(GridNioServer.java:1797)
>                 at
> org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:120)
>                 at java.lang.Thread.run(Thread.java:748)
>
>
> These don't appear to be catchable errors, so I don't really know where
> they're originating from. My DataStreamers are continuing to load data and
> according to my metrics, which are based on results from the DataStreamer
> futures, the DataStreamers aren't dropping rows.
>
> My question is, what exactly is going on here? Is it possible that I'm
> losing data, and if not, is there some way to disable these messages, which
> tend to clog up my logs and make troubleshooting real errors difficult.
>
>
>
>
>
>
>
> --
> Sent from: http://apache-ignite-users.70518.x6.nabble.com/
>