Whamcloud - gitweb
LU-12631 llite: report latency for filesystem ops 78/36078/12
authorAndreas Dilger <adilger@whamcloud.com>
Fri, 6 Sep 2019 07:50:44 +0000 (01:50 -0600)
committerOleg Drokin <green@whamcloud.com>
Tue, 12 Nov 2019 04:06:29 +0000 (04:06 +0000)
Add the elapsed time of VFS operations to the llite stats
counter, instead of just tracking the number of operations,
to allow tracking of operation round-trip latency.

Update sanity test_127[ab] to check that llite.*.stats and
osc.*.stats counter shows read/write stats in usec, and
fix code style nearby.

Signed-off-by: Andreas Dilger <adilger@whamcloud.com>
Change-Id: I40e188374f91c030d978a83157d8869e928cab07
Reviewed-on: https://review.whamcloud.com/36078
Tested-by: jenkins <devops@whamcloud.com>
Tested-by: Maloo <maloo@whamcloud.com>
Reviewed-by: Li Xi <lixi@ddn.com>
Reviewed-by: Wang Shilong <wshilong@ddn.com>
Reviewed-by: Oleg Drokin <green@whamcloud.com>
12 files changed:
contrib/scripts/spelling.txt
lustre/include/lprocfs_status.h
lustre/llite/dir.c
lustre/llite/file.c
lustre/llite/llite_internal.h
lustre/llite/llite_lib.c
lustre/llite/llite_mmap.c
lustre/llite/lproc_llite.c
lustre/llite/namei.c
lustre/llite/super25.c
lustre/llite/xattr.c
lustre/tests/sanity.sh

index 96cf01d..470c62b 100644 (file)
@@ -132,7 +132,6 @@ LPLX||%#lx
 LPO64||%#llo
 LPPID||%d
 lprocfs_str_to_s64||kstrtoxxx_from_user
-LPROCFS||CONFIG_PROC_FS
 LPROC_SEQ_FOPS||LUSTRE_RW_ATTR
 LPROC_SEQ_FOPS_RO_TYPE||LUSTRE_RO_ATTR
 LPROC_SEQ_FOPS_RO||LUSTRE_RO_ATTR
index 2b66f7a..fd916d3 100644 (file)
@@ -144,15 +144,15 @@ struct rename_stats {
  */
 
 enum {
-        LPROCFS_CNTR_EXTERNALLOCK = 0x0001,
-        LPROCFS_CNTR_AVGMINMAX    = 0x0002,
-        LPROCFS_CNTR_STDDEV       = 0x0004,
-
-        /* counter data type */
-        LPROCFS_TYPE_REGS         = 0x0100,
-        LPROCFS_TYPE_BYTES        = 0x0200,
-        LPROCFS_TYPE_PAGES        = 0x0400,
-        LPROCFS_TYPE_CYCLE        = 0x0800,
+       LPROCFS_CNTR_EXTERNALLOCK       = 0x0001,
+       LPROCFS_CNTR_AVGMINMAX          = 0x0002,
+       LPROCFS_CNTR_STDDEV             = 0x0004,
+
+       /* counter data type */
+       LPROCFS_TYPE_REQS               = 0x0100,
+       LPROCFS_TYPE_BYTES              = 0x0200,
+       LPROCFS_TYPE_PAGES              = 0x0400,
+       LPROCFS_TYPE_USEC               = 0x0800,
 };
 
 #define LC_MIN_INIT ((~(__u64)0) >> 1)
index 7946691..ace18b5 100644 (file)
@@ -314,15 +314,16 @@ static int ll_iterate(struct file *filp, struct dir_context *ctx)
 static int ll_readdir(struct file *filp, void *cookie, filldir_t filldir)
 #endif
 {
-       struct inode            *inode  = file_inode(filp);
-       struct ll_file_data     *lfd    = LUSTRE_FPRIVATE(filp);
-       struct ll_sb_info       *sbi    = ll_i2sbi(inode);
-       int                     hash64  = sbi->ll_flags & LL_SBI_64BIT_HASH;
-       int                     api32   = ll_need_32bit_api(sbi);
-       struct md_op_data       *op_data;
-       struct lu_fid           pfid = { 0 };
-       __u64                   pos;
-       int                     rc;
+       struct inode *inode = file_inode(filp);
+       struct ll_file_data *lfd = LUSTRE_FPRIVATE(filp);
+       struct ll_sb_info *sbi = ll_i2sbi(inode);
+       int hash64 = sbi->ll_flags & LL_SBI_64BIT_HASH;
+       int api32 = ll_need_32bit_api(sbi);
+       struct md_op_data *op_data;
+       struct lu_fid pfid = { 0 };
+       ktime_t kstart = ktime_get();
+       __u64 pos;
+       int rc;
        ENTRY;
 
        if (lfd != NULL)
@@ -406,7 +407,8 @@ static int ll_readdir(struct file *filp, void *cookie, filldir_t filldir)
 
 out:
        if (!rc)
-               ll_stats_ops_tally(sbi, LPROC_LL_READDIR, 1);
+               ll_stats_ops_tally(sbi, LPROC_LL_READDIR,
+                                  ktime_us_delta(ktime_get(), kstart));
 
        RETURN(rc);
 }
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);
 }
 
index f27043c..480f21b 100644 (file)
@@ -796,15 +796,17 @@ void cl_put_grouplock(struct ll_grouplock *lg);
 /* llite/lproc_llite.c */
 int ll_debugfs_register_super(struct super_block *sb, const char *name);
 void ll_debugfs_unregister_super(struct super_block *sb);
