LU-15317 osc: Add RPC to iotrace

Add RPCs to iotrace debugging.

To avoid creating too much debug output, this debug
ignores the possiblity that an RPC contains non-contiguous
extents.  Thus the eventual visualization will act as
though the RPC is a continuous whole.  I judge this to be
superior to the amount of log data and complexity of
capturing each extent separately.  If that level of detail
is needed, a higher debug level can be used.

Lustre-change: https://review.whamcloud.com/45894
Lustre-commit: 5cb722c384077dd2469763a4f70a72bed555c8db

Was-Change-Id: I6fe416ba44be5572f130704ba9d3e9b85d09c656

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.

Lustre-change: https://review.whamcloud.com/46484
Lustre-commit: d48b10cef36d74cc63cf6e9340f43a5cebd985de

Was-Change-Id: I17f52ebc87a31d5ba34f63dc8b6a279e83cd10ef

LU-15317 llite: Add FID to async ra iotrace

IOtrace log entries need to include the FID of the file
concerned.  Add this to async readahead.

Lustre-change: https://review.whamcloud.com/45912
Lustre-commit: 1f3ecfdbb4c765808a1d30677e0f67421fab6e0c

Was-Change-Id: I8d788969f29412ce88f1cafa229977f6efa20962

LU-15317 llite: Add strided readahead to iotrace

We need to capture some additional parameters to correctly
understand the behavior of strided readahead.  Add these
parameters to the existing iotrace message.

Lustre-change: https://review.whamcloud.com/45888
Lustre-commit: 5ed185955985b099b3bd7311b346f5945c0940a4

Was-Change-Id: I7caddf9dfaf9ba5f2645d045d5a4a50562cc1b54

LU-15317 llite: Make iotrace logging quieter

Most of the time, we don't read any pages with readahead,
since we're moving through the window and aren't ready to
read more yet.  That's important for readahead debug, but
there's no need to log it for iotrace.  (This matters
because without this change, this messsage is the large
majority of iotrace messages.)

Lustre-change: https://review.whamcloud.com/45887
Lustre-commit: a91b5d4a990c6a870774e1e856cc41f665a88854

Was-Change-Id: I58197acd1ef97c903320a2433ec1d5dcb0e46bd0

Test-parameters: trivial

Signed-off-by: Patrick Farrell <pfarrell@whamcloud.com>
Change-Id: I6fe416ba44be5572f130704ba9d3e9b85d09c656
Reviewed-on: https://review.whamcloud.com/c/fs/lustre-release/+/59075
Tested-by: jenkins <devops@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 7b73a2a..345e805 100644 (file)
--- a/lustre/llite/file.c
+++ b/lustre/llite/file.c
@@ -2088,6 +2088,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);
 }
 
@@ -2231,6 +2237,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 16d73eb..48ecd21 100644 (file)
--- a/lustre/llite/llite_mmap.c
+++ b/lustre/llite/llite_mmap.c
@@ -463,6 +463,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;
 }
 
@@ -538,6 +543,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;
 }
 

diff --git a/lustre/llite/rw.c b/lustre/llite/rw.c
index abb105e..b97038a 100644 (file)
--- a/lustre/llite/rw.c
+++ b/lustre/llite/rw.c
@@ -592,9 +592,9 @@ static void ll_readahead_handle_work(struct work_struct *wq)
        sbi = ll_i2sbi(inode);
 
        CDEBUG(D_READA|D_IOTRACE,
-              "%s: async ra from %lu to %lu triggered by user pid %d\n",
-              file_dentry(file)->d_name.name, work->lrw_start_idx,
-              work->lrw_end_idx, work->lrw_user_pid);
+              "%s:"DFID": async ra from %lu to %lu triggered by user pid %d\n",
+              file_dentry(file)->d_name.name, PFID(ll_inode2fid(inode)),
+              work->lrw_start_idx, work->lrw_end_idx, work->lrw_user_pid);
 
        env = cl_env_alloc(&refcheck, LCT_NOREF);
        if (IS_ERR(env))
@@ -1691,10 +1691,15 @@ int ll_io_read_page(const struct lu_env *env, struct cl_io *io,
                rc2 = ll_readahead(env, io, &queue->c2_qin, ras,
                                   uptodate, file, skip_index,
                                   &ra_start_index);
-               CDEBUG(D_READA|D_IOTRACE,
-                      DFID " %d pages read ahead at %lu, triggered by user read at %lu\n",
+               /* to keep iotrace clean, we only print here if we actually
+                * read pages
+                */
+               CDEBUG(D_READA | (rc2 ? D_IOTRACE : 0),
+                      DFID " %d pages read ahead at %lu, triggered by user read at %lu, stride offset %lld, stride length %lld, stride bytes %lld\n",
                       PFID(ll_inode2fid(inode)), rc2, ra_start_index,
-                      vvp_index(vpg));
+                      vvp_index(vpg), ras->ras_stride_offset,
+                      ras->ras_stride_length, ras->ras_stride_bytes);
+
        } else if (vvp_index(vpg) == io_start_index &&
                   io_end_index - io_start_index > 0) {
                rc2 = ll_readpages(env, io, &queue->c2_qin, io_start_index + 1,

diff --git a/lustre/osc/osc_request.c b/lustre/osc/osc_request.c
index 59607e7..5dfd643 100644 (file)
--- a/lustre/osc/osc_request.c
+++ b/lustre/osc/osc_request.c
@@ -2781,6 +2781,7 @@ int osc_build_rpc(const struct lu_env *env, struct client_obd *cli,
 
        spin_lock(&cli->cl_loi_list_lock);
        starting_offset >>= PAGE_SHIFT;
+       ending_offset >>= PAGE_SHIFT;
        if (cmd == OBD_BRW_READ) {
                cli->cl_r_in_flight++;
                lprocfs_oh_tally_log2(&cli->cl_read_page_hist, page_count);
@@ -2797,8 +2798,19 @@ int osc_build_rpc(const struct lu_env *env, struct client_obd *cli,
        spin_unlock(&cli->cl_loi_list_lock);
 
        DEBUG_REQ(D_INODE, req, "%d pages, aa %p, now %ur/%uw in flight",
-                 page_count, aa, cli->cl_r_in_flight,
-                 cli->cl_w_in_flight);
+                 page_count, aa, cli->cl_r_in_flight, cli->cl_w_in_flight);
+       if (libcfs_debug & D_IOTRACE) {
+               struct lu_fid fid;
+
+               fid.f_seq = crattr->cra_oa->o_parent_seq;
+               fid.f_oid = crattr->cra_oa->o_parent_oid;
+               fid.f_ver = crattr->cra_oa->o_parent_ver;
+               CDEBUG(D_IOTRACE,
+                      DFID": %d %s pages, start %lld, end %lld, now %ur/%uw in flight\n",
+                      PFID(&fid), page_count,
+                      cmd == OBD_BRW_READ ? "read" : "write", starting_offset,
+                      ending_offset, cli->cl_r_in_flight, cli->cl_w_in_flight);
+       }
        OBD_FAIL_TIMEOUT(OBD_FAIL_OSC_DELAY_IO, cfs_fail_val);
 
        ptlrpcd_add_req(req);