Whamcloud - gitweb
LU-12631 llite: report latency for filesystem ops
[fs/lustre-release.git] / lustre / llite / file.c
index a4da041..3db09e1 100644 (file)
@@ -374,19 +374,19 @@ out:
  */
 int ll_file_release(struct inode *inode, struct file *file)
 {
-        struct ll_file_data *fd;
-        struct ll_sb_info *sbi = ll_i2sbi(inode);
-        struct ll_inode_info *lli = ll_i2info(inode);
-        int rc;
-        ENTRY;
+       struct ll_file_data *fd;
+       struct ll_sb_info *sbi = ll_i2sbi(inode);
+       struct ll_inode_info *lli = ll_i2info(inode);
+       ktime_t kstart = ktime_get();
+       int rc;
+
+       ENTRY;
 
        CDEBUG(D_VFSTRACE, "VFS Op:inode="DFID"(%p)\n",
               PFID(ll_inode2fid(inode)), inode);
 
-       if (inode->i_sb->s_root != file_dentry(file))
-                ll_stats_ops_tally(sbi, LPROC_LL_RELEASE, 1);
-        fd = LUSTRE_FPRIVATE(file);
-        LASSERT(fd != NULL);
+       fd = LUSTRE_FPRIVATE(file);
+       LASSERT(fd != NULL);
 
        /* The last ref on @file, maybe not the the owner pid of statahead,
         * because parent and child process can share the same file handle. */
@@ -396,7 +396,7 @@ int ll_file_release(struct inode *inode, struct file *file)
        if (inode->i_sb->s_root == file_dentry(file)) {
                LUSTRE_FPRIVATE(file) = NULL;
                ll_file_data_put(fd);
-               RETURN(0);
+               GOTO(out, rc = 0);
        }
 
        pcc_file_release(inode, file);
@@ -412,6 +412,10 @@ int ll_file_release(struct inode *inode, struct file *file)
        if (CFS_FAIL_TIMEOUT_MS(OBD_FAIL_PTLRPC_DUMP_LOG, cfs_fail_val))
                libcfs_debug_dumplog();
 
+out:
+       if (!rc && inode->i_sb->s_root != file_dentry(file))
+               ll_stats_ops_tally(sbi, LPROC_LL_RELEASE,
+                                  ktime_us_delta(ktime_get(), kstart));
        RETURN(rc);
 }
 
@@ -693,6 +697,7 @@ int ll_file_open(struct inode *inode, struct file *file)
        struct obd_client_handle **och_p = NULL;
        __u64 *och_usecount = NULL;
        struct ll_file_data *fd;
+       ktime_t kstart = ktime_get();
        int rc = 0;
        ENTRY;
 
@@ -876,9 +881,10 @@ out_openerr:
 
                if (fd != NULL)
                        ll_file_data_put(fd);
-        } else {
-                ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_OPEN, 1);
-        }
+       } else {
+               ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_OPEN,
+                                  ktime_us_delta(ktime_get(), kstart));
+       }
 
 out_nofiledata:
        if (it && it_disposition(it, DISP_ENQ_OPEN_REF)) {
@@ -886,7 +892,7 @@ out_nofiledata:
                it_clear_disposition(it, DISP_ENQ_OPEN_REF);
        }
 
-        return rc;
+       return rc;
 }
 
 static int ll_md_blocking_lease_ast(struct ldlm_lock *lock,
@@ -1648,7 +1654,7 @@ ll_do_fast_read(struct kiocb *iocb, struct iov_iter *iter)
        if (result > 0) {
                ll_heat_add(file_inode(iocb->ki_filp), CIT_READ, result);
                ll_stats_ops_tally(ll_i2sbi(file_inode(iocb->ki_filp)),
-                               LPROC_LL_READ_BYTES, result);
+                                  LPROC_LL_READ_BYTES, result);
        }
 
        return result;
@@ -1665,6 +1671,7 @@ static ssize_t ll_file_read_iter(struct kiocb *iocb, struct iov_iter *to)
        ssize_t result;
        ssize_t rc2;
        __u16 refcheck;
+       ktime_t kstart = ktime_get();
        bool cached;
 
        if (!iov_iter_count(to))
@@ -1683,7 +1690,7 @@ static ssize_t ll_file_read_iter(struct kiocb *iocb, struct iov_iter *to)
         */
        result = pcc_file_read_iter(iocb, to, &cached);
        if (cached)
-               return result;
+               GOTO(out, result);
 
        ll_ras_enter(file);
 
@@ -1708,10 +1715,13 @@ static ssize_t ll_file_read_iter(struct kiocb *iocb, struct iov_iter *to)
 
        cl_env_put(env, &refcheck);
 out:
