summaryrefslogtreecommitdiffstats
path: root/fs/gfs2/recovery.c
diff options
context:
space:
mode:
authorAbhi Das <adas@redhat.com>2018-03-29 10:41:27 -0700
committerBob Peterson <rpeterso@redhat.com>2018-03-29 10:41:27 -0700
commit5e86d9d122d0d6fae00d9dff41c22d6f4d09f566 (patch)
treef1c04c72d8d03d4ceeb02ab7f0ebecc0926ae475 /fs/gfs2/recovery.c
parentfffb64127adc3eea6a19ceefdc88d171f68b9d34 (diff)
downloadlinux-5e86d9d122d0d6fae00d9dff41c22d6f4d09f566.tar.bz2
gfs2: time journal recovery steps accurately
This patch spits out the time taken by the various steps in the journal recover process. Previously, the journal recovery time didn't account for finding the journal head in the log which takes up a significant portion of time. Signed-off-by: Abhi Das <adas@redhat.com> Signed-off-by: Bob Peterson <rpeterso@redhat.com>
Diffstat (limited to 'fs/gfs2/recovery.c')
-rw-r--r--fs/gfs2/recovery.c20
1 files changed, 14 insertions, 6 deletions
diff --git a/fs/gfs2/recovery.c b/fs/gfs2/recovery.c
index b6b258998bcd..d8b622c375ab 100644
--- a/fs/gfs2/recovery.c
+++ b/fs/gfs2/recovery.c
@@ -15,6 +15,7 @@
#include <linux/gfs2_ondisk.h>
#include <linux/crc32.h>
#include <linux/crc32c.h>
+#include <linux/ktime.h>
#include "gfs2.h"
#include "incore.h"
@@ -409,12 +410,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, thaw_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",
@@ -446,6 +448,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);
@@ -455,13 +458,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 freeze lock */
error = gfs2_glock_nq_init(sdp->sd_freeze_gl, LM_ST_SHARED,
@@ -495,6 +497,7 @@ void gfs2_recover_func(struct work_struct *work)
goto fail_gunlock_thaw;
}
+ t_tlck = ktime_get();
fs_info(sdp, "jid=%u: Replaying journal...\n", jd->jd_jid);
for (pass = 0; pass < 2; pass++) {
@@ -509,9 +512,14 @@ void gfs2_recover_func(struct work_struct *work)
clean_journal(jd, &head);
gfs2_glock_dq_uninit(&thaw_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);