Mostafa Mokhtar created IMPALA-6432:
---
Summary: Default rpc_negotiation_timeout_ms may cause queries to
fail on large clusters
Key: IMPALA-6432
URL: https://issues.apache.org/jira/browse/IMPALA-6432
Project: IMPALA
Issue Type: Sub-task
Components: Distributed Exec
Affects Versions: Impala 2.11.0
Reporter: Mostafa Mokhtar
While running the stress test on a 140 node secure cluster with "default"
configs queries were failing with negotiation timeouts.
With rpc_negotiation_timeout_ms=6 queries appear to run fine, ideally we
should understand why this takes very long and bump the default to a more
reasonable value.
{code}
W0121 16:51:04.014796 156630 negotiation.cc:302] Failed RPC negotiation. Trace:
0121 16:51:00.254978 (+ 0us) reactor.cc:481] Submitting negotiation task for
server connection from 10.17.221.35:38297
0121 16:51:03.194696 (+2939718us) server_negotiation.cc:169] Beginning
negotiation
0121 16:51:03.194697 (+ 1us) server_negotiation.cc:358] Waiting for connection
header
0121 16:51:03.194708 (+ 11us) server_negotiation.cc:366] Connection header
received
0121 16:51:03.194720 (+ 12us) server_negotiation.cc:322] Received NEGOTIATE
NegotiatePB request
0121 16:51:03.194721 (+ 1us) server_negotiation.cc:407] Received NEGOTIATE
request from client
0121 16:51:03.194725 (+ 4us) server_negotiation.cc:334] Sending NEGOTIATE
NegotiatePB response
0121 16:51:03.194761 (+ 36us) server_negotiation.cc:190] Negotiated authn=SASL
0121 16:51:03.206182 (+ 11421us) server_negotiation.cc:322] Received
SASL_INITIATE NegotiatePB request
0121 16:51:03.206183 (+ 1us) server_negotiation.cc:754] Received SASL_INITIATE
request from client
0121 16:51:03.206184 (+ 1us) server_negotiation.cc:765] Client requested to use
mechanism: GSSAPI
0121 16:51:03.206190 (+ 6us) server_negotiation.cc:794] Calling
sasl_server_start()
0121 16:51:03.990155 (+783965us) server_negotiation.cc:334] Sending
SASL_CHALLENGE NegotiatePB response
0121 16:51:04.014736 (+ 24581us) negotiation.cc:293] Negotiation complete:
Timed out: Server connection negotiation failed: server connection from
10.17.221.35:38297: BlockingWrite timed out
Metrics: \{"server-negotiator.queue_time_us":2939697}
W0121 16:51:04.014961 156629 negotiation.cc:302] Failed RPC negotiation. Trace:
0121 16:51:00.512560 (+ 0us) reactor.cc:481] Submitting negotiation task for
server connection from 10.17.232.27:38602
0121 16:51:03.50 (+2989662us) server_negotiation.cc:169] Beginning
negotiation
0121 16:51:03.502223 (+ 1us) server_negotiation.cc:358] Waiting for connection
header
0121 16:51:03.502231 (+ 8us) server_negotiation.cc:366] Connection header
received
0121 16:51:03.502242 (+ 11us) server_negotiation.cc:322] Received NEGOTIATE
NegotiatePB request
0121 16:51:03.502243 (+ 1us) server_negotiation.cc:407] Received NEGOTIATE
request from client
0121 16:51:03.502247 (+ 4us) server_negotiation.cc:334] Sending NEGOTIATE
NegotiatePB response
0121 16:51:03.502272 (+ 25us) server_negotiation.cc:190] Negotiated authn=SASL
0121 16:51:03.506579 (+ 4307us) server_negotiation.cc:322] Received
SASL_INITIATE NegotiatePB request
0121 16:51:03.506581 (+ 2us) server_negotiation.cc:754] Received SASL_INITIATE
request from client
0121 16:51:03.506581 (+ 0us) server_negotiation.cc:765] Client requested to use
mechanism: GSSAPI
0121 16:51:03.506588 (+ 7us) server_negotiation.cc:794] Calling
sasl_server_start()
0121 16:51:04.003539 (+496951us) server_negotiation.cc:334] Sending
SASL_CHALLENGE NegotiatePB response
0121 16:51:04.014903 (+ 11364us) negotiation.cc:293] Negotiation complete:
Timed out: Server connection negotiation failed: server connection from
10.17.232.27:38602: BlockingWrite timed out
Metrics: \{"server-negotiator.queue_time_us":2989644}
W0121 16:51:04.026866 156629 negotiation.cc:302] Failed RPC negotiation. Trace:
0121 16:51:00.796311 (+ 0us) reactor.cc:481] Submitting negotiation task for
server connection from 10.17.232.48:52481
0121 16:51:04.026814 (+3230503us) server_negotiation.cc:169] Beginning
negotiation
0121 16:51:04.026815 (+ 1us) server_negotiation.cc:358] Waiting for connection
header
0121 16:51:04.026839 (+ 24us) negotiation.cc:293] Negotiation complete: Timed
out: Server connection negotiation failed: server connection from
10.17.232.48:52481
Metrics: \{"server-negotiator.queue_time_us":3230488}
W0121 16:51:04.027504 156632 negotiation.cc:302] Failed RPC negotiation. Trace:
0121 16:51:00.807588 (+ 0us) reactor.cc:481] Submitting negotiation task for
server connection from 10.17.232.43:55531
0121 16:51:04.027449 (+3219861us) server_negotiation.cc:169] Beginning
negotiation
0121 16:51:04.027450 (+ 1us) server_negotiation.cc:358] Waiting for connection
header
0121 16:51:04.027481 (+ 31us) negotiation.cc:293] Negotiation complete: Timed
out: Server connection negotiation failed: server connecti