[IMPALA-8027] KRPC datastream timing out on both the receiver and sender side even in a minicluster

• Type: Bug
• Status: Resolved
• Priority: Critical
• Resolution: Duplicate
• Affects Version/s: Impala 3.2.0
• Component/s: Distributed Exec
• Labels: broken-build
• Epic Color: ghx-label-1
• Assignee: Michael Ho
• Reporter: Bikramjeet Vig
• Created: 29/Dec/18 00:48
• Updated: 27/Feb/19 04:20
• Resolved: 27/Feb/19 04:18

Description

krpc datastreams seem to time out at the same time at both sender and receiver causing two running queries to fail. This happened while running core tests on s3.

Logs from coordinator:

I1228 05:18:56.202587 13396 krpc-data-stream-mgr.cc:353] Sender 127.0.0.1 timed out waiting for receiver fragment instance: 8f46b2518734bef1:6ef2d40400000000, dest node: 2
I1228 05:18:56.203061 13396 rpcz_store.cc:265] Call impala.DataStreamService.TransmitData from 127.0.0.1:53118 (request call id 11274) took 120782ms. Request Metrics: {}
I1228 05:18:56.203114 13396 krpc-data-stream-mgr.cc:353] Sender 127.0.0.1 timed out waiting for receiver fragment instance: 194f5b70907ac97c:84a116d600000000, dest node: 2
I1228 05:18:56.203136 13396 rpcz_store.cc:265] Call impala.DataStreamService.TransmitData from 127.0.0.1:53110 (request call id 8637) took 123811ms. Request Metrics: {}
I1228 05:18:56.203155 13396 krpc-data-stream-mgr.cc:353] Sender 127.0.0.1 timed out waiting for receiver fragment instance: 194f5b70907ac97c:84a116d600000000, dest node: 2
I1228 05:18:56.203167 13396 rpcz_store.cc:265] Call impala.DataStreamService.TransmitData from 127.0.0.1:53118 (request call id 11273) took 123776ms. Request Metrics: {}
I1228 05:18:56.203181 13396 krpc-data-stream-mgr.cc:408] Reduced stream ID cache from 413 items, to 410, eviction took: 1ms
I1228 05:18:56.204746 13377 coordinator.cc:707] Backend completed: host=impala-ec2-centos74-m5-4xlarge-ondemand-07b3.vpc.cloudera.com:22001 remaining=2 query_id=8f46b2518734bef1:6ef2d40400000000
I1228 05:18:56.204756 13377 coordinator-backend-state.cc:262] query_id=8f46b2518734bef1:6ef2d40400000000: first in-progress backend: impala-ec2-centos74-m5-4xlarge-ondemand-07b3.vpc.cloudera.com:22000
I1228 05:18:56.204769 13377 coordinator.cc:522] ExecState: query id=8f46b2518734bef1:6ef2d40400000000 finstance=8f46b2518734bef1:6ef2d40400000001 on host=impala-ec2-centos74-m5-4xlarge-ondemand-07b3.vpc.cloudera.com:22001 (EXECUTING -> ERROR) status=Sender 127.0.0.1 timed out waiting for receiver fragment instance: 8f46b2518734bef1:6ef2d40400000000, dest node: 2

Logs from executor:

E1228 05:18:56.203181 26715 krpc-data-stream-sender.cc:343] channel send to 127.0.0.1:27000 failed: (fragment_instance_id=8f46b2518734bef1:6ef2d40400000000): Sender 127.0.0.1 timed out waiting for receiver fragment instance: 8f46b2518734bef1:6ef2d40400000000, dest node: 2
E1228 05:18:56.203256 26682 krpc-data-stream-sender.cc:343] channel send to 127.0.0.1:27000 failed: (fragment_instance_id=194f5b70907ac97c:84a116d600000000): Sender 127.0.0.1 timed out waiting for receiver fragment instance: 194f5b70907ac97c:84a116d600000000, dest node: 2
I1228 05:18:56.203451 26715 query-state.cc:576] Instance completed. instance_id=8f46b2518734bef1:6ef2d40400000001 #in-flight=3 status=DATASTREAM_SENDER_TIMEOUT: Sender 127.0.0.1 timed out waiting for receiver fragment instance: 8f46b2518734bef1:6ef2d40400000000, dest node: 2
I1228 05:18:56.203485 26713 query-state.cc:249] UpdateBackendExecState(): last report for 8f46b2518734bef1:6ef2d40400000000
I1228 05:18:56.203514 26682 query-state.cc:576] Instance completed. instance_id=194f5b70907ac97c:84a116d600000003 #in-flight=2 status=DATASTREAM_SENDER_TIMEOUT: Sender 127.0.0.1 timed out waiting for receiver fragment instance: 194f5b70907ac97c:84a116d600000000, dest node: 2
I1228 05:18:56.203536 26680 query-state.cc:249] UpdateBackendExecState(): last report for 194f5b70907ac97c:84a116d600000000

Issue Links

• is duplicated by: IMPALA-6818 Rethink data-stream sender/receiver startup sequencing