From commits-return-6042-archive-asf-public=cust-asf.ponee.io@kudu.apache.org Wed Jun 13 18:59:53 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id 4798918066C for ; Wed, 13 Jun 2018 18:59:52 +0200 (CEST) Received: (qmail 27202 invoked by uid 500); 13 Jun 2018 16:59:50 -0000 Mailing-List: contact commits-help@kudu.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@kudu.apache.org Delivered-To: mailing list commits@kudu.apache.org Received: (qmail 27102 invoked by uid 99); 13 Jun 2018 16:59:50 -0000 Received: from git1-us-west.apache.org (HELO git1-us-west.apache.org) (140.211.11.23) by apache.org (qpsmtpd/0.29) with ESMTP; Wed, 13 Jun 2018 16:59:50 +0000 Received: by git1-us-west.apache.org (ASF Mail Server at git1-us-west.apache.org, from userid 33) id 2CABAE04BC; Wed, 13 Jun 2018 16:59:50 +0000 (UTC) Content-Type: text/plain; charset="us-ascii" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit From: mpercy@apache.org To: commits@kudu.apache.org Message-Id: X-Mailer: ASF-Git Admin Mailer Subject: kudu git commit: Log idle time when expiring tablet copy sessions Date: Wed, 13 Jun 2018 16:59:50 +0000 (UTC) Repository: kudu Updated Branches: refs/heads/master 930c7f40f -> 8bec7d35a Log idle time when expiring tablet copy sessions It would aid debugging to print the session idle time when logging that tablet copy sessions have expired and are being killed. Tested this by running TabletCopyServiceTest.TestSessionTimeout and observing the output in the logs, which looked like this: I0607 23:44:18.084945 31632 tablet_copy_service.cc:434] P 446ddba1bf9f43089120e9fa6810c5b5: tablet copy session 446ddba1bf9f43089120e9fa6810c5b5-TestTablet on tablet TestTablet with peer 446ddba1bf9f43089120e9fa6810c5b5 has expired after 4.007s of idle time I0607 23:44:18.085067 31632 tablet_copy_service.cc:413] P 446ddba1bf9f43089120e9fa6810c5b5: ending tablet copy session 446ddba1bf9f43089120e9fa6810c5b5-TestTablet on tablet TestTablet with peer 446ddba1bf9f43089120e9fa6810c5b5 Note that it expired after 4 seconds of idle time because I temporarily modified the test to expire after 4 seconds instead of 0 seconds, which is the value it normally uses to obtain a fast test run. Change-Id: I3dd37afbe6faeb29d05aafd799bc05ed2b2af4d6 Reviewed-on: http://gerrit.cloudera.org:8080/10652 Tested-by: Kudu Jenkins Reviewed-by: Will Berkeley Project: http://git-wip-us.apache.org/repos/asf/kudu/repo Commit: http://git-wip-us.apache.org/repos/asf/kudu/commit/8bec7d35 Tree: http://git-wip-us.apache.org/repos/asf/kudu/tree/8bec7d35 Diff: http://git-wip-us.apache.org/repos/asf/kudu/diff/8bec7d35 Branch: refs/heads/master Commit: 8bec7d35a5e9edd434914dc8a71049b67d15f0fc Parents: 930c7f4 Author: Mike Percy Authored: Thu Jun 7 14:48:41 2018 -0700 Committer: Mike Percy Committed: Wed Jun 13 16:59:31 2018 +0000 ---------------------------------------------------------------------- src/kudu/tserver/tablet_copy_service.cc | 36 +++++++++++++--------- src/kudu/tserver/tablet_copy_service.h | 5 ++- src/kudu/tserver/tablet_copy_source_session.h | 3 ++ 3 files changed, 28 insertions(+), 16 deletions(-) ---------------------------------------------------------------------- http://git-wip-us.apache.org/repos/asf/kudu/blob/8bec7d35/src/kudu/tserver/tablet_copy_service.cc ---------------------------------------------------------------------- diff --git a/src/kudu/tserver/tablet_copy_service.cc b/src/kudu/tserver/tablet_copy_service.cc index 4467a6b..3fb028c 100644 --- a/src/kudu/tserver/tablet_copy_service.cc +++ b/src/kudu/tserver/tablet_copy_service.cc @@ -98,10 +98,6 @@ using tablet::TabletReplica; namespace tserver { -static MonoTime GetNewExpireTime() { - return MonoTime::Now() + MonoDelta::FromSeconds(FLAGS_tablet_copy_idle_timeout_sec); -} - TabletCopyServiceImpl::TabletCopyServiceImpl( ServerBase* server, TabletReplicaLookupIf* tablet_replica_lookup) @@ -117,6 +113,12 @@ TabletCopyServiceImpl::TabletCopyServiceImpl( &session_expiration_thread_)); } +TabletCopyServiceImpl::SessionEntry::SessionEntry(scoped_refptr session_in) + : session(std::move(session_in)), + last_accessed_time(MonoTime::Now()), + expire_timeout(MonoDelta::FromSeconds(FLAGS_tablet_copy_idle_timeout_sec)) { +} + bool TabletCopyServiceImpl::AuthorizeServiceUser(const google::protobuf::Message* /*req*/, google::protobuf::Message* /*resp*/, rpc::RpcContext* rpc) { @@ -158,7 +160,7 @@ void TabletCopyServiceImpl::BeginTabletCopySession( session.reset(new TabletCopySourceSession(tablet_replica, session_id, requestor_uuid, fs_manager_, &tablet_copy_metrics_)); - InsertOrDie(&sessions_, session_id, { session, GetNewExpireTime() }); + InsertOrDie(&sessions_, session_id, SessionEntry(session)); } else { session = session_entry->session; LOG_WITH_PREFIX(INFO) << Substitute( @@ -397,7 +399,7 @@ Status TabletCopyServiceImpl::ValidateFetchRequestDataId( void TabletCopyServiceImpl::ResetSessionExpirationUnlocked(const std::string& session_id) { SessionEntry* session_entry = FindOrNull(sessions_, session_id); if (!session_entry) return; - session_entry->expires = GetNewExpireTime(); + session_entry->last_accessed_time = MonoTime::Now(); } Status TabletCopyServiceImpl::DoEndTabletCopySessionUnlocked( @@ -408,7 +410,7 @@ Status TabletCopyServiceImpl::DoEndTabletCopySessionUnlocked( RETURN_NOT_OK(FindSessionUnlocked(session_id, app_error, &session)); // Remove the session from the map. // It will get destroyed once there are no outstanding refs. - LOG_WITH_PREFIX(INFO) << "Ending tablet copy session " << session_id << " on tablet " + LOG_WITH_PREFIX(INFO) << "ending tablet copy session " << session_id << " on tablet " << session->tablet_id() << " with peer " << session->requestor_uuid(); CHECK_EQ(1, sessions_.erase(session_id)); return Status::OK(); @@ -419,19 +421,23 @@ void TabletCopyServiceImpl::EndExpiredSessions() { MutexLock l(sessions_lock_); const MonoTime now = MonoTime::Now(); - vector expired_session_ids; + vector expired_session_entries; for (const auto& entry : sessions_) { - const string& session_id = entry.first; - const MonoTime& expiration = entry.second.expires; + const MonoTime& expiration = entry.second.last_accessed_time + entry.second.expire_timeout; if (expiration < now) { - expired_session_ids.push_back(session_id); + expired_session_entries.push_back(entry.second); } } - for (const string& session_id : expired_session_ids) { - LOG_WITH_PREFIX(INFO) << "Tablet Copy session " << session_id - << " has expired. Terminating session."; + for (const auto& session_entry : expired_session_entries) { + auto idle_time = MonoTime::Now() - session_entry.last_accessed_time; + auto& session = session_entry.session; + LOG_WITH_PREFIX(INFO) << "tablet copy session " << session->session_id() + << " on tablet " << session->tablet_id() + << " with peer " << session->requestor_uuid() + << " has expired after " << idle_time.ToString() + << " of idle time"; TabletCopyErrorPB::Code app_error; - CHECK_OK(DoEndTabletCopySessionUnlocked(session_id, &app_error)); + CHECK_OK(DoEndTabletCopySessionUnlocked(session->session_id(), &app_error)); } } while (!shutdown_latch_.WaitFor(MonoDelta::FromMilliseconds( FLAGS_tablet_copy_timeout_poll_period_ms))); http://git-wip-us.apache.org/repos/asf/kudu/blob/8bec7d35/src/kudu/tserver/tablet_copy_service.h ---------------------------------------------------------------------- diff --git a/src/kudu/tserver/tablet_copy_service.h b/src/kudu/tserver/tablet_copy_service.h index a119083..19ac07a 100644 --- a/src/kudu/tserver/tablet_copy_service.h +++ b/src/kudu/tserver/tablet_copy_service.h @@ -83,8 +83,11 @@ class TabletCopyServiceImpl : public TabletCopyServiceIf { private: struct SessionEntry { + explicit SessionEntry(scoped_refptr session_in); + scoped_refptr session; - MonoTime expires; + MonoTime last_accessed_time; // Time this session was last accessed. + MonoDelta expire_timeout; }; typedef std::unordered_map SessionMap; http://git-wip-us.apache.org/repos/asf/kudu/blob/8bec7d35/src/kudu/tserver/tablet_copy_source_session.h ---------------------------------------------------------------------- diff --git a/src/kudu/tserver/tablet_copy_source_session.h b/src/kudu/tserver/tablet_copy_source_session.h index 3795d3f..af15c45 100644 --- a/src/kudu/tserver/tablet_copy_source_session.h +++ b/src/kudu/tserver/tablet_copy_source_session.h @@ -117,6 +117,9 @@ class TabletCopySourceSession : public RefCountedThreadSafe