[Cluster-devel] [RFC PATCH 2/3] gfs2: add timing info for various stages of journal recovery

[Steven Whitehouse <swhiteho@redhat.com>]

Hi,

Looks good.

Acked-by: Steven Whitehouse <swhiteho@redhat.com>

Steve.


On 29/05/18 09:05, Abhi Das wrote:
> Tells you how many milliseconds each stage of journal recovery
> takes.
>
> Signed-off-by: Abhi Das <adas@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);