From patchwork Thu Feb 27 21:08:33 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: James Simmons X-Patchwork-Id: 11409715 Return-Path: Received: from mail.kernel.org (pdx-korg-mail-1.web.codeaurora.org [172.30.200.123]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 428F214BC for ; Thu, 27 Feb 2020 21:20:01 +0000 (UTC) Received: from pdx1-mailman02.dreamhost.com (pdx1-mailman02.dreamhost.com [64.90.62.194]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by mail.kernel.org (Postfix) with ESMTPS id 2B0B4246A1 for ; Thu, 27 Feb 2020 21:20:01 +0000 (UTC) DMARC-Filter: OpenDMARC Filter v1.3.2 mail.kernel.org 2B0B4246A1 Authentication-Results: mail.kernel.org; dmarc=none (p=none dis=none) header.from=infradead.org Authentication-Results: mail.kernel.org; spf=none smtp.mailfrom=lustre-devel-bounces@lists.lustre.org Received: from pdx1-mailman02.dreamhost.com (localhost [IPv6:::1]) by pdx1-mailman02.dreamhost.com (Postfix) with ESMTP id 002CE21FCFD; Thu, 27 Feb 2020 13:19:31 -0800 (PST) X-Original-To: lustre-devel@lists.lustre.org Delivered-To: lustre-devel-lustre.org@pdx1-mailman02.dreamhost.com Received: from smtp3.ccs.ornl.gov (smtp3.ccs.ornl.gov [160.91.203.39]) by pdx1-mailman02.dreamhost.com (Postfix) with ESMTP id D447121FA61 for ; Thu, 27 Feb 2020 13:18:28 -0800 (PST) Received: from star.ccs.ornl.gov (star.ccs.ornl.gov [160.91.202.134]) by smtp3.ccs.ornl.gov (Postfix) with ESMTP id B244EE01; Thu, 27 Feb 2020 16:18:13 -0500 (EST) Received: by star.ccs.ornl.gov (Postfix, from userid 2004) id B0D4F46C; Thu, 27 Feb 2020 16:18:13 -0500 (EST) From: James Simmons To: Andreas Dilger , Oleg Drokin , NeilBrown Date: Thu, 27 Feb 2020 16:08:33 -0500 Message-Id: <1582838290-17243-46-git-send-email-jsimmons@infradead.org> X-Mailer: git-send-email 1.8.3.1 In-Reply-To: <1582838290-17243-1-git-send-email-jsimmons@infradead.org> References: <1582838290-17243-1-git-send-email-jsimmons@infradead.org> Subject: [lustre-devel] [PATCH 045/622] lustre: ldlm: fix l_last_activity usage X-BeenThere: lustre-devel@lists.lustre.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: "For discussing Lustre software development." List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Cc: Alexander Boyko , Lustre Development List MIME-Version: 1.0 Errors-To: lustre-devel-bounces@lists.lustre.org Sender: "lustre-devel" From: Alexander Boyko When race happen between ldlm_server_blocking_ast() and ldlm_request_cancel(), the at_measured() is called with wrong value equal to current time. And even worse, ldlm_bl_timeout() can return current_time*1.5. Before a time functions was fixed by LU-9019(fdeeed2fb) for 64bit, this race leads to ETIMEDOUT at ptlrpc_import_delay_req() and client eviction during bl ast sending. The wrong type conversion take a place at pltrpc_send_limit_expired() at cfs_time_seconds(). We should not take cancels into accoount if the BLAST is not send, just because the last_activity is not properly initialised - it destroys the AT completely. The patch devides l_last_activity to the client l_activity and server l_blast_sent for better understanding. The l_blast_sent is used for blocking ast only to measure time between BLAST and cancel request. For example: server cancels blocked lock after 1518731697s waiting_locks_callback()) ### lock callback timer expired after 0s: evicting client WC-bug-id: https://jira.whamcloud.com/browse/LU-10945 Lustre-commit: e09d273cb5f2 ("LU-10945 ldlm: fix l_last_activity usage") Signed-off-by: Alexander Boyko Cray-bug-id: LUS-5736 Reviewed-on: https://review.whamcloud.com/32133 Reviewed-by: Andreas Dilger Reviewed-by: Vitaly Fertman Reviewed-by: James Simmons Reviewed-by: Mikhal Pershin Reviewed-by: Oleg Drokin Signed-off-by: James Simmons --- fs/lustre/include/lustre_dlm.h | 13 +++++++------ fs/lustre/ldlm/ldlm_lock.c | 1 + fs/lustre/ldlm/ldlm_request.c | 14 +++++++------- 3 files changed, 15 insertions(+), 13 deletions(-) diff --git a/fs/lustre/include/lustre_dlm.h b/fs/lustre/include/lustre_dlm.h index 1a19b35..6ad12a3 100644 --- a/fs/lustre/include/lustre_dlm.h +++ b/fs/lustre/include/lustre_dlm.h @@ -708,12 +708,6 @@ struct ldlm_lock { wait_queue_head_t l_waitq; /** - * Seconds. It will be updated if there is any activity related to - * the lock, e.g. enqueue the lock or send blocking AST. - */ - time64_t l_last_activity; - - /** * Time, in nanoseconds, last used by e.g. being matched by lock match. */ ktime_t l_last_used; @@ -735,6 +729,13 @@ struct ldlm_lock { /** Private storage for lock user. Opaque to LDLM. */ void *l_ast_data; + + /** + * Seconds. It will be updated if there is any activity related to + * the lock at client, e.g. enqueue the lock. + */ + time64_t l_activity; + /* Separate ost_lvb used mostly by Data-on-MDT for now. * It is introduced to don't mix with layout lock data. */ diff --git a/fs/lustre/ldlm/ldlm_lock.c b/fs/lustre/ldlm/ldlm_lock.c index 894b99b..1bf387a 100644 --- a/fs/lustre/ldlm/ldlm_lock.c +++ b/fs/lustre/ldlm/ldlm_lock.c @@ -420,6 +420,7 @@ static struct ldlm_lock *ldlm_lock_new(struct ldlm_resource *resource) lu_ref_init(&lock->l_reference); lu_ref_add(&lock->l_reference, "hash", lock); lock->l_callback_timeout = 0; + lock->l_activity = 0; #if LUSTRE_TRACKS_LOCK_EXP_REFS INIT_LIST_HEAD(&lock->l_exp_refs_link); diff --git a/fs/lustre/ldlm/ldlm_request.c b/fs/lustre/ldlm/ldlm_request.c index 3991a8f..67c23fc 100644 --- a/fs/lustre/ldlm/ldlm_request.c +++ b/fs/lustre/ldlm/ldlm_request.c @@ -114,9 +114,9 @@ static void ldlm_expired_completion_wait(struct ldlm_lock *lock, u32 conn_cnt) LDLM_ERROR(lock, "lock timed out (enqueued at %lld, %llds ago); not entering recovery in server code, just going back to sleep", - (s64)lock->l_last_activity, + (s64)lock->l_activity, (s64)(ktime_get_real_seconds() - - lock->l_last_activity)); + lock->l_activity)); if (ktime_get_seconds() > next_dump) { last_dump = next_dump; next_dump = ktime_get_seconds() + 300; @@ -133,8 +133,8 @@ static void ldlm_expired_completion_wait(struct ldlm_lock *lock, u32 conn_cnt) ptlrpc_fail_import(imp, conn_cnt); LDLM_ERROR(lock, "lock timed out (enqueued at %lld, %llds ago), entering recovery for %s@%s", - (s64)lock->l_last_activity, - (s64)(ktime_get_real_seconds() - lock->l_last_activity), + (s64)lock->l_activity, + (s64)(ktime_get_real_seconds() - lock->l_activity), obd2cli_tgt(obd), imp->imp_connection->c_remote_uuid.uuid); } @@ -182,7 +182,7 @@ static int ldlm_completion_tail(struct ldlm_lock *lock, void *data) LDLM_DEBUG(lock, "client-side enqueue: granted"); } else { /* Take into AT only CP RPC, not immediately granted locks */ - delay = ktime_get_real_seconds() - lock->l_last_activity; + delay = ktime_get_real_seconds() - lock->l_activity; LDLM_DEBUG(lock, "client-side enqueue: granted after %lds", delay); @@ -245,7 +245,7 @@ int ldlm_completion_ast(struct ldlm_lock *lock, u64 flags, void *data) timeout = ldlm_cp_timeout(lock); - lock->l_last_activity = ktime_get_real_seconds(); + lock->l_activity = ktime_get_real_seconds(); if (imp) { spin_lock(&imp->imp_lock); @@ -725,7 +725,7 @@ int ldlm_cli_enqueue(struct obd_export *exp, struct ptlrpc_request **reqp, lock->l_export = NULL; lock->l_blocking_ast = einfo->ei_cb_bl; lock->l_flags |= (*flags & (LDLM_FL_NO_LRU | LDLM_FL_EXCL)); - lock->l_last_activity = ktime_get_real_seconds(); + lock->l_activity = ktime_get_real_seconds(); /* lock not sent to server yet */ if (!reqp || !*reqp) {