-       if (result > 0)
+       if (result > 0) {
                ll_rw_stats_tally(ll_i2sbi(file_inode(file)), current->pid,
                                  LUSTRE_FPRIVATE(file), iocb->ki_pos, result,
                                  READ);
+               ll_stats_ops_tally(ll_i2sbi(file_inode(file)), LPROC_LL_READ,
+                                  ktime_us_delta(ktime_get(), kstart));
+       }
 
        return result;
 }
@@ -1786,6 +1796,7 @@ static ssize_t ll_file_write_iter(struct kiocb *iocb, struct iov_iter *from)
        struct file *file = iocb->ki_filp;
        __u16 refcheck;
        bool cached;
+       ktime_t kstart = ktime_get();
        int result;
 
        ENTRY;
@@ -1805,7 +1816,7 @@ static ssize_t ll_file_write_iter(struct kiocb *iocb, struct iov_iter *from)
         */
        result = pcc_file_write_iter(iocb, from, &cached);
        if (cached && result != -ENOSPC && result != -EDQUOT)
-               return result;
+               GOTO(out, rc_normal = result);
 
        /* NB: we can't do direct IO for tiny writes because they use the page
         * cache, we can't do sync writes because tiny writes can't flush
@@ -1844,10 +1855,14 @@ static ssize_t ll_file_write_iter(struct kiocb *iocb, struct iov_iter *from)
 
        cl_env_put(env, &refcheck);
 out:
-       if (rc_normal > 0)
+       if (rc_normal > 0) {
                ll_rw_stats_tally(ll_i2sbi(file_inode(file)), current->pid,
                                  LUSTRE_FPRIVATE(file), iocb->ki_pos,
                                  rc_normal, WRITE);
+               ll_stats_ops_tally(ll_i2sbi(file_inode(file)), LPROC_LL_WRITE,
+                                  ktime_us_delta(ktime_get(), kstart));
+       }
+
        RETURN(rc_normal);
 }
 
@@ -4029,6 +4044,7 @@ static loff_t ll_file_seek(struct file *file, loff_t offset, int origin)
 {
        struct inode *inode = file_inode(file);
        loff_t retval, eof = 0;
+       ktime_t kstart = ktime_get();
 
        ENTRY;
        retval = offset + ((origin == SEEK_END) ? i_size_read(inode) :
@@ -4036,7 +4052,6 @@ static loff_t ll_file_seek(struct file *file, loff_t offset, int origin)
        CDEBUG(D_VFSTRACE, "VFS Op:inode="DFID"(%p), to=%llu=%#llx(%d)\n",
               PFID(ll_inode2fid(inode)), inode, retval, retval,
               origin);
-       ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_LLSEEK, 1);
 
        if (origin == SEEK_END || origin == SEEK_HOLE || origin == SEEK_DATA) {
                retval = ll_glimpse_size(inode);
@@ -4046,7 +4061,10 @@ static loff_t ll_file_seek(struct file *file, loff_t offset, int origin)
        }
 
        retval = ll_generic_file_llseek_size(file, offset, origin,
-                                         ll_file_maxbytes(inode), eof);
+                                            ll_file_maxbytes(inode), eof);
+       if (retval >= 0)
+               ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_LLSEEK,
+                                  ktime_us_delta(ktime_get(), kstart));
        RETURN(retval);
 }
 
@@ -4136,6 +4154,7 @@ int ll_fsync(struct file *file, loff_t start, loff_t end, int datasync)
        struct inode *inode = dentry->d_inode;
        struct ll_inode_info *lli = ll_i2info(inode);
        struct ptlrpc_request *req;
+       ktime_t kstart = ktime_get();
        int rc, err;
 
        ENTRY;
@@ -4144,8 +4163,6 @@ int ll_fsync(struct file *file, loff_t start, loff_t end, int datasync)
               "datasync %d\n",
               PFID(ll_inode2fid(inode)), inode, start, end, datasync);
 
-       ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_FSYNC, 1);
-
        /* fsync's caller has already called _fdata{sync,write}, we want
         * that IO to finish before calling the osc and mdc sync methods */
        rc = filemap_write_and_wait_range(inode->i_mapping, start, end);
@@ -4191,6 +4208,10 @@ int ll_fsync(struct file *file, loff_t start, loff_t end, int datasync)
        }
 
        inode_unlock(inode);
+
+       if (!rc)
+               ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_FSYNC,
+                                  ktime_us_delta(ktime_get(), kstart));
        RETURN(rc);
 }
 
@@ -4208,6 +4229,7 @@ ll_file_flock(struct file *file, int cmd, struct file_lock *file_lock)
        struct lustre_handle lockh = { 0 };
        union ldlm_policy_data flock = { { 0 } };
        int fl_type = file_lock->fl_type;
+       ktime_t kstart = ktime_get();
        __u64 flags = 0;
        int rc;
        int rc2 = 0;
@@ -4216,22 +4238,20 @@ ll_file_flock(struct file *file, int cmd, struct file_lock *file_lock)
        CDEBUG(D_VFSTRACE, "VFS Op:inode="DFID" file_lock=%p\n",
               PFID(ll_inode2fid(inode)), file_lock);
 
-        ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_FLOCK, 1);
-
-        if (file_lock->fl_flags & FL_FLOCK) {
-                LASSERT((cmd == F_SETLKW) || (cmd == F_SETLK));
-                /* flocks are whole-file locks */
-                flock.l_flock.end = OFFSET_MAX;
-                /* For flocks owner is determined by the local file desctiptor*/
-                flock.l_flock.owner = (unsigned long)file_lock->fl_file;
-        } else if (file_lock->fl_flags & FL_POSIX) {
-                flock.l_flock.owner = (unsigned long)file_lock->fl_owner;
-                flock.l_flock.start = file_lock->fl_start;
-                flock.l_flock.end = file_lock->fl_end;
-        } else {
-                RETURN(-EINVAL);
-        }
-        flock.l_flock.pid = file_lock->fl_pid;
+       if (file_lock->fl_flags & FL_FLOCK) {
+               LASSERT((cmd == F_SETLKW) || (cmd == F_SETLK));
+               /* flocks are whole-file locks */
+               flock.l_flock.end = OFFSET_MAX;
+               /* For flocks owner is determined by the local file desctiptor*/
+               flock.l_flock.owner = (unsigned long)file_lock->fl_file;
+       } else if (file_lock->fl_flags & FL_POSIX) {
+               flock.l_flock.owner = (unsigned long)file_lock->fl_owner;
+               flock.l_flock.start = file_lock->fl_start;
+               flock.l_flock.end = file_lock->fl_end;
+       } else {
+               RETURN(-EINVAL);
+       }
+       flock.l_flock.pid = file_lock->fl_pid;
 
 #if defined(HAVE_LM_COMPARE_OWNER) || defined(lm_compare_owner)
        /* Somewhat ugly workaround for svc lockd.
@@ -4336,7 +4356,10 @@ ll_file_flock(struct file *file, int cmd, struct file_lock *file_lock)
 
        ll_finish_md_op_data(op_data);
 
-        RETURN(rc);
+       if (!rc)
+               ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_FLOCK,
+                                  ktime_us_delta(ktime_get(), kstart));
+       RETURN(rc);
 }
 
 int ll_get_fid_by_name(struct inode *parent, const char *name,
@@ -4722,10 +4745,9 @@ int ll_getattr_dentry(struct dentry *de, struct kstat *stat)
        struct inode *inode = de->d_inode;
        struct ll_sb_info *sbi = ll_i2sbi(inode);
        struct ll_inode_info *lli = ll_i2info(inode);
+       ktime_t kstart = ktime_get();
        int rc;
 
-       ll_stats_ops_tally(sbi, LPROC_LL_GETATTR, 1);
-
        rc = ll_inode_revalidate(de, IT_GETATTR);
        if (rc < 0)
                RETURN(rc);
@@ -4786,7 +4808,10 @@ int ll_getattr_dentry(struct dentry *de, struct kstat *stat)
        stat->size = i_size_read(inode);
        stat->blocks = inode->i_blocks;
 
-        return 0;
+       ll_stats_ops_tally(sbi, LPROC_LL_GETATTR,
+                          ktime_us_delta(ktime_get(), kstart));
+
+       return 0;
 }
 
 #ifdef HAVE_INODEOPS_ENHANCED_GETATTR
@@ -4922,6 +4947,7 @@ int ll_inode_permission(struct inode *inode, int mask)
        const struct cred *old_cred = NULL;
        cfs_cap_t cap;
        bool squash_id = false;
+       ktime_t kstart = ktime_get();
        ENTRY;
 
        if (mask & MAY_NOT_BLOCK)
@@ -4967,7 +4993,6 @@ int ll_inode_permission(struct inode *inode, int mask)
                old_cred = override_creds(cred);
        }
 
-       ll_stats_ops_tally(sbi, LPROC_LL_INODE_PERM, 1);
        rc = generic_permission(inode, mask);
        /* restore current process's credentials and FS capability */
        if (squash_id) {
@@ -4975,6 +5000,10 @@ int ll_inode_permission(struct inode *inode, int mask)
                put_cred(cred);
        }
 
+       if (!rc)
+               ll_stats_ops_tally(sbi, LPROC_LL_INODE_PERM,
+                                  ktime_us_delta(ktime_get(), kstart));
+
        RETURN(rc);
 }