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 <kwho@cloudera.com>
Tested-by: Impala Public Jenkins <impala-public-jenkins@cloudera.com>
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 @@
// 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 @@
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 @@
&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 @@
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,
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::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 @@
}
// 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 @@
}
}
- 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;
+ {
+ // 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;
- 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));
+ 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;
}
}