-void ll_stats_ops_tally(struct ll_sb_info *sbi, int op, int count);
+void ll_stats_ops_tally(struct ll_sb_info *sbi, int op, long count);
 
 enum {
        LPROC_LL_READ_BYTES,
        LPROC_LL_WRITE_BYTES,
+       LPROC_LL_READ,
+       LPROC_LL_WRITE,
        LPROC_LL_IOCTL,
        LPROC_LL_OPEN,
        LPROC_LL_RELEASE,
-       LPROC_LL_MAP,
+       LPROC_LL_MMAP,
        LPROC_LL_FAULT,
        LPROC_LL_MKWRITE,
        LPROC_LL_LLSEEK,
@@ -823,7 +825,6 @@ enum {
        LPROC_LL_MKNOD,
        LPROC_LL_RENAME,
        LPROC_LL_STATFS,
-       LPROC_LL_ALLOC_INODE,
        LPROC_LL_SETXATTR,
        LPROC_LL_GETXATTR,
        LPROC_LL_GETXATTR_HITS,
index e84f5e5..22fa391 100644 (file)
@@ -1724,6 +1724,7 @@ int ll_setattr_raw(struct dentry *dentry, struct iattr *attr,
         struct inode *inode = dentry->d_inode;
         struct ll_inode_info *lli = ll_i2info(inode);
         struct md_op_data *op_data = NULL;
+       ktime_t kstart = ktime_get();
        int rc = 0;
 
        ENTRY;
@@ -1896,8 +1897,10 @@ out:
                inode_has_no_xattr(inode);
        }
 
-       ll_stats_ops_tally(ll_i2sbi(inode), (attr->ia_valid & ATTR_SIZE) ?
-                       LPROC_LL_TRUNC : LPROC_LL_SETATTR, 1);
+       if (!rc)
+               ll_stats_ops_tally(ll_i2sbi(inode), attr->ia_valid & ATTR_SIZE ?
+                                       LPROC_LL_TRUNC : LPROC_LL_SETATTR,
+                                  ktime_us_delta(ktime_get(), kstart));
 
        return rc;
 }
@@ -1985,15 +1988,16 @@ int ll_statfs_internal(struct ll_sb_info *sbi, struct obd_statfs *osfs,
 out:
        RETURN(rc);
 }
+
 int ll_statfs(struct dentry *de, struct kstatfs *sfs)
 {
        struct super_block *sb = de->d_sb;
        struct obd_statfs osfs;
        __u64 fsid = huge_encode_dev(sb->s_dev);
+       ktime_t kstart = ktime_get();
        int rc;
 
-       CDEBUG(D_VFSTRACE, "VFS Op: at %llu jiffies\n", get_jiffies_64());
-       ll_stats_ops_tally(ll_s2sbi(sb), LPROC_LL_STATFS, 1);
+       CDEBUG(D_VFSTRACE, "VFS Op:sb=%s (%p)\n", sb->s_id, sb);
 
        /* Some amount of caching on the client is allowed */
        rc = ll_statfs_internal(ll_s2sbi(sb), &osfs, OBD_STATFS_SUM);
@@ -2016,11 +2020,15 @@ int ll_statfs(struct dentry *de, struct kstatfs *sfs)
                 }
         }
 
-        sfs->f_blocks = osfs.os_blocks;
-        sfs->f_bfree = osfs.os_bfree;
-        sfs->f_bavail = osfs.os_bavail;
+       sfs->f_blocks = osfs.os_blocks;
+       sfs->f_bfree = osfs.os_bfree;
+       sfs->f_bavail = osfs.os_bavail;
        sfs->f_fsid.val[0] = (__u32)fsid;
        sfs->f_fsid.val[1] = (__u32)(fsid >> 32);
+
+       ll_stats_ops_tally(ll_s2sbi(sb), LPROC_LL_STATFS,
+                          ktime_us_delta(ktime_get(), kstart));
+
        return 0;
 }
 
index 14ed60d..ead6b39 100644 (file)
@@ -351,14 +351,12 @@ static vm_fault_t ll_fault(struct vm_area_struct *vma, struct vm_fault *vmf)
        bool printed = false;
        bool cached;
        vm_fault_t result;
+       ktime_t kstart = ktime_get();
        sigset_t set;
 
-       ll_stats_ops_tally(ll_i2sbi(file_inode(vma->vm_file)),
-                          LPROC_LL_FAULT, 1);
-
        result = pcc_fault(vma, vmf, &cached);
        if (cached)
-               return result;
+               goto out;
 
        /* Only SIGKILL and SIGTERM is allowed for fault/nopage/mkwrite
         * so that it can be killed by admin but not cause segfault by
@@ -395,12 +393,18 @@ restart:
         }
        cfs_restore_sigs(set);
 
-       if (vmf->page && result == VM_FAULT_LOCKED)
+out:
+       if (vmf->page && result == VM_FAULT_LOCKED) {
                ll_rw_stats_tally(ll_i2sbi(file_inode(vma->vm_file)),
                                  current->pid, LUSTRE_FPRIVATE(vma->vm_file),
                                  cl_offset(NULL, vmf->page->index), PAGE_SIZE,
                                  READ);
-        return result;
+               ll_stats_ops_tally(ll_i2sbi(file_inode(vma->vm_file)),
+                                  LPROC_LL_FAULT,
+                                  ktime_us_delta(ktime_get(), kstart));
+       }
+
+       return result;
 }
 
 #ifdef HAVE_VM_OPS_USE_VM_FAULT_ONLY
@@ -416,21 +420,19 @@ static vm_fault_t ll_page_mkwrite(struct vm_area_struct *vma,
        bool printed = false;
        bool retry;
        bool cached;
+       ktime_t kstart = ktime_get();
        vm_fault_t result;
 
-       ll_stats_ops_tally(ll_i2sbi(file_inode(vma->vm_file)),
-                          LPROC_LL_MKWRITE, 1);
-
        result = pcc_page_mkwrite(vma, vmf, &cached);
        if (cached)
-               return result;
+               goto out;
 
        file_update_time(vma->vm_file);
-        do {
-                retry = false;
-                result = ll_page_mkwrite0(vma, vmf->page, &retry);
+       do {
+               retry = false;
+               result = ll_page_mkwrite0(vma, vmf->page, &retry);
 
-                if (!printed && ++count > 16) {
+               if (!printed && ++count > 16) {
                        const struct dentry *de = file_dentry(vma->vm_file);
 
                        CWARN("app(%s): the page %lu of file "DFID" is under"
@@ -461,12 +463,18 @@ static vm_fault_t ll_page_mkwrite(struct vm_area_struct *vma,
                 break;
         }
 
-       if (result == VM_FAULT_LOCKED)
+out:
+       if (result == VM_FAULT_LOCKED) {
                ll_rw_stats_tally(ll_i2sbi(file_inode(vma->vm_file)),
                                  current->pid, LUSTRE_FPRIVATE(vma->vm_file),
                                  cl_offset(NULL, vmf->page->index), PAGE_SIZE,
                                  WRITE);
-        return result;
+               ll_stats_ops_tally(ll_i2sbi(file_inode(vma->vm_file)),
+                                  LPROC_LL_MKWRITE,
+                                  ktime_us_delta(ktime_get(), kstart));
+       }
+
+       return result;
 }
 
 /**
@@ -527,27 +535,31 @@ static const struct vm_operations_struct ll_file_vm_ops = {
 int ll_file_mmap(struct file *file, struct vm_area_struct * vma)
 {
        struct inode *inode = file_inode(file);
+       ktime_t kstart = ktime_get();
        bool cached;
-        int rc;
+       int rc;
 
-        ENTRY;
+       ENTRY;
 
-        if (ll_file_nolock(file))
-                RETURN(-EOPNOTSUPP);
+       if (ll_file_nolock(file))
+               RETURN(-EOPNOTSUPP);
 
        rc = pcc_file_mmap(file, vma, &cached);
        if (cached && rc != 0)
                RETURN(rc);
 
-        ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_MAP, 1);
-        rc = generic_file_mmap(file, vma);
-        if (rc == 0) {
+       rc = generic_file_mmap(file, vma);
+       if (rc == 0) {
                vma->vm_ops = &ll_file_vm_ops;
-                vma->vm_ops->open(vma);
-                /* update the inode's size and mtime */
+               vma->vm_ops->open(vma);
+               /* update the inode's size and mtime */
                if (!cached)
                        rc = ll_glimpse_size(inode);
