From: Andreas Dilger <adilger@whamcloud.com>
Date: Fri, 6 Sep 2019 07:50:44 +0000 (-0600)
Subject: LU-12631 llite: report latency for filesystem ops
X-Git-Tag: 2.13.51~199
X-Git-Url: https://git.whamcloud.com/?p=fs%2Flustre-release.git;a=commitdiff_plain;h=ea58c4cfb0fc255befbbb7754bd4ed71704a2a2c;hp=8a0a6dbec5537764958d4863e76de249fdd675a4

LU-12631 llite: report latency for filesystem ops

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>
---

diff --git a/contrib/scripts/spelling.txt b/contrib/scripts/spelling.txt
index 96cf01d..470c62b 100644
--- a/contrib/scripts/spelling.txt
+++ b/contrib/scripts/spelling.txt
@@ -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
diff --git a/lustre/include/lprocfs_status.h b/lustre/include/lprocfs_status.h
index 2b66f7a..fd916d3 100644
--- a/lustre/include/lprocfs_status.h
+++ b/lustre/include/lprocfs_status.h
@@ -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)
diff --git a/lustre/llite/dir.c b/lustre/llite/dir.c
index 7946691..ace18b5 100644
--- a/lustre/llite/dir.c
+++ b/lustre/llite/dir.c
@@ -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);
 }
diff --git a/lustre/llite/file.c b/lustre/llite/file.c
index a4da041..3db09e1 100644
--- a/lustre/llite/file.c
+++ b/lustre/llite/file.c
@@ -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);
 }
 
diff --git a/lustre/llite/llite_internal.h b/lustre/llite/llite_internal.h
index f27043c..480f21b 100644
--- a/lustre/llite/llite_internal.h
+++ b/lustre/llite/llite_internal.h
@@ -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,
diff --git a/lustre/llite/llite_lib.c b/lustre/llite/llite_lib.c
index e84f5e5..22fa391 100644
--- a/lustre/llite/llite_lib.c
+++ b/lustre/llite/llite_lib.c
@@ -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;
 }
 
diff --git a/lustre/llite/llite_mmap.c b/lustre/llite/llite_mmap.c
index 14ed60d..ead6b39 100644
--- a/lustre/llite/llite_mmap.c
+++ b/lustre/llite/llite_mmap.c
@@ -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);
 }
diff --git a/lustre/llite/lproc_llite.c b/lustre/llite/lproc_llite.c
index 6f26f49..081316e 100644
--- a/lustre/llite/lproc_llite.c
+++ b/lustre/llite/lproc_llite.c
@@ -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),
diff --git a/lustre/llite/namei.c b/lustre/llite/namei.c
index 3c4d375..7e46d5f 100644
--- a/lustre/llite/namei.c
+++ b/lustre/llite/namei.c
@@ -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);
 }
diff --git a/lustre/llite/super25.c b/lustre/llite/super25.c
index bf3a131..dce25a7 100644
--- a/lustre/llite/super25.c
+++ b/lustre/llite/super25.c
@@ -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;
diff --git a/lustre/llite/xattr.c b/lustre/llite/xattr.c
index 50e98a1..6cfad04 100644
--- a/lustre/llite/xattr.c
+++ b/lustre/llite/xattr.c
@@ -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));
 }
 
diff --git a/lustre/tests/sanity.sh b/lustre/tests/sanity.sh
index c78862e..0f32b1a 100644
--- a/lustre/tests/sanity.sh
+++ b/lustre/tests/sanity.sh
@@ -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"