Tells you how many milliseconds each stage of journal recovery takes. Signed-off-by: Abhi Das <a...@redhat.com> --- fs/gfs2/ops_fstype.c | 5 +++++ fs/gfs2/recovery.c | 20 ++++++++++++++------ 2 files changed, 19 insertions(+), 6 deletions(-)
diff --git a/fs/gfs2/ops_fstype.c b/fs/gfs2/ops_fstype.c index cf3e366..fd460c1 100644 --- a/fs/gfs2/ops_fstype.c +++ b/fs/gfs2/ops_fstype.c @@ -532,7 +532,9 @@ int map_journal_extents(struct gfs2_sbd *sdp, struct gfs2_jdesc *jd) struct gfs2_journal_extent *jext = NULL; struct buffer_head bh; int rc = 0; + ktime_t start, end; + start = ktime_get(); prev_db = 0; for (lb = 0; lb < i_size_read(jd->jd_inode) >> sdp->sd_sb.sb_bsize_shift; lb++) { @@ -564,6 +566,9 @@ int map_journal_extents(struct gfs2_sbd *sdp, struct gfs2_jdesc *jd) } prev_db = db; } + end = ktime_get(); + fs_info(sdp, "jid=%u: Journal extent mapped in %lldms\n", jd->jd_jid, + ktime_ms_delta(end, start)); return rc; } diff --git a/fs/gfs2/recovery.c b/fs/gfs2/recovery.c index 56dea44..4b042db 100644 --- a/fs/gfs2/recovery.c +++ b/fs/gfs2/recovery.c @@ -14,6 +14,7 @@ #include <linux/buffer_head.h> #include <linux/gfs2_ondisk.h> #include <linux/crc32.h> +#include <linux/ktime.h> #include "gfs2.h" #include "incore.h" @@ -455,12 +456,13 @@ void gfs2_recover_func(struct work_struct *work) struct gfs2_sbd *sdp = GFS2_SB(jd->jd_inode); struct gfs2_log_header_host head; struct gfs2_holder j_gh, ji_gh, t_gh; - unsigned long t; + ktime_t t_start, t_jlck, t_jhd, t_tlck, t_rep; int ro = 0; unsigned int pass; int error; int jlocked = 0; + t_start = ktime_get(); if (sdp->sd_args.ar_spectator || (jd->jd_jid != sdp->sd_lockstruct.ls_jid)) { fs_info(sdp, "jid=%u: Trying to acquire journal lock...\n", @@ -492,6 +494,7 @@ void gfs2_recover_func(struct work_struct *work) fs_info(sdp, "jid=%u, already locked for use\n", jd->jd_jid); } + t_jlck = ktime_get(); fs_info(sdp, "jid=%u: Looking at journal...\n", jd->jd_jid); error = gfs2_jdesc_check(jd); @@ -501,13 +504,12 @@ void gfs2_recover_func(struct work_struct *work) error = gfs2_find_jhead(jd, &head); if (error) goto fail_gunlock_ji; + t_jhd = ktime_get(); if (!(head.lh_flags & GFS2_LOG_HEAD_UNMOUNT)) { fs_info(sdp, "jid=%u: Acquiring the transaction lock...\n", jd->jd_jid); - t = jiffies; - /* Acquire a shared hold on the transaction lock */ error = gfs2_glock_nq_init(sdp->sd_trans_gl, LM_ST_SHARED, @@ -541,6 +543,7 @@ void gfs2_recover_func(struct work_struct *work) goto fail_gunlock_tr; } + t_tlck = ktime_get(); fs_info(sdp, "jid=%u: Replaying journal...\n", jd->jd_jid); for (pass = 0; pass < 2; pass++) { @@ -557,9 +560,14 @@ void gfs2_recover_func(struct work_struct *work) goto fail_gunlock_tr; gfs2_glock_dq_uninit(&t_gh); - t = DIV_ROUND_UP(jiffies - t, HZ); - fs_info(sdp, "jid=%u: Journal replayed in %lus\n", - jd->jd_jid, t); + t_rep = ktime_get(); + fs_info(sdp, "jid=%u: Journal replayed in %lldms [jlck:%lldms, " + "jhead:%lldms, tlck:%lldms, replay:%lldms]\n", + jd->jd_jid, ktime_ms_delta(t_rep, t_start), + ktime_ms_delta(t_jlck, t_start), + ktime_ms_delta(t_jhd, t_jlck), + ktime_ms_delta(t_tlck, t_jhd), + ktime_ms_delta(t_rep, t_tlck)); } gfs2_recovery_done(sdp, jd->jd_jid, LM_RD_SUCCESS); -- 2.4.11