-        }
+       }
 
-        RETURN(rc);
+       if (!rc)
+               ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_MMAP,
+                                  ktime_us_delta(ktime_get(), kstart));
+
+       RETURN(rc);
 }
index 6f26f49..081316e 100644 (file)
@@ -1538,62 +1538,66 @@ static struct kobj_type sbi_ktype = {
        .release        = sbi_kobj_release,
 };
 
+#define LPROCFS_TYPE_LATENCY \
+       (LPROCFS_TYPE_USEC | LPROCFS_CNTR_AVGMINMAX | LPROCFS_CNTR_STDDEV)
 static const struct llite_file_opcode {
-        __u32       opcode;
-        __u32       type;
-        const char *opname;
+       __u32           opcode;
+       __u32           type;
+       const char      *opname;
 } llite_opcode_table[LPROC_LL_FILE_OPCODES] = {
-        /* file operation */
-        { LPROC_LL_READ_BYTES,     LPROCFS_CNTR_AVGMINMAX|LPROCFS_TYPE_BYTES,
-                                   "read_bytes" },
-        { LPROC_LL_WRITE_BYTES,    LPROCFS_CNTR_AVGMINMAX|LPROCFS_TYPE_BYTES,
-                                   "write_bytes" },
-        { LPROC_LL_IOCTL,          LPROCFS_TYPE_REGS, "ioctl" },
-        { LPROC_LL_OPEN,           LPROCFS_TYPE_REGS, "open" },
-        { LPROC_LL_RELEASE,        LPROCFS_TYPE_REGS, "close" },
-        { LPROC_LL_MAP,            LPROCFS_TYPE_REGS, "mmap" },
-       { LPROC_LL_FAULT,          LPROCFS_TYPE_REGS, "page_fault" },
-       { LPROC_LL_MKWRITE,        LPROCFS_TYPE_REGS, "page_mkwrite" },
-        { LPROC_LL_LLSEEK,         LPROCFS_TYPE_REGS, "seek" },
-        { LPROC_LL_FSYNC,          LPROCFS_TYPE_REGS, "fsync" },
-        { LPROC_LL_READDIR,        LPROCFS_TYPE_REGS, "readdir" },
-        /* inode operation */
-        { LPROC_LL_SETATTR,        LPROCFS_TYPE_REGS, "setattr" },
-        { LPROC_LL_TRUNC,          LPROCFS_TYPE_REGS, "truncate" },
-        { LPROC_LL_FLOCK,          LPROCFS_TYPE_REGS, "flock" },
-        { LPROC_LL_GETATTR,        LPROCFS_TYPE_REGS, "getattr" },
-        /* dir inode operation */
-        { LPROC_LL_CREATE,         LPROCFS_TYPE_REGS, "create" },
-        { LPROC_LL_LINK,           LPROCFS_TYPE_REGS, "link" },
-        { LPROC_LL_UNLINK,         LPROCFS_TYPE_REGS, "unlink" },
-        { LPROC_LL_SYMLINK,        LPROCFS_TYPE_REGS, "symlink" },
-        { LPROC_LL_MKDIR,          LPROCFS_TYPE_REGS, "mkdir" },
-        { LPROC_LL_RMDIR,          LPROCFS_TYPE_REGS, "rmdir" },
-        { LPROC_LL_MKNOD,          LPROCFS_TYPE_REGS, "mknod" },
-        { LPROC_LL_RENAME,         LPROCFS_TYPE_REGS, "rename" },
+       /* file operation */
+       { LPROC_LL_READ_BYTES,  LPROCFS_CNTR_AVGMINMAX | LPROCFS_TYPE_BYTES,
+               "read_bytes" },
+       { LPROC_LL_WRITE_BYTES, LPROCFS_CNTR_AVGMINMAX | LPROCFS_TYPE_BYTES,
+               "write_bytes" },
+       { LPROC_LL_READ,        LPROCFS_TYPE_LATENCY,   "read" },
+       { LPROC_LL_WRITE,       LPROCFS_TYPE_LATENCY,   "write" },
+       { LPROC_LL_IOCTL,       LPROCFS_TYPE_REQS,      "ioctl" },
+       { LPROC_LL_OPEN,        LPROCFS_TYPE_LATENCY,   "open" },
+       { LPROC_LL_RELEASE,     LPROCFS_TYPE_LATENCY,   "close" },
+       { LPROC_LL_MMAP,        LPROCFS_TYPE_LATENCY,   "mmap" },
+       { LPROC_LL_FAULT,       LPROCFS_TYPE_LATENCY,   "page_fault" },
+       { LPROC_LL_MKWRITE,     LPROCFS_TYPE_LATENCY,   "page_mkwrite" },
+       { LPROC_LL_LLSEEK,      LPROCFS_TYPE_LATENCY,   "seek" },
+       { LPROC_LL_FSYNC,       LPROCFS_TYPE_LATENCY,   "fsync" },
+       { LPROC_LL_READDIR,     LPROCFS_TYPE_LATENCY,   "readdir" },
+       /* inode operation */
+       { LPROC_LL_SETATTR,     LPROCFS_TYPE_LATENCY,   "setattr" },
+       { LPROC_LL_TRUNC,       LPROCFS_TYPE_LATENCY,   "truncate" },
+       { LPROC_LL_FLOCK,       LPROCFS_TYPE_LATENCY,   "flock" },
+       { LPROC_LL_GETATTR,     LPROCFS_TYPE_LATENCY,   "getattr" },
+       /* dir inode operation */
+       { LPROC_LL_CREATE,      LPROCFS_TYPE_LATENCY,   "create" },
+       { LPROC_LL_LINK,        LPROCFS_TYPE_LATENCY,   "link" },
+       { LPROC_LL_UNLINK,      LPROCFS_TYPE_LATENCY,   "unlink" },
+       { LPROC_LL_SYMLINK,     LPROCFS_TYPE_LATENCY,   "symlink" },
+       { LPROC_LL_MKDIR,       LPROCFS_TYPE_LATENCY,   "mkdir" },
+       { LPROC_LL_RMDIR,       LPROCFS_TYPE_LATENCY,   "rmdir" },
+       { LPROC_LL_MKNOD,       LPROCFS_TYPE_LATENCY,   "mknod" },
+       { LPROC_LL_RENAME,      LPROCFS_TYPE_LATENCY,   "rename" },
        /* special inode operation */
-       { LPROC_LL_STATFS,          LPROCFS_TYPE_REGS, "statfs" },
-       { LPROC_LL_ALLOC_INODE,    LPROCFS_TYPE_REGS, "alloc_inode" },
-       { LPROC_LL_SETXATTR,       LPROCFS_TYPE_REGS, "setxattr" },
-       { LPROC_LL_GETXATTR,       LPROCFS_TYPE_REGS, "getxattr" },
-       { LPROC_LL_GETXATTR_HITS,  LPROCFS_TYPE_REGS, "getxattr_hits" },
-       { LPROC_LL_LISTXATTR,      LPROCFS_TYPE_REGS, "listxattr" },
-       { LPROC_LL_REMOVEXATTR,    LPROCFS_TYPE_REGS, "removexattr" },
-       { LPROC_LL_INODE_PERM,     LPROCFS_TYPE_REGS, "inode_permission" },
+       { LPROC_LL_STATFS,      LPROCFS_TYPE_LATENCY,   "statfs" },
+       { LPROC_LL_SETXATTR,    LPROCFS_TYPE_LATENCY,   "setxattr" },
+       { LPROC_LL_GETXATTR,    LPROCFS_TYPE_LATENCY,   "getxattr" },
+       { LPROC_LL_GETXATTR_HITS, LPROCFS_TYPE_REQS,    "getxattr_hits" },
+       { LPROC_LL_LISTXATTR,   LPROCFS_TYPE_LATENCY,   "listxattr" },
+       { LPROC_LL_REMOVEXATTR, LPROCFS_TYPE_LATENCY,   "removexattr" },
+       { LPROC_LL_INODE_PERM,  LPROCFS_TYPE_LATENCY,   "inode_permission" },
 };
 
