Re: very large mount time after unxepected power down

[Vyacheslav Dubeyko <slava-yeENwD64cLxBDgjK7y7TUQ@public.gmane.org>]

[-- Attachment #1: Type: text/plain, Size: 2488 bytes --]

Hi,

On Tue, 2012-11-27 at 15:29 +0400, Vyacheslav Dubeyko wrote:
> On Tue, 2012-11-27 at 12:58 +0300, Сергей Александров wrote:
> > As I expected, no new info:
> > [57291.417113] NILFS warning: mounting unchecked fs
> > [57291.417125] NILFS: nilfs_search_super_root
> > [57291.417132] NILFS: pseg_start 115603456, seg_seq 4347757
> > [57291.417137] NILFS: cno 1252241, segnum 56447
> > [62768.349242] NILFS: recovery complete.
> > [62768.351804] segctord starting. Construction interval = 5 seconds,
> > CP frequency < 30 seconds
> > 
> > So, I suppose, nilfs is searching for a super root for a very long
> > time and find's out that it is consistent.
> 
> 
> Ok. I think that I understand situation currently. I try to simulate the
> issue and investigate it more deeply. If my presupposition will be wrong
> then I will ask about more details.
> 

Currently, I understand that my presuppositions were wrong or I simulate
situation in not proper environment. Sorry.

We can view from outputs that it really takes place situation of super
root searching by means of validation of logs (nilfs_validate_log). But
it is not so clear a reason of it. My presupposition about values in
superblocks can be a one of possible reason of reported issue. But in
current NILFS implementation primary and secondary superblocks are
swapped and flushed frequently. So, it can be a reason only in the case
when RAID influences on flush process, I think. But it is only my
suspicion. The algorithm of superblocks swapping works fine on my side
and for sudden power-off also.

So, anyway, I can suggest currently only to investigate situation more
deeply. The reason can be in some special corruption of logs or in
peculiarities of algorithm of nilfs_search_super_root() method (I think
that it is a more probable reason). But we need to have more details
about environment of the issue.

I prepared additional two patches (please, find in attachment) that add
more debug messages (especially, in the nilfs_search_super_root()
method). I suggest to apply these patches temporary and get this debug
output for the case of issue reproducing. The most of this output will
occur during mount operation and tryings to recover filesystem.

With the best regards,
Vyacheslav Dubeyko.

> Thanks,
> Vyacheslav Dubeyko.
> 
> > --------------------------------------------------
> > Александров Сергей Васильевич



[-- Attachment #2: 0001-nilfs2-debug-messages-for-log-validation-sequence-in.patch --]
[-- Type: text/x-patch, Size: 2895 bytes --]

From: Vyacheslav Dubeyko <slava-yeENwD64cLxBDgjK7y7TUQ@public.gmane.org>
Subject: [PATCH 1/2] nilfs2: debug messages for log validation sequence investigation

Add debug messages for log validation sequence investigation

Signed-off-by: Vyacheslav Dubeyko <slava-yeENwD64cLxBDgjK7y7TUQ@public.gmane.org>
---
 fs/nilfs2/recovery.c  |    6 ++++++
 fs/nilfs2/super.c     |    6 ++++++
 fs/nilfs2/the_nilfs.c |    6 ++++++
 3 files changed, 18 insertions(+)

diff --git a/fs/nilfs2/recovery.c b/fs/nilfs2/recovery.c
index f1626f5..1e8b044 100644
--- a/fs/nilfs2/recovery.c
+++ b/fs/nilfs2/recovery.c
@@ -840,6 +840,12 @@ int nilfs_search_super_root(struct the_nilfs *nilfs,
 		__breadahead(nilfs->ns_bdev, b++, nilfs->ns_blocksize);
 
 	for (;;) {
+
+
+		pr_debug("NILFS: pseg_start %ld, seg_seq %lld\n", pseg_start, seg_seq);
+		pr_debug("NILFS: cno %lld, segnum %lld\n", cno, segnum);
+		pr_debug("NILFS: nextnum %lld\n", nextnum);
+
 		brelse(bh_sum);
 		ret = NILFS_SEG_FAIL_IO;
 		bh_sum = nilfs_read_log_header(nilfs, pseg_start, &sum);
diff --git a/fs/nilfs2/super.c b/fs/nilfs2/super.c
index 3c991dc..c88cb7a 100644
--- a/fs/nilfs2/super.c
+++ b/fs/nilfs2/super.c
@@ -254,6 +254,10 @@ void nilfs_set_log_cursor(struct nilfs_super_block *sbp,
 	nilfs_count_free_blocks(nilfs, &nfreeblocks);
 	sbp->s_free_blocks_count = cpu_to_le64(nfreeblocks);
 
+	pr_debug("NILFS: nilfs_set_log_cursor\n");
+	pr_debug("NILFS: nilfs->ns_last_cno: %lld\n", nilfs->ns_last_cno);
+	pr_debug("NILFS: nilfs->ns_last_pseg: %lld\n", nilfs->ns_last_pseg);
+
 	spin_lock(&nilfs->ns_last_segment_lock);
 	sbp->s_last_seq = cpu_to_le64(nilfs->ns_last_seq);
 	sbp->s_last_pseg = cpu_to_le64(nilfs->ns_last_pseg);
@@ -294,6 +298,8 @@ int nilfs_commit_super(struct super_block *sb, int flag)
 	struct nilfs_super_block **sbp = nilfs->ns_sbp;
 	time_t t;
 
+	pr_debug("NILFS: nilfs_commit_super: sb %#x, flags %x\n", sb, flag);
+
 	/* nilfs->ns_sem must be locked by the caller. */
 	t = get_seconds();
 	nilfs->ns_sbwtime = t;
diff --git a/fs/nilfs2/the_nilfs.c b/fs/nilfs2/the_nilfs.c
index 41e6a04..ceeaf9b 100644
--- a/fs/nilfs2/the_nilfs.c
+++ b/fs/nilfs2/the_nilfs.c
@@ -475,6 +475,12 @@ void nilfs_swap_super_block(struct the_nilfs *nilfs)
 	struct buffer_head *tsbh = nilfs->ns_sbh[0];
 	struct nilfs_super_block *tsbp = nilfs->ns_sbp[0];
 
+	pr_debug("NILFS: swap superblocks\n");
+	pr_debug("NILFS: nilfs->ns_sbp[0]->s_last_cno: %lld\n", le64_to_cpu(nilfs->ns_sbp[0]->s_last_cno));
+	pr_debug("NILFS: nilfs->ns_sbp[0]->s_last_pseg: %lld\n", le64_to_cpu(nilfs->ns_sbp[0]->s_last_pseg));
+	pr_debug("NILFS: nilfs->ns_sbp[1]->s_last_cno: %lld\n", le64_to_cpu(nilfs->ns_sbp[1]->s_last_cno));
+	pr_debug("NILFS: nilfs->ns_sbp[1]->s_last_pseg: %lld\n", le64_to_cpu(nilfs->ns_sbp[1]->s_last_pseg));
+
 	nilfs->ns_sbh[0] = nilfs->ns_sbh[1];
 	nilfs->ns_sbp[0] = nilfs->ns_sbp[1];
 	nilfs->ns_sbh[1] = tsbh;
-- 
1.7.9.5


[-- Attachment #3: 0002-nilfs2-debug-messages-for-log-validation-sequence-in.patch --]
[-- Type: text/x-patch, Size: 4852 bytes --]

From: Vyacheslav Dubeyko <slava-yeENwD64cLxBDgjK7y7TUQ@public.gmane.org>
Subject: [PATCH 2/2] nilfs2: debug messages for log validation sequence investigation

Add debug messages for log validation sequence investigation

Signed-off-by: Vyacheslav Dubeyko <slava-yeENwD64cLxBDgjK7y7TUQ@public.gmane.org>
---
 fs/nilfs2/recovery.c |   52 +++++++++++++++++++++++++++++++++++++++++++-------
 1 file changed, 45 insertions(+), 7 deletions(-)

diff --git a/fs/nilfs2/recovery.c b/fs/nilfs2/recovery.c
index 1e8b044..cb9dd62 100644
--- a/fs/nilfs2/recovery.c
+++ b/fs/nilfs2/recovery.c
@@ -841,19 +841,23 @@ int nilfs_search_super_root(struct the_nilfs *nilfs,
 
 	for (;;) {
 
-
-		pr_debug("NILFS: pseg_start %ld, seg_seq %lld\n", pseg_start, seg_seq);
+		pr_debug("NILFS: pseg_start %ld, seg_seq %lld\n",
+							pseg_start, seg_seq);
 		pr_debug("NILFS: cno %lld, segnum %lld\n", cno, segnum);
 		pr_debug("NILFS: nextnum %lld\n", nextnum);
 
 		brelse(bh_sum);
 		ret = NILFS_SEG_FAIL_IO;
 		bh_sum = nilfs_read_log_header(nilfs, pseg_start, &sum);
-		if (!bh_sum)
+		if (!bh_sum) {
+			pr_debug("NILFS: nilfs_read_log_header error\n");
 			goto failed;
+		}
 
 		ret = nilfs_validate_log(nilfs, seg_seq, bh_sum, sum);
 		if (ret) {
+			pr_debug("NILFS: nilfs_validate_log: err %d\n",
+					ret);
 			if (ret == NILFS_SEG_FAIL_IO)
 				goto failed;
 			goto strayed;
@@ -862,6 +866,9 @@ int nilfs_search_super_root(struct the_nilfs *nilfs,
 		nblocks = le32_to_cpu(sum->ss_nblocks);
 		pseg_end = pseg_start + nblocks - 1;
 		if (unlikely(pseg_end > seg_end)) {
+			pr_debug("NILFS: failed consistency\n");
+			pr_debug("NILFS: pseg_start %lld, nblocks %d\n",
+						pseg_start, nblocks);
 			ret = NILFS_SEG_FAIL_CONSISTENCY;
 			goto strayed;
 		}
@@ -877,6 +884,7 @@ int nilfs_search_super_root(struct the_nilfs *nilfs,
 
 		flags = le16_to_cpu(sum->ss_flags);
 		if (!(flags & NILFS_SS_SR) && !scan_newer) {
+			pr_debug("NILFS: !NILFS_SS_SR && !scan_newer\n");
 			/* This will never happen because a superblock
 			   (last_segment) always points to a pseg
 			   having a super root. */
@@ -897,10 +905,16 @@ int nilfs_search_super_root(struct the_nilfs *nilfs,
 			}
 			if (flags & NILFS_SS_LOGEND)
 				ri->ri_lsegs_end = pseg_start;
+
+			pr_debug("NILFS: !NILFS_SS_SR\n");
+
 			goto try_next_pseg;
 		}
 
 		/* A valid super root was found. */
+		pr_debug("NILFS: A valid super root was found\n");
+		pr_debug("NILFS: cno %lld, pseg_end %lld\n", cno, pseg_end);
+
 		ri->ri_cno = cno++;
 		ri->ri_super_root = pseg_end;
 		ri->ri_lsegs_start = ri->ri_lsegs_end = 0;
@@ -914,15 +928,28 @@ int nilfs_search_super_root(struct the_nilfs *nilfs,
 		nilfs->ns_ctime = le64_to_cpu(sum->ss_create);
 		nilfs->ns_nextnum = nextnum;
 
-		if (scan_newer)
+		if (scan_newer) {
+
+			pr_debug("NILFS: scan_newer -> need_recovery\n");
+
 			ri->ri_need_recovery = NILFS_RECOVERY_SR_UPDATED;
-		else {
-			if (nilfs->ns_mount_state & NILFS_VALID_FS)
+		} else {
+			if (nilfs->ns_mount_state & NILFS_VALID_FS) {
+
+				pr_debug("NILFS: NILFS_VALID_FS\n");
+				pr_debug("NILFS: super_root_found\n");
+
 				goto super_root_found;
+			} else {
+
+				pr_debug("NILFS: *not* NILFS_VALID_FS\n");
+
+			}
 			scan_newer = 1;
 		}
 
  try_next_pseg:
+		pr_debug("NILFS: try_next_pseg\n");
 		/* Standing on a course, or met an inconsistent state */
 		pseg_start += nblocks;
 		if (pseg_start < seg_end)
@@ -930,6 +957,7 @@ int nilfs_search_super_root(struct the_nilfs *nilfs,
 		goto feed_segment;
 
  strayed:
+		pr_debug("NILFS: strayed: scan_newer %d\n", scan_newer);
 		/* Off the trail */
 		if (!scan_newer)
 			/*
@@ -939,13 +967,16 @@ int nilfs_search_super_root(struct the_nilfs *nilfs,
 			goto failed;
 
  feed_segment:
+		pr_debug("NILFS: feed_segment: empty_seg %d\n", empty_seg);
 		/* Looking to the next full segment */
 		if (empty_seg++)
 			goto super_root_found; /* found a valid super root */
 
 		ret = nilfs_segment_list_add(&segments, segnum);
-		if (unlikely(ret))
+		if (unlikely(ret)) {
+			pr_debug("NILFS: nilfs_segment_list_add err %d\n", ret);
 			goto failed;
+		}
 
 		seg_seq++;
 		segnum = nextnum;
@@ -954,15 +985,22 @@ int nilfs_search_super_root(struct the_nilfs *nilfs,
 	}
 
  super_root_found:
+	pr_debug("NILFS: super_root_found\n");
+
 	/* Updating pointers relating to the latest checkpoint */
 	brelse(bh_sum);
 	list_splice_tail(&segments, &ri->ri_used_segments);
 	nilfs->ns_last_pseg = sr_pseg_start;
 	nilfs->ns_last_seq = nilfs->ns_seg_seq;
 	nilfs->ns_last_cno = ri->ri_cno;
+
+	pr_debug("NILFS: last_pseg %lld, last_seq %lld, last_cno %lld\n",
+				sr_pseg_start, nilfs->ns_seg_seq, ri->ri_cno);
+
 	return 0;
 
  failed:
+	pr_debug("NILFS: nilfs_search_super_root failed\n");
 	brelse(bh_sum);
 	nilfs_dispose_segment_list(&segments);
 	return (ret < 0) ? ret : nilfs_warn_segment_error(ret);
-- 
1.7.9.5