From 45b717e92e7b81e594ab6365c4da95034a6f6511 Mon Sep 17 00:00:00 2001 From: Patrick Farrell Date: Fri, 2 May 2025 18:38:53 -0700 Subject: [PATCH] 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 Change-Id: I6fe416ba44be5572f130704ba9d3e9b85d09c656 Reviewed-on: https://review.whamcloud.com/c/fs/lustre-release/+/59075 Tested-by: jenkins Tested-by: Maloo Reviewed-by: Oleg Drokin --- lustre/llite/file.c | 12 ++++++++++++ lustre/llite/llite_mmap.c | 10 ++++++++++ lustre/llite/rw.c | 17 +++++++++++------ lustre/osc/osc_request.c | 16 ++++++++++++++-- 4 files changed, 47 insertions(+), 8 deletions(-) diff --git a/lustre/llite/file.c b/lustre/llite/file.c index 7b73a2a..345e805 100644 --- 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 --- 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 --- 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 --- 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); -- 1.8.3.1