-void ll_stats_ops_tally(struct ll_sb_info *sbi, int op, int count)
+void ll_stats_ops_tally(struct ll_sb_info *sbi, int op, long count)
 {
-        if (!sbi->ll_stats)
-                return;
-        if (sbi->ll_stats_track_type == STATS_TRACK_ALL)
-                lprocfs_counter_add(sbi->ll_stats, op, count);
-        else if (sbi->ll_stats_track_type == STATS_TRACK_PID &&
-                 sbi->ll_stats_track_id == current->pid)
-                lprocfs_counter_add(sbi->ll_stats, op, count);
-        else if (sbi->ll_stats_track_type == STATS_TRACK_PPID &&
-                 sbi->ll_stats_track_id == current->parent->pid)
-                lprocfs_counter_add(sbi->ll_stats, op, count);
+       if (!sbi->ll_stats)
+               return;
+
+       if (sbi->ll_stats_track_type == STATS_TRACK_ALL)
+               lprocfs_counter_add(sbi->ll_stats, op, count);
+       else if (sbi->ll_stats_track_type == STATS_TRACK_PID &&
+                sbi->ll_stats_track_id == current->pid)
+               lprocfs_counter_add(sbi->ll_stats, op, count);
+       else if (sbi->ll_stats_track_type == STATS_TRACK_PPID &&
+                sbi->ll_stats_track_id == current->parent->pid)
+               lprocfs_counter_add(sbi->ll_stats, op, count);
        else if (sbi->ll_stats_track_type == STATS_TRACK_GID &&
                 sbi->ll_stats_track_id ==
                        from_kgid(&init_user_ns, current_gid()))
@@ -1672,12 +1676,14 @@ int ll_debugfs_register_super(struct super_block *sb, const char *name)
                u32 type = llite_opcode_table[id].type;
                void *ptr = NULL;
 
-               if (type & LPROCFS_TYPE_REGS)
-                       ptr = "regs";
+               if (type & LPROCFS_TYPE_REQS)
+                       ptr = "reqs";
                else if (type & LPROCFS_TYPE_BYTES)
                        ptr = "bytes";
                else if (type & LPROCFS_TYPE_PAGES)
                        ptr = "pages";
+               else if (type & LPROCFS_TYPE_USEC)
+                       ptr = "usec";
                lprocfs_counter_init(sbi->ll_stats,
                                     llite_opcode_table[id].opcode,
                                     (type & LPROCFS_CNTR_AVGMINMAX),
index 3c4d375..7e46d5f 100644 (file)
@@ -1455,6 +1455,7 @@ static int ll_mknod(struct inode *dir, struct dentry *dchild, ll_umode_t mode,
                    dev_t rdev)
 {
        struct qstr *name = &dchild->d_name;
+       ktime_t kstart = ktime_get();
        int err;
        ENTRY;
 
@@ -1485,7 +1486,8 @@ static int ll_mknod(struct inode *dir, struct dentry *dchild, ll_umode_t mode,
        }
 
        if (!err)
-               ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_MKNOD, 1);
+               ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_MKNOD,
+                                  ktime_us_delta(ktime_get(), kstart));
 
        RETURN(err);
 }
