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 <c17825@cray.com>
Change-Id: I44962d2b3675b77e09182bbe062bdd78d6cb0af5
Cray-bug-id: LUS-5736
Signed-off-by: Oleg Drokin <green@whamcloud.com>
Reviewed-on: https://review.whamcloud.com/34131
Tested-by: Jenkins
Tested-by: Maloo <maloo@whamcloud.com>

diff --git a/lustre/include/lustre_dlm.h b/lustre/include/lustre_dlm.h
index 7d84ff0..3eed422 100644 (file)
--- 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 (file)
--- 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 (file)
--- 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 (file)
--- 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) {