IMPALA-7444: Improve logging of opening/closing/expiring sessions. Recent troubleshooting efforts have shown we can improve logging of client session opening and expiry processing to enhance serviceability.
This patch adds minor, but useful debug log improvements. Change-Id: Iecf2d3ce707cc36c21da8a2459c2f68cf0b56a4a Reviewed-on: http://gerrit.cloudera.org:8080/11234 Reviewed-by: Michael Ho <[email protected]> Tested-by: Impala Public Jenkins <[email protected]> Project: http://git-wip-us.apache.org/repos/asf/impala/repo Commit: http://git-wip-us.apache.org/repos/asf/impala/commit/1158883e Tree: http://git-wip-us.apache.org/repos/asf/impala/tree/1158883e Diff: http://git-wip-us.apache.org/repos/asf/impala/diff/1158883e Branch: refs/heads/master Commit: 1158883e859c38339800053a28dff5454f93ba5b Parents: 83bb4ae Author: Zoram Thanga <[email protected]> Authored: Tue Aug 14 22:41:23 2018 -0700 Committer: Impala Public Jenkins <[email protected]> Committed: Sat Aug 18 03:44:50 2018 +0000 ---------------------------------------------------------------------- be/src/service/impala-hs2-server.cc | 14 +++++-- be/src/service/impala-server.cc | 66 ++++++++++++++++++-------------- 2 files changed, 47 insertions(+), 33 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/impala/blob/1158883e/be/src/service/impala-hs2-server.cc ---------------------------------------------------------------------- diff --git a/be/src/service/impala-hs2-server.cc b/be/src/service/impala-hs2-server.cc index c49c65b..353c190 100644 --- a/be/src/service/impala-hs2-server.cc +++ b/be/src/service/impala-hs2-server.cc @@ -266,9 +266,6 @@ Status ImpalaServer::TExecuteStatementReqToTQueryContext( // HiveServer2 API void ImpalaServer::OpenSession(TOpenSessionResp& return_val, const TOpenSessionReq& request) { - // DO NOT log this Thrift struct in its entirety, in case a bad client sets the - // password. - VLOG_QUERY << "OpenSession(): username=" << request.username; // Generate session ID and the secret TUniqueId session_id; @@ -284,6 +281,12 @@ void ImpalaServer::OpenSession(TOpenSessionResp& return_val, return_val.__isset.sessionHandle = true; UUIDToTUniqueId(session_uuid, &session_id); } + + // DO NOT log this Thrift struct in its entirety, in case a bad client sets the + // password. + VLOG_QUERY << "Opening session: " << PrintId(session_id) << " username: " + << request.username; + // create a session state: initialize start time, session type, database and default // query options. // TODO: put secret in session state map and check it @@ -329,7 +332,8 @@ void ImpalaServer::OpenSession(TOpenSessionResp& return_val, &state->set_query_options_mask); if (status.ok() && iequals(v.first, "idle_session_timeout")) { state->session_timeout = state->set_query_options.idle_session_timeout; - VLOG_QUERY << "OpenSession(): idle_session_timeout=" + VLOG_QUERY << "OpenSession(): session: " << PrintId(session_id) + <<" idle_session_timeout=" << PrettyPrinter::Print(state->session_timeout, TUnit::TIME_S); } } @@ -360,6 +364,8 @@ void ImpalaServer::OpenSession(TOpenSessionResp& return_val, return_val.__isset.configuration = true; return_val.status.__set_statusCode(thrift::TStatusCode::SUCCESS_STATUS); return_val.serverProtocolVersion = state->hs2_version; + VLOG_QUERY << "Opened session: " << PrintId(session_id) << " username: " + << request.username; } void ImpalaServer::CloseSession(TCloseSessionResp& return_val, http://git-wip-us.apache.org/repos/asf/impala/blob/1158883e/be/src/service/impala-server.cc ---------------------------------------------------------------------- diff --git a/be/src/service/impala-server.cc b/be/src/service/impala-server.cc index cc8465f..23a09f5 100644 --- a/be/src/service/impala-server.cc +++ b/be/src/service/impala-server.cc @@ -1191,6 +1191,8 @@ Status ImpalaServer::CancelInternal(const TUniqueId& query_id, bool check_inflig Status ImpalaServer::CloseSessionInternal(const TUniqueId& session_id, bool ignore_if_absent) { + VLOG_QUERY << "Closing session: " << PrintId(session_id); + // Find the session_state and remove it from the map. shared_ptr<SessionState> session_state; { @@ -1231,6 +1233,7 @@ Status ImpalaServer::CloseSessionInternal(const TUniqueId& session_id, } // Reconfigure the poll period of session_timeout_thread_ if necessary. UnregisterSessionTimeout(session_state->session_timeout); + VLOG_QUERY << "Closed session: " << PrintId(session_id); return Status::OK(); } @@ -1932,39 +1935,44 @@ void ImpalaServer::UnregisterSessionTimeout(int32_t session_timeout) { } } - lock_guard<mutex> map_lock(session_state_map_lock_); int64_t now = UnixMillis(); + int expired_cnt = 0; VLOG(3) << "Session expiration thread waking up"; - // TODO: If holding session_state_map_lock_ for the duration of this loop is too - // expensive, consider a priority queue. - for (SessionStateMap::value_type& session_state: session_state_map_) { - unordered_set<TUniqueId> inflight_queries; - { - lock_guard<mutex> state_lock(session_state.second->lock); - if (session_state.second->ref_count > 0) continue; - // A session closed by other means is in the process of being removed, and it's - // best not to interfere. - if (session_state.second->closed || session_state.second->expired) continue; - if (session_state.second->session_timeout == 0) continue; - - int64_t last_accessed_ms = session_state.second->last_accessed_ms; - int64_t session_timeout_ms = session_state.second->session_timeout * 1000; - if (now - last_accessed_ms <= session_timeout_ms) continue; - LOG(INFO) << "Expiring session: " << PrintId(session_state.first) << ", user:" - << session_state.second->connected_user << ", last active: " - << ToStringFromUnixMillis(last_accessed_ms); - session_state.second->expired = true; - ImpaladMetrics::NUM_SESSIONS_EXPIRED->Increment(1L); - // Since expired is true, no more queries will be added to the inflight list. - inflight_queries.insert(session_state.second->inflight_queries.begin(), - session_state.second->inflight_queries.end()); - } - // Unregister all open queries from this session. - Status status = Status::Expected("Session expired due to inactivity"); - for (const TUniqueId& query_id: inflight_queries) { - cancellation_thread_pool_->Offer(CancellationWork(query_id, status, true)); + { + // TODO: If holding session_state_map_lock_ for the duration of this loop is too + // expensive, consider a priority queue. + lock_guard<mutex> map_lock(session_state_map_lock_); + for (SessionStateMap::value_type& session_state: session_state_map_) { + unordered_set<TUniqueId> inflight_queries; + { + lock_guard<mutex> state_lock(session_state.second->lock); + if (session_state.second->ref_count > 0) continue; + // A session closed by other means is in the process of being removed, and it's + // best not to interfere. + if (session_state.second->closed || session_state.second->expired) continue; + if (session_state.second->session_timeout == 0) continue; + + int64_t last_accessed_ms = session_state.second->last_accessed_ms; + int64_t session_timeout_ms = session_state.second->session_timeout * 1000; + if (now - last_accessed_ms <= session_timeout_ms) continue; + LOG(INFO) << "Expiring session: " << PrintId(session_state.first) << ", user: " + << session_state.second->connected_user << ", last active: " + << ToStringFromUnixMillis(last_accessed_ms); + session_state.second->expired = true; + ++expired_cnt; + ImpaladMetrics::NUM_SESSIONS_EXPIRED->Increment(1L); + // Since expired is true, no more queries will be added to the inflight list. + inflight_queries.insert(session_state.second->inflight_queries.begin(), + session_state.second->inflight_queries.end()); + } + // Unregister all open queries from this session. + Status status = Status::Expected("Session expired due to inactivity"); + for (const TUniqueId& query_id: inflight_queries) { + cancellation_thread_pool_->Offer(CancellationWork(query_id, status, true)); + } } } + LOG_IF(INFO, expired_cnt > 0) << "Expired sessions. Count: " << expired_cnt; } }