@@ -1497,6 +1499,7 @@ static int ll_mknod(struct inode *dir, struct dentry *dchild, ll_umode_t mode,
 static int ll_create_nd(struct inode *dir, struct dentry *dentry,
                        umode_t mode, bool want_excl)
 {
+       ktime_t kstart = ktime_get();
        int rc;
 
        CFS_FAIL_TIMEOUT(OBD_FAIL_LLITE_CREATE_FILE_PAUSE, cfs_fail_val);
@@ -1510,11 +1513,13 @@ static int ll_create_nd(struct inode *dir, struct dentry *dentry,
         * volatile file name, so we use ll_mknod() here. */
        rc = ll_mknod(dir, dentry, mode, 0);
 
-       ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_CREATE, 1);
-
        CDEBUG(D_VFSTRACE, "VFS Op:name=%.*s, unhashed %d\n",
               dentry->d_name.len, dentry->d_name.name, d_unhashed(dentry));
 
+       if (!rc)
+               ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_CREATE,
+                                  ktime_us_delta(ktime_get(), kstart));
+
        return rc;
 }
 #else /* !HAVE_IOP_ATOMIC_OPEN */
@@ -1523,6 +1528,7 @@ static int ll_create_nd(struct inode *dir, struct dentry *dentry,
 {
        struct ll_dentry_data *lld = ll_d2d(dentry);
        struct lookup_intent *it = NULL;
+       ktime_t kstart = ktime_get();
        int rc;
 
        CFS_FAIL_TIMEOUT(OBD_FAIL_LLITE_CREATE_FILE_PAUSE, cfs_fail_val);
@@ -1556,16 +1562,17 @@ static int ll_create_nd(struct inode *dir, struct dentry *dentry,
                filp = lookup_instantiate_filp(nd, dentry, NULL);
                if (IS_ERR(filp))
                        rc = PTR_ERR(filp);
-        }
+       }
 
 out:
-        ll_intent_release(it);
-        OBD_FREE(it, sizeof(*it));
+       ll_intent_release(it);
+       OBD_FREE(it, sizeof(*it));
 
-        if (!rc)
-                ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_CREATE, 1);
+       if (!rc)
+               ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_CREATE,
+                                  ktime_us_delta(ktime_get(), kstart));
 
-        return rc;
+       return rc;
 }
 #endif /* HAVE_IOP_ATOMIC_OPEN */
 
@@ -1573,6 +1580,7 @@ static int ll_symlink(struct inode *dir, struct dentry *dchild,
                      const char *oldpath)
 {
        struct qstr *name = &dchild->d_name;
+       ktime_t kstart = ktime_get();
        int err;
        ENTRY;
 
@@ -1583,10 +1591,11 @@ static int ll_symlink(struct inode *dir, struct dentry *dchild,
        err = ll_new_node(dir, dchild, oldpath, S_IFLNK | S_IRWXUGO, 0,
                          LUSTRE_OPC_SYMLINK);
 
-        if (!err)
-                ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_SYMLINK, 1);
+       if (!err)
+               ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_SYMLINK,
+                                  ktime_us_delta(ktime_get(), kstart));
 
-        RETURN(err);
+       RETURN(err);
 }
 
 static int ll_link(struct dentry *old_dentry, struct inode *dir,
@@ -1597,6 +1606,7 @@ static int ll_link(struct dentry *old_dentry, struct inode *dir,
        struct ll_sb_info *sbi = ll_i2sbi(dir);
        struct ptlrpc_request *request = NULL;
        struct md_op_data *op_data;
+       ktime_t kstart = ktime_get();
        int err;
 
        ENTRY;
@@ -1604,29 +1614,31 @@ static int ll_link(struct dentry *old_dentry, struct inode *dir,
               "target=%.*s\n", PFID(ll_inode2fid(src)), src,
               PFID(ll_inode2fid(dir)), dir, name->len, name->name);
 
-        op_data = ll_prep_md_op_data(NULL, src, dir, name->name, name->len,
-                                     0, LUSTRE_OPC_ANY, NULL);
-        if (IS_ERR(op_data))
-                RETURN(PTR_ERR(op_data));
+       op_data = ll_prep_md_op_data(NULL, src, dir, name->name, name->len,
+                                    0, LUSTRE_OPC_ANY, NULL);
+       if (IS_ERR(op_data))
+               RETURN(PTR_ERR(op_data));
 
-        err = md_link(sbi->ll_md_exp, op_data, &request);
-        ll_finish_md_op_data(op_data);
-        if (err)
-                GOTO(out, err);
+       err = md_link(sbi->ll_md_exp, op_data, &request);
+       ll_finish_md_op_data(op_data);
+       if (err)
+               GOTO(out, err);
 
-        ll_update_times(request, dir);
-        ll_stats_ops_tally(sbi, LPROC_LL_LINK, 1);
-        EXIT;
+       ll_update_times(request, dir);
+       ll_stats_ops_tally(sbi, LPROC_LL_LINK,
+                          ktime_us_delta(ktime_get(), kstart));
+       EXIT;
 out:
-        ptlrpc_req_finished(request);
-        RETURN(err);
+       ptlrpc_req_finished(request);
+       RETURN(err);
 }
 
 static int ll_mkdir(struct inode *dir, struct dentry *dchild, ll_umode_t mode)
 {
        struct qstr *name = &dchild->d_name;
-        int err;
-        ENTRY;
+       ktime_t kstart = ktime_get();
+       int err;
+       ENTRY;
 
        CDEBUG(D_VFSTRACE, "VFS Op:name=%.*s, dir="DFID"(%p)\n",
               name->len, name->name, PFID(ll_inode2fid(dir)), dir);
@@ -1638,7 +1650,8 @@ static int ll_mkdir(struct inode *dir, struct dentry *dchild, ll_umode_t mode)
 
        err = ll_new_node(dir, dchild, NULL, mode, 0, LUSTRE_OPC_MKDIR);
        if (err == 0)
-               ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_MKDIR, 1);
+               ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_MKDIR,
+                                  ktime_us_delta(ktime_get(), kstart));
 
        RETURN(err);
 }
