locks: dump client pid and time of blocking/granting.

Change-Id: Icaa919f3009fb70f6af9b95fceaf800f3beca447
BUG: 3662
Reviewed-on: http://review.gluster.com/532
Tested-by: Gluster Build System <jenkins@build.gluster.com>
Reviewed-by: Vijay Bellur <vijay@gluster.com>

6 files changed, 65 insertions, 19 deletions

diff --git a/xlators/features/locks/src/common.c b/xlators/features/locks/src/common.c
index 4e089a0ee36..4b6a810fde8 100644
--- a/xlators/features/locks/src/common.c
+++ b/xlators/features/locks/src/common.c
@@ -533,6 +533,11 @@ posix_lock_to_flock (posix_lock_t *lock, struct gf_flock *flock)
 static void
 __insert_lock (pl_inode_t *pl_inode, posix_lock_t *lock)
 {
+        if (lock->blocked)
+                gettimeofday (&lock->blkd_time, NULL);
+        else
+                gettimeofday (&lock->granted_time, NULL);
+
         list_add_tail (&lock->list, &pl_inode->ext_list);
 
         return;
diff --git a/xlators/features/locks/src/common.h b/xlators/features/locks/src/common.h
index dddcd339ba7..d95e287cb94 100644
--- a/xlators/features/locks/src/common.h
+++ b/xlators/features/locks/src/common.h
@@ -20,6 +20,7 @@
 #ifndef __COMMON_H__
 #define __COMMON_H__
 
+#define SET_FLOCK_PID(flock, lock) ((flock)->l_pid = lock->client_pid)
 posix_lock_t *
 new_posix_lock (struct gf_flock *flock, void *transport, pid_t client_pid,
                 uint64_t owner, fd_t *fd);
diff --git a/xlators/features/locks/src/entrylk.c b/xlators/features/locks/src/entrylk.c
index c3f40829b57..886a30b0ef2 100644
--- a/xlators/features/locks/src/entrylk.c
+++ b/xlators/features/locks/src/entrylk.c
@@ -349,6 +349,7 @@ __lock_name (pl_inode_t *pinode, const char *basename, entrylk_type type,
 
                 }
 
+                gettimeofday (&lock->blkd_time, NULL);
                 list_add_tail (&lock->blocked_locks, &dom->blocked_entrylks);
 
                 gf_log (this->name, GF_LOG_TRACE,
@@ -370,6 +371,7 @@ __lock_name (pl_inode_t *pinode, const char *basename, entrylk_type type,
                 lock->frame     = frame;
                 lock->this      = this;
 
+                gettimeofday (&lock->blkd_time, NULL);
                 list_add_tail (&lock->blocked_locks, &dom->blocked_entrylks);
 
                 gf_log (this->name, GF_LOG_TRACE,
@@ -384,6 +386,7 @@ __lock_name (pl_inode_t *pinode, const char *basename, entrylk_type type,
         switch (type) {
 
         case ENTRYLK_WRLCK:
+                gettimeofday (&lock->granted_time, NULL);
                 list_add_tail (&lock->domain_list, &dom->entrylk_list);
                 break;
 
diff --git a/xlators/features/locks/src/inodelk.c b/xlators/features/locks/src/inodelk.c
index aa2b2855d93..94ecfc265ad 100644
--- a/xlators/features/locks/src/inodelk.c
+++ b/xlators/features/locks/src/inodelk.c
@@ -208,6 +208,7 @@ __lock_inodelk (xlator_t *this, pl_inode_t *pl_inode, pl_inode_lock_t *lock,
                 if (can_block == 0)
                         goto out;
 
+                gettimeofday (&lock->blkd_time, NULL);
                 list_add_tail (&lock->blocked_locks, &dom->blocked_inodelks);
 
                 gf_log (this->name, GF_LOG_TRACE,
@@ -227,6 +228,7 @@ __lock_inodelk (xlator_t *this, pl_inode_t *pl_inode, pl_inode_lock_t *lock,
                 if (can_block == 0)
                         goto out;
 
+                gettimeofday (&lock->blkd_time, NULL);
                 list_add_tail (&lock->blocked_locks, &dom->blocked_inodelks);
 
                 gf_log (this->name, GF_LOG_TRACE,
@@ -242,6 +244,7 @@ __lock_inodelk (xlator_t *this, pl_inode_t *pl_inode, pl_inode_lock_t *lock,
 
                 goto out;
         }
+        gettimeofday (&lock->granted_time, NULL);
         list_add (&lock->list, &dom->inodelk_list);
 
         ret = 0;
diff --git a/xlators/features/locks/src/locks.h b/xlators/features/locks/src/locks.h
index ab70064a9d9..476b9a83cd6 100644
--- a/xlators/features/locks/src/locks.h
+++ b/xlators/features/locks/src/locks.h
@@ -48,6 +48,9 @@ struct __posix_lock {
         fd_t              *fd;
         call_frame_t      *frame;
 
+        struct timeval     blkd_time;   /*time at which lock was queued into blkd list*/
+        struct timeval     granted_time; /*time at which lock was queued into active list*/
+
         /* These two together serve to uniquely identify each process
            across nodes */
 
@@ -73,6 +76,9 @@ struct __pl_inode_lock {
 
         call_frame_t      *frame;
 
+        struct timeval     blkd_time;   /*time at which lock was queued into blkd list*/
+        struct timeval     granted_time; /*time at which lock was queued into active list*/
+
         /* These two together serve to uniquely identify each process
            across nodes */
 
@@ -111,6 +117,9 @@ struct __entry_lock {
         const char       *basename;
         entrylk_type      type;
 
+        struct timeval     blkd_time;   /*time at which lock was queued into blkd list*/
+        struct timeval     granted_time; /*time at which lock was queued into active list*/
+
         void      *trans;
         pid_t             client_pid;    /* pid of client process */
         uint64_t          owner;
diff --git a/xlators/features/locks/src/posix.c b/xlators/features/locks/src/posix.c
index 20f6cdd66d9..62bdf812dee 100644
--- a/xlators/features/locks/src/posix.c
+++ b/xlators/features/locks/src/posix.c
@@ -1504,7 +1504,8 @@ out:
 
 void
 pl_dump_lock (char *str, int size, struct gf_flock *flock,
-              uint64_t owner, void *trans)
+              uint64_t owner, void *trans, time_t *granted_time,
+              time_t *blkd_time, gf_boolean_t active)
 {
         char *type_str = NULL;
 
@@ -1523,13 +1524,22 @@ pl_dump_lock (char *str, int size, struct gf_flock *flock,
                 break;
         }
 
-        snprintf (str, size, "type=%s, start=%llu, len=%llu, pid=%llu, lk-owner=%llu, transport=%p",
-                  type_str, (unsigned long long) flock->l_start,
-                  (unsigned long long) flock->l_len,
-                  (unsigned long long) flock->l_pid,
-                  (unsigned long long) owner,
-                  trans);
-
+        if (active)
+                snprintf (str, size, "type=%s, start=%llu, len=%llu, pid=%llu, lk-owner=%llu, transport=%p, "
+                          "blocked at %s, granted at  %s",
+                          type_str, (unsigned long long) flock->l_start,
+                          (unsigned long long) flock->l_len,
+                          (unsigned long long) flock->l_pid,
+                          (unsigned long long) owner,
+                          trans, ctime (blkd_time), ctime (granted_time));
+        else
+                snprintf (str, size, "type=%s, start=%llu, len=%llu, pid=%llu, lk-owner=%llu, transport=%p, "
+                          "blocked at  %s",
+                          type_str, (unsigned long long) flock->l_start,
+                          (unsigned long long) flock->l_len,
+                          (unsigned long long) flock->l_pid,
+                          (unsigned long long) owner,
+                          trans, ctime (blkd_time));
 
 }
 
@@ -1556,12 +1566,15 @@ __dump_entrylks (pl_inode_t *pl_inode)
 
                         gf_proc_dump_build_key(key,
                                                "xlator.feature.locks.lock-dump.domain.entrylk",
-                                               "entrylk[%d](ACTIVE)",count );
-                        snprintf (tmp, 256," %s on %s owner=%llu, transport=%p",
+                                               "entrylk[%d](ACTIVE)", count );
+                        snprintf (tmp, 256," %s on %s pid = %llu, owner=%llu, transport=%p,"
+                                  " blocked at %s, granted at %s",
                                   lock->type == ENTRYLK_RDLCK ? "ENTRYLK_RDLCK" :
                                   "ENTRYLK_WRLCK", lock->basename,
-                                  (unsigned long long) lock->owner,
-                                  lock->trans);
+                                  (unsigned long long) lock->client_pid,
+                                  (unsigned long long) lock->owner, lock->trans,
+                                  ctime (&lock->blkd_time.tv_sec),
+                                  ctime (&lock->granted_time.tv_sec));
 
                         gf_proc_dump_write(key, tmp);
 
@@ -1572,12 +1585,14 @@ __dump_entrylks (pl_inode_t *pl_inode)
 
                         gf_proc_dump_build_key(key,
                                                "xlator.feature.locks.lock-dump.domain.entrylk",
-                                               "entrylk[%d](BLOCKED)",count );
-                        snprintf (tmp, 256," %s on %s owner=%llu, transport=%p,"
-                                  " state = Blocked",
+                                               "entrylk[%d](BLOCKED)", count );
+                        snprintf (tmp, 256," %s on %s pid = %llu, owner=%llu, transport=%p,"
+                                  " blocked at %s",
                                   lock->type == ENTRYLK_RDLCK ? "ENTRYLK_RDLCK" :
                                   "ENTRYLK_WRLCK", lock->basename,
-                                  (unsigned long long) lock->owner, lock->trans);
+                                  (unsigned long long) lock->client_pid,
+                                  (unsigned long long) lock->owner, lock->trans,
+                                  ctime (&lock->blkd_time.tv_sec));
 
                         gf_proc_dump_write(key, tmp);
 
@@ -1624,8 +1639,12 @@ __dump_inodelks (pl_inode_t *pl_inode)
                                                "xlator.feature.locks.lock-dump.domain.inodelk",
                                                "inodelk[%d](ACTIVE)",count );
 
+                        SET_FLOCK_PID (&lock->user_flock, lock);
                         pl_dump_lock (tmp, 256, &lock->user_flock,
-                                      lock->owner, lock->transport);
+                                      lock->owner, lock->transport,
+                                      &lock->granted_time.tv_sec,
+                                      &lock->blkd_time.tv_sec,
+                                      _gf_true);
                         gf_proc_dump_write(key, tmp);
 
                         count++;
@@ -1636,8 +1655,11 @@ __dump_inodelks (pl_inode_t *pl_inode)
                         gf_proc_dump_build_key(key,
                                                "xlator.feature.locks.lock-dump.domain.inodelk",
                                                "inodelk[%d](BLOCKED)",count );
+                        SET_FLOCK_PID (&lock->user_flock, lock);
                         pl_dump_lock (tmp, 256, &lock->user_flock,
-                                      lock->owner, lock->transport);
+                                      lock->owner, lock->transport,
+                                      0, &lock->blkd_time.tv_sec,
+                                      _gf_false);
                         gf_proc_dump_write(key, tmp);
 
                         count++;
@@ -1669,13 +1691,16 @@ __dump_posixlks (pl_inode_t *pl_inode)
 
       list_for_each_entry (lock, &pl_inode->ext_list, list) {
 
+              SET_FLOCK_PID (&lock->user_flock, lock);
               gf_proc_dump_build_key(key,
                                      "xlator.feature.locks.lock-dump.domain.posixlk",
                                      "posixlk[%d](%s)",
                                      count,
                                      lock->blocked ? "BLOCKED" : "ACTIVE");
               pl_dump_lock (tmp, 256, &lock->user_flock,
-                            lock->owner, lock->transport);
+                            lock->owner, lock->transport,
+                            &lock->granted_time.tv_sec, &lock->blkd_time.tv_sec,
+                            (lock->blocked)? _gf_false: _gf_true);
               gf_proc_dump_write(key, tmp);
 
               count++;