You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@impala.apache.org by jo...@apache.org on 2018/08/18 20:38:21 UTC
[2/7] impala git commit: IMPALA-7444: Improve logging of
opening/closing/expiring sessions.
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 <kw...@cloudera.com>
Tested-by: Impala Public Jenkins <im...@cloudera.com>
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 <zo...@cloudera.com>
Authored: Tue Aug 14 22:41:23 2018 -0700
Committer: Impala Public Jenkins <im...@cloudera.com>
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;
}
}