LU-15317 llite: Add COMPLETED iotrace messages

It's very useful to see how long an I/O call took.  There
are other ways to do this, but the goal is for iotrace to
provide all necessary information for basic I/O performance
analysis, so we add COMPLETED messages to iotrace.

Test-Parameters: trivial

Signed-off-by: Patrick Farrell <pfarrell@whamcloud.com>
Change-Id: I17f52ebc87a31d5ba34f63dc8b6a279e83cd10ef
Reviewed-on: https://review.whamcloud.com/46484
Tested-by: jenkins <devops@whamcloud.com>
Reviewed-by: Sebastien Buisson <sbuisson@ddn.com>
Reviewed-by: Andreas Dilger <adilger@whamcloud.com>
Tested-by: Maloo <maloo@whamcloud.com>
Reviewed-by: Oleg Drokin <green@whamcloud.com>

diff --git a/lustre/llite/file.c b/lustre/llite/file.c
index dbf79e9..530210b 100644 (file)
--- a/lustre/llite/file.c
+++ b/lustre/llite/file.c
@@ -2002,6 +2002,12 @@ out:
                                   ktime_us_delta(ktime_get(), kstart));
        }
 
+       CDEBUG(D_IOTRACE,
+              "COMPLETED: file %s:"DFID", ppos: %lld, count: %zu\n",
+              file_dentry(file)->d_name.name,
+              PFID(ll_inode2fid(file_inode(file))), iocb->ki_pos,
+              iov_iter_count(to));
+
        RETURN(result);
 }
 
@@ -2145,6 +2151,12 @@ out:
                                   ktime_us_delta(ktime_get(), kstart));
        }
 
+       CDEBUG(D_IOTRACE,
+              "COMPLETED: file %s:"DFID", ppos: %lld, count: %zu\n",
+              file_dentry(file)->d_name.name,
+              PFID(ll_inode2fid(file_inode(file))), iocb->ki_pos,
+              iov_iter_count(from));
+
        RETURN(rc_normal);
 }
 

diff --git a/lustre/llite/llite_mmap.c b/lustre/llite/llite_mmap.c
index d976c25..8da0702 100644 (file)
--- a/lustre/llite/llite_mmap.c
+++ b/lustre/llite/llite_mmap.c
@@ -423,6 +423,11 @@ out:
                                   ktime_us_delta(ktime_get(), kstart));
        }
 
+       CDEBUG(D_IOTRACE,
+              "COMPLETED: "DFID": vma=%p start=%#lx end=%#lx vm_flags=%#lx idx=%lu\n",
+              PFID(&ll_i2info(file_inode(vma->vm_file))->lli_fid),
+              vma, vma->vm_start, vma->vm_end, vma->vm_flags, vmf->pgoff);
+
        return result;
 }
 
@@ -498,6 +503,11 @@ out:
                                   ktime_us_delta(ktime_get(), kstart));
        }
 
+       CDEBUG(D_IOTRACE,
+              "COMPLETED: "DFID": vma=%p start=%#lx end=%#lx vm_flags=%#lx idx=%lu\n",
+              PFID(&ll_i2info(file_inode(vma->vm_file))->lli_fid),
+              vma, vma->vm_start, vma->vm_end, vma->vm_flags,
+              vmf->page->index);
        return result;
 }