@@ -1646,10 +1659,12 @@ static int ll_mkdir(struct inode *dir, struct dentry *dchild, ll_umode_t mode)
 static int ll_rmdir(struct inode *dir, struct dentry *dchild)
 {
        struct qstr *name = &dchild->d_name;
-        struct ptlrpc_request *request = NULL;
-        struct md_op_data *op_data;
-        int rc;
-        ENTRY;
+       struct ptlrpc_request *request = NULL;
+       struct md_op_data *op_data;
+       ktime_t kstart = ktime_get();
+       int rc;
+
+       ENTRY;
 
        CDEBUG(D_VFSTRACE, "VFS Op:name=%.*s, dir="DFID"(%p)\n",
               name->len, name->name, PFID(ll_inode2fid(dir)), dir);
@@ -1666,15 +1681,16 @@ static int ll_rmdir(struct inode *dir, struct dentry *dchild)
                op_data->op_fid3 = *ll_inode2fid(dchild->d_inode);
 
        op_data->op_fid2 = op_data->op_fid3;
-        rc = md_unlink(ll_i2sbi(dir)->ll_md_exp, op_data, &request);
-        ll_finish_md_op_data(op_data);
-        if (rc == 0) {
-                ll_update_times(request, dir);
-                ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_RMDIR, 1);
-        }
+       rc = md_unlink(ll_i2sbi(dir)->ll_md_exp, op_data, &request);
+       ll_finish_md_op_data(op_data);
+       if (!rc)
+               ll_update_times(request, dir);
 
-        ptlrpc_req_finished(request);
-        RETURN(rc);
+       ptlrpc_req_finished(request);
+       if (!rc)
+               ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_RMDIR,
+                                  ktime_us_delta(ktime_get(), kstart));
+       RETURN(rc);
 }
 
 /**
@@ -1684,6 +1700,7 @@ int ll_rmdir_entry(struct inode *dir, char *name, int namelen)
 {
        struct ptlrpc_request *request = NULL;
        struct md_op_data *op_data;
+       ktime_t kstart = ktime_get();
        int rc;
        ENTRY;
 
@@ -1697,12 +1714,13 @@ int ll_rmdir_entry(struct inode *dir, char *name, int namelen)
        op_data->op_cli_flags |= CLI_RM_ENTRY;
        rc = md_unlink(ll_i2sbi(dir)->ll_md_exp, op_data, &request);
        ll_finish_md_op_data(op_data);
-       if (rc == 0) {
+       if (!rc)
                ll_update_times(request, dir);
-               ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_RMDIR, 1);
-       }
 
        ptlrpc_req_finished(request);
+       if (!rc)
+               ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_RMDIR,
+                                  ktime_us_delta(ktime_get(), kstart));
        RETURN(rc);
 }
 
@@ -1712,8 +1730,11 @@ static int ll_unlink(struct inode *dir, struct dentry *dchild)
        struct ptlrpc_request *request = NULL;
        struct md_op_data *op_data;
        struct mdt_body *body;
+       ktime_t kstart = ktime_get();
        int rc;
+
        ENTRY;
+
        CDEBUG(D_VFSTRACE, "VFS Op:name=%.*s, dir="DFID"(%p)\n",
               name->len, name->name, PFID(ll_inode2fid(dir)), dir);
 
@@ -1746,10 +1767,12 @@ static int ll_unlink(struct inode *dir, struct dentry *dchild)
                set_nlink(dchild->d_inode, body->mbo_nlink);
 
        ll_update_times(request, dir);
-       ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_UNLINK, 1);
 
 out:
        ptlrpc_req_finished(request);
+       if (!rc)
+               ll_stats_ops_tally(ll_i2sbi(dir), LPROC_LL_UNLINK,
+                                  ktime_us_delta(ktime_get(), kstart));
        RETURN(rc);
 }
 
@@ -1765,6 +1788,7 @@ static int ll_rename(struct inode *src, struct dentry *src_dchild,
        struct ptlrpc_request *request = NULL;
        struct ll_sb_info *sbi = ll_i2sbi(src);
        struct md_op_data *op_data;
+       ktime_t kstart = ktime_get();
        int err;
        ENTRY;
 
@@ -1793,20 +1817,22 @@ static int ll_rename(struct inode *src, struct dentry *src_dchild,
        if (tgt_dchild->d_inode != NULL)
                op_data->op_fid4 = *ll_inode2fid(tgt_dchild->d_inode);
 
-        err = md_rename(sbi->ll_md_exp, op_data,
-                        src_name->name, src_name->len,
-                        tgt_name->name, tgt_name->len, &request);
-        ll_finish_md_op_data(op_data);
-        if (!err) {
-                ll_update_times(request, src);
-                ll_update_times(request, tgt);
-                ll_stats_ops_tally(sbi, LPROC_LL_RENAME, 1);
-        }
+       err = md_rename(sbi->ll_md_exp, op_data,
+                       src_name->name, src_name->len,
+                       tgt_name->name, tgt_name->len, &request);
+       ll_finish_md_op_data(op_data);
+       if (!err) {
+               ll_update_times(request, src);
+               ll_update_times(request, tgt);
+       }
 
-        ptlrpc_req_finished(request);
+       ptlrpc_req_finished(request);
 
-       if (err == 0)
+       if (!err) {
                d_move(src_dchild, tgt_dchild);
+               ll_stats_ops_tally(sbi, LPROC_LL_RENAME,
+                                  ktime_us_delta(ktime_get(), kstart));
+       }
 
        RETURN(err);
 }
index bf3a131..dce25a7 100644 (file)
@@ -49,7 +49,6 @@ static struct kmem_cache *ll_inode_cachep;
 static struct inode *ll_alloc_inode(struct super_block *sb)
 {
        struct ll_inode_info *lli;
-       ll_stats_ops_tally(ll_s2sbi(sb), LPROC_LL_ALLOC_INODE, 1);
        OBD_SLAB_ALLOC_PTR_GFP(lli, ll_inode_cachep, GFP_NOFS);
        if (lli == NULL)
                return NULL;
index 50e98a1..6cfad04 100644 (file)
@@ -112,6 +112,7 @@ static int ll_xattr_set_common(const struct xattr_handler *handler,
        struct ptlrpc_request *req = NULL;
        const char *pv = value;
        char *fullname;
+       ktime_t kstart = ktime_get();
        u64 valid;
        int rc;
        ENTRY;
@@ -119,13 +120,10 @@ static int ll_xattr_set_common(const struct xattr_handler *handler,
        /* When setxattr() is called with a size of 0 the value is
         * unconditionally replaced by "". When removexattr() is
         * called we get a NULL value and XATTR_REPLACE for flags. */
-       if (!value && flags == XATTR_REPLACE) {
-               ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_REMOVEXATTR, 1);
+       if (!value && flags == XATTR_REPLACE)
                valid = OBD_MD_FLXATTRRM;
-       } else {
-               ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_SETXATTR, 1);
+       else
                valid = OBD_MD_FLXATTR;
-       }
 
        /* FIXME: enable IMA when the conditions are ready */
        if (handler->flags == XATTR_SECURITY_T &&
@@ -170,12 +168,17 @@ static int ll_xattr_set_common(const struct xattr_handler *handler,
        if (rc) {
                if (rc == -EOPNOTSUPP && handler->flags == XATTR_USER_T) {
                        LCONSOLE_INFO("Disabling user_xattr feature because it is not supported on the server\n");
-                        sbi->ll_flags &= ~LL_SBI_USER_XATTR;
-                }
+                       sbi->ll_flags &= ~LL_SBI_USER_XATTR;
+               }
                RETURN(rc);
-        }
+       }
+
+       ptlrpc_req_finished(req);
+
+       ll_stats_ops_tally(ll_i2sbi(inode), valid == OBD_MD_FLXATTRRM ?
+                               LPROC_LL_REMOVEXATTR : LPROC_LL_SETXATTR,
+                          ktime_us_delta(ktime_get(), kstart));
 
-        ptlrpc_req_finished(req);
        RETURN(0);
 }
 
@@ -319,6 +322,11 @@ static int ll_xattr_set(const struct xattr_handler *handler,
                        const char *name, const void *value, size_t size,
                        int flags)
 {
+       ktime_t kstart = ktime_get();
+       int op_type = flags == XATTR_REPLACE ? LPROC_LL_REMOVEXATTR :
+                                              LPROC_LL_SETXATTR;
+       int rc;
+
        LASSERT(inode);
        LASSERT(name);
 
@@ -327,18 +335,14 @@ static int ll_xattr_set(const struct xattr_handler *handler,
 
        /* lustre/trusted.lov.xxx would be passed through xattr API */
        if (!strcmp(name, "lov")) {
-               int op_type = flags == XATTR_REPLACE ? LPROC_LL_REMOVEXATTR :
-                                                      LPROC_LL_SETXATTR;
-
-               ll_stats_ops_tally(ll_i2sbi(inode), op_type, 1);
-
-               return ll_setstripe_ea(dentry, (struct lov_user_md *)value,
+               rc = ll_setstripe_ea(dentry, (struct lov_user_md *)value,
                                       size);
+               ll_stats_ops_tally(ll_i2sbi(inode), op_type,
+                                  ktime_us_delta(ktime_get(), kstart));
+               return rc;
        } else if (!strcmp(name, "lma") || !strcmp(name, "link")) {
-               int op_type = flags == XATTR_REPLACE ? LPROC_LL_REMOVEXATTR :
-                                                      LPROC_LL_SETXATTR;
-
-               ll_stats_ops_tally(ll_i2sbi(inode), op_type, 1);
+               ll_stats_ops_tally(ll_i2sbi(inode), op_type,
+                                  ktime_us_delta(ktime_get(), kstart));
                return 0;
        }
 
@@ -424,13 +428,12 @@ static int ll_xattr_get_common(const struct xattr_handler *handler,
                               const char *name, void *buffer, size_t size)
 {
        struct ll_sb_info *sbi = ll_i2sbi(inode);
+       ktime_t kstart = ktime_get();
        char *fullname;
        int rc;
 
        ENTRY;
 
-       ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_GETXATTR, 1);
-
        rc = xattr_type_filter(sbi, handler);
        if (rc)
                RETURN(rc);
@@ -470,6 +473,9 @@ static int ll_xattr_get_common(const struct xattr_handler *handler,
        rc = ll_xattr_list(inode, fullname, handler->flags, buffer, size,
                           OBD_MD_FLXATTR);
        kfree(fullname);
+       ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_GETXATTR,
+                          ktime_us_delta(ktime_get(), kstart));
+
        RETURN(rc);
 }
 
@@ -588,6 +594,7 @@ ssize_t ll_listxattr(struct dentry *dentry, char *buffer, size_t size)
 {
        struct inode *inode = dentry->d_inode;
        struct ll_sb_info *sbi = ll_i2sbi(inode);
+       ktime_t kstart = ktime_get();
        char *xattr_name;
        ssize_t rc, rc2;
        size_t len, rem;
@@ -597,8 +604,6 @@ ssize_t ll_listxattr(struct dentry *dentry, char *buffer, size_t size)
        CDEBUG(D_VFSTRACE, "VFS Op:inode="DFID"(%p)\n",
               PFID(ll_inode2fid(inode)), inode);
 
-       ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_LISTXATTR, 1);
-
        rc = ll_xattr_list(inode, NULL, XATTR_OTHER_T, buffer, size,
                           OBD_MD_FLXATTRLS);
        if (rc < 0)
@@ -610,7 +615,7 @@ ssize_t ll_listxattr(struct dentry *dentry, char *buffer, size_t size)
         * exists.
         */
        if (!size)
-               RETURN(rc + sizeof(XATTR_LUSTRE_LOV));
+               goto out;
 
        xattr_name = buffer;
        rem = rc;
@@ -644,6 +649,10 @@ ssize_t ll_listxattr(struct dentry *dentry, char *buffer, size_t size)
 
        memcpy(buffer + rc, XATTR_LUSTRE_LOV, sizeof(XATTR_LUSTRE_LOV));
 
+out:
+       ll_stats_ops_tally(ll_i2sbi(inode), LPROC_LL_LISTXATTR,
+                          ktime_us_delta(ktime_get(), kstart));
+
        RETURN(rc + sizeof(XATTR_LUSTRE_LOV));
 }
 
index c78862e..0f32b1a 100644 (file)
@@ -11361,41 +11361,52 @@ run_test 126 "check that the fsgid provided by the client is taken into account"
 
 test_127a() { # bug 15521
        [ $PARALLEL == "yes" ] && skip "skip parallel run"
+       local name count samp unit min max sum sumsq
 
        $LFS setstripe -i 0 -c 1 $DIR/$tfile || error "setstripe failed"
+       echo "stats before reset"
+       $LCTL get_param osc.*.stats
        $LCTL set_param osc.*.stats=0
-       FSIZE=$((2048 * 1024))
-       dd if=/dev/zero of=$DIR/$tfile bs=$FSIZE count=1
+       local fsize=$((2048 * 1024))
+
+       dd if=/dev/zero of=$DIR/$tfile bs=$fsize count=1
        cancel_lru_locks osc
-       dd if=$DIR/$tfile of=/dev/null bs=$FSIZE
-
-       $LCTL get_param osc.*0000-osc-*.stats | grep samples > $DIR/${tfile}.tmp
-        while read NAME COUNT SAMP UNIT MIN MAX SUM SUMSQ; do
-                echo "got $COUNT $NAME"
-                [ ! $MIN ] && error "Missing min value for $NAME proc entry"
-                eval $NAME=$COUNT || error "Wrong proc format"
-
-                case $NAME in
-                        read_bytes|write_bytes)
-                        [ $MIN -lt 4096 ] && error "min is too small: $MIN"
-                        [ $MIN -gt $FSIZE ] && error "min is too big: $MIN"
-                        [ $MAX -lt 4096 ] && error "max is too small: $MAX"
-                        [ $MAX -gt $FSIZE ] && error "max is too big: $MAX"
-                        [ $SUM -ne $FSIZE ] && error "sum is wrong: $SUM"
-                        [ $SUMSQ -lt $(((FSIZE /4096) * (4096 * 4096))) ] &&
-                                error "sumsquare is too small: $SUMSQ"
-                        [ $SUMSQ -gt $((FSIZE * FSIZE)) ] &&
-                                error "sumsquare is too big: $SUMSQ"
-                        ;;
-                        *) ;;
-                esac
-        done < $DIR/${tfile}.tmp
-
-        #check that we actually got some stats
-        [ "$read_bytes" ] || error "Missing read_bytes stats"
-        [ "$write_bytes" ] || error "Missing write_bytes stats"
-        [ "$read_bytes" != 0 ] || error "no read done"
-        [ "$write_bytes" != 0 ] || error "no write done"
+       dd if=$DIR/$tfile of=/dev/null bs=$fsize
+
+       $LCTL get_param osc.*0000-osc-*.stats | grep samples > $DIR/$tfile.tmp
+       stack_trap "rm -f $TMP/$tfile.tmp"
+       while read name count samp unit min max sum sumsq; do
+               echo "got name=$name count=$count unit=$unit min=$min max=$max"
+               [ ! $min ] && error "Missing min value for $name proc entry"
+               eval $name=$count || error "Wrong proc format"
+
+               case $name in
+               read_bytes|write_bytes)
+                       [[ "$unit" =~ "bytes" ]] ||
+                               error "unit is not 'bytes': $unit"
+                       (( $min >= 4096 )) || error "min is too small: $min"
+                       (( $min <= $fsize )) || error "min is too big: $min"
+                       (( $max >= 4096 )) || error "max is too small: $max"
+                       (( $max <= $fsize )) || error "max is too big: $max"
+                       (( $sum == $fsize )) || error "sum is wrong: $sum"
+                       (( $sumsq >= ($fsize / 4096) * (4096 * 4096) )) ||
+                               error "sumsquare is too small: $sumsq"
+                       (( $sumsq <= $fsize * $fsize )) ||
+                               error "sumsquare is too big: $sumsq"
+                       ;;
+               ost_read|ost_write)
+                       [[ "$unit" =~ "usec" ]] ||
+                               error "unit is not 'usec': $unit"
+                       ;;
+               *)      ;;
+               esac
+       done < $DIR/$tfile.tmp
+
+       #check that we actually got some stats
+       [ "$read_bytes" ] || error "Missing read_bytes stats"
+       [ "$write_bytes" ] || error "Missing write_bytes stats"
+       [ "$read_bytes" != 0 ] || error "no read done"
+       [ "$write_bytes" != 0 ] || error "no write done"
 }
 run_test 127a "verify the client stats are sane"
 
@@ -11403,6 +11414,8 @@ test_127b() { # bug LU-333
        [ $PARALLEL == "yes" ] && skip "skip parallel run"
        local name count samp unit min max sum sumsq
 
+       echo "stats before reset"
+       $LCTL get_param llite.*.stats
        $LCTL set_param llite.*.stats=0
 
        # perform 2 reads and writes so MAX is different from SUM.
@@ -11413,30 +11426,28 @@ test_127b() { # bug LU-333
        dd if=$DIR/$tfile of=/dev/null bs=$PAGE_SIZE count=1
 
        $LCTL get_param llite.*.stats | grep samples > $TMP/$tfile.tmp
+       stack_trap "rm -f $TMP/$tfile.tmp"
        while read name count samp unit min max sum sumsq; do
-               echo "got $count $name"
+               echo "got name=$name count=$count unit=$unit min=$min max=$max"
                eval $name=$count || error "Wrong proc format"
 
                case $name in
-               read_bytes)
-                       [ $count -ne 2 ] && error "count is not 2: $count"
-                       [ $min -ne $PAGE_SIZE ] &&
+               read_bytes|write_bytes)
+                       [[ "$unit" =~ "bytes" ]] ||
+                               error "unit is not 'bytes': $unit"
+                       (( $count == 2 )) || error "count is not 2: $count"
+                       (( $min == $PAGE_SIZE )) ||
                                error "min is not $PAGE_SIZE: $min"
-                       [ $max -ne $PAGE_SIZE ] &&
-                               error "max is incorrect: $max"
-                       [ $sum -ne $((PAGE_SIZE * 2)) ] &&
-                               error "sum is wrong: $sum"
+                       (( $max == $PAGE_SIZE )) ||
+                               error "max is not $PAGE_SIZE: $max"
+                       (( $sum == $PAGE_SIZE * 2 )) ||
+                               error "sum is not $((PAGE_SIZE * 2)): $sum"
                        ;;
-               write_bytes)
-                       [ $count -ne 2 ] && error "count is not 2: $count"
-                       [ $min -ne $PAGE_SIZE ] &&
-                               error "min is not $PAGE_SIZE: $min"
-                       [ $max -ne $PAGE_SIZE ] &&
-                               error "max is incorrect: $max"
-                       [ $sum -ne $((PAGE_SIZE * 2)) ] &&
-                               error "sum is wrong: $sum"
+               read|write)
+                       [[ "$unit" =~ "usec" ]] ||
+                               error "unit is not 'usec': $unit"
                        ;;
-               *) ;;
+               *)      ;;
                esac
        done < $TMP/$tfile.tmp
 
@@ -11445,8 +11456,6 @@ test_127b() { # bug LU-333
        [ "$write_bytes" ] || error "Missing write_bytes stats"
        [ "$read_bytes" != 0 ] || error "no read done"
        [ "$write_bytes" != 0 ] || error "no write done"
-
-       rm -f $TMP/${tfile}.tmp
 }
 run_test 127b "verify the llite client stats are sane"