From 20722fbd3d4fd5e83773332753069e8bec0d2b15 Mon Sep 17 00:00:00 2001 From: Oleg Drokin Date: Tue, 29 Jan 2019 12:45:48 -0500 Subject: [PATCH] LU-10945 ldlm: fix l_last_activity usage 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(e920be681) 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 Signed-off-by: Alexander Boyko Change-Id: I44962d2b3675b77e09182bbe062bdd78d6cb0af5 Cray-bug-id: LUS-5736 Signed-off-by: Oleg Drokin Reviewed-on: https://review.whamcloud.com/34131 Tested-by: Jenkins Tested-by: Maloo --- lustre/include/lustre_dlm.h | 16 ++++++++++------ lustre/ldlm/ldlm_lock.c | 1 + lustre/ldlm/ldlm_lockd.c | 15 +++++---------- lustre/ldlm/ldlm_request.c | 14 +++++++------- 4 files changed, 23 insertions(+), 23 deletions(-) diff --git a/lustre/include/lustre_dlm.h b/lustre/include/lustre_dlm.h index 7d84ff0..3eed422 100644 --- a/lustre/include/lustre_dlm.h +++ b/lustre/include/lustre_dlm.h @@ -816,12 +816,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; @@ -845,6 +839,16 @@ struct ldlm_lock { /** Private storage for lock user. Opaque to LDLM. */ void *l_ast_data; + union { + /** + * Seconds. It will be updated if there is any activity related to + * the lock at client, e.g. enqueue the lock. For server it is the + * time when blocking ast was sent. + */ + time64_t l_activity; + time64_t l_blast_sent; + }; + /* * Server-side-only members. */ diff --git a/lustre/ldlm/ldlm_lock.c b/lustre/ldlm/ldlm_lock.c index 33b0fd1..df28b2d 100644 --- a/lustre/ldlm/ldlm_lock.c +++ b/lustre/ldlm/ldlm_lock.c @@ -483,6 +483,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/lustre/ldlm/ldlm_lockd.c b/lustre/ldlm/ldlm_lockd.c index 260b9a0..0f5f747 100644 --- a/lustre/ldlm/ldlm_lockd.c +++ b/lustre/ldlm/ldlm_lockd.c @@ -329,7 +329,7 @@ static void waiting_locks_callback(unsigned long unused) ldlm_lock_to_ns(lock)->ns_timeouts++; LDLM_ERROR(lock, "lock callback timer expired after %llds: " "evicting client at %s ", - ktime_get_real_seconds() - lock->l_last_activity, + ktime_get_real_seconds() - lock->l_blast_sent, libcfs_nid2str( lock->l_export->exp_connection->c_peer.nid)); @@ -459,7 +459,7 @@ static int ldlm_add_waiting_lock(struct ldlm_lock *lock) } ldlm_set_waited(lock); - lock->l_last_activity = ktime_get_real_seconds(); + lock->l_blast_sent = ktime_get_real_seconds(); ret = __ldlm_add_waiting_lock(lock, timeout); if (ret) { /* grab ref on the lock if it has been added to the @@ -939,8 +939,6 @@ int ldlm_server_blocking_ast(struct ldlm_lock *lock, if (AT_OFF) req->rq_timeout = ldlm_get_rq_timeout(); - lock->l_last_activity = ktime_get_real_seconds(); - if (lock->l_export && lock->l_export->exp_nid_stats && lock->l_export->exp_nid_stats->nid_ldlm_stats) lprocfs_counter_incr(lock->l_export->exp_nid_stats->nid_ldlm_stats, @@ -1029,8 +1027,6 @@ int ldlm_server_completion_ast(struct ldlm_lock *lock, __u64 flags, void *data) } } - lock->l_last_activity = ktime_get_real_seconds(); - LDLM_DEBUG(lock, "server preparing completion AST"); ptlrpc_request_set_replen(req); @@ -1139,8 +1135,6 @@ int ldlm_server_glimpse_ast(struct ldlm_lock *lock, void *data) if (AT_OFF) req->rq_timeout = ldlm_get_rq_timeout(); - lock->l_last_activity = ktime_get_real_seconds(); - req->rq_interpret_reply = ldlm_cb_interpret; if (lock->l_export && lock->l_export->exp_nid_stats && @@ -1697,9 +1691,10 @@ int ldlm_request_cancel(struct ptlrpc_request *req, pres = res; } - if ((flags & LATF_STATS) && ldlm_is_ast_sent(lock)) { + if ((flags & LATF_STATS) && ldlm_is_ast_sent(lock) && + lock->l_blast_sent != 0) { time64_t delay = ktime_get_real_seconds() - - lock->l_last_activity; + lock->l_blast_sent; LDLM_DEBUG(lock, "server cancels blocked lock after %llds", (s64)delay); at_measured(&lock->l_export->exp_bl_lock_at, delay); diff --git a/lustre/ldlm/ldlm_request.c b/lustre/ldlm/ldlm_request.c index 8e7ecfc..8394478 100644 --- a/lustre/ldlm/ldlm_request.c +++ b/lustre/ldlm/ldlm_request.c @@ -125,9 +125,9 @@ int ldlm_expired_completion_wait(void *data) 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 (cfs_time_after(cfs_time_current(), next_dump)) { last_dump = next_dump; next_dump = cfs_time_shift(300); @@ -143,8 +143,8 @@ int ldlm_expired_completion_wait(void *data) imp = obd->u.cli.cl_import; ptlrpc_fail_import(imp, lwd->lwd_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); RETURN(0); @@ -192,7 +192,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 %llds", (s64)delay); @@ -285,7 +285,7 @@ noreproc: timeout = ldlm_cp_timeout(lock); lwd.lwd_lock = lock; - lock->l_last_activity = cfs_time_current_sec(); + lock->l_activity = cfs_time_current_sec(); if (ldlm_is_no_timeout(lock)) { LDLM_DEBUG(lock, "waiting indefinitely because of NO_TIMEOUT"); @@ -948,7 +948,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 = cfs_time_current_sec(); + lock->l_activity = cfs_time_current_sec(); /* lock not sent to server yet */ if (reqp == NULL || *reqp == NULL) { -- 1.8.3.1