Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

[dexen deVries]

Hi,


I had same problems as bryce and Łukasz Wójcicki described earlier:

[41045.664120] nilfs_ioctl_move_inode_block: conflicting node buffer: ino=79, cno=6, offset=0, blocknr=206010, vblocknr=94783
[41045.664129] NILFS: GC failed during preparation: cannot read source blocks: err=-17
and nilfs_cleanerd dies.


First round of digging indicates this can be reproduced by running two
nilfs_cleanerd instances at the same time.
I'm not sure if that was the original cause, but I'm going to investingate a bit more;
please hint me at what to pay attention to, if you would.


Regards,
-- 
dexen deVries

``One can't proceed from the informal to the formal by formal means.''
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

[Ivan Telichko]

Hi,

Same problem here, nilfs_cleanerd dies with these messages in system log:

  Apr 23 15:24:11 : nilfs_ioctl_move_inode_block: conflicting data buffer:
    ino=97606, cno=281, offset=14, blocknr=3526535, vblocknr=1555981
  Apr 23 15:24:11 : NILFS: GC failed during preparation: cannot read source
    blocks: err=-17

It happened after I had to reboot with Alt+SysRq (system suddenly locked up).
Then I booted SysRescueCD, mounted nilfs partition and found it filled up, but
nilfs_cleanerd was working. I left it working for some time, it managed to free
about 1.3Gb, but then died with error above. After that it does not start at
all. Removing all checkpoints changed nothing. Partition works fine, but space
is not freed anymore.

There were unusual messages in the system log just before forced reboot:

  Apr 22 09:26:39 : nilfs_palloc_freev: entry number 5381610 already freed
  Apr 22 09:26:39 : nilfs_palloc_freev: entry number 5381611 already freed
  Apr 22 09:26:39 : nilfs_palloc_freev: entry number 5381612 already freed
  Apr 22 09:26:41 : nilfs_sufile_do_free: segment 2342 is already clean
  Apr 22 09:26:41 : nilfs_sufile_do_free: segment 2343 is already clean
  Apr 22 09:26:41 : nilfs_sufile_do_free: segment 2344 is already clean
  Apr 22 09:26:41 : nilfs_sufile_do_free: segment 2345 is already clean
  ...same thing goes on for about 7 minutes, then system dies.

I am using nilfs-utils 2.0.21 on linux-2.6.32-gentoo-r7 with nilfs2 compiled in
the kernel, nilfs on root partition, with initramfs. Also, there were two
instances of nilfs_cleanerd started on system boot. I thought it was strange,
but harmless, so I ignored it.

---

Regards,
  Ivan Telichko


--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

[Ryusuke Konishi]

Hi,
On Fri, 22 Apr 2011 18:27:30 +0000 (UTC), Ivan Telichko wrote:
> Hi,
> 
> Same problem here, nilfs_cleanerd dies with these messages in system log:
> 
>   Apr 23 15:24:11 : nilfs_ioctl_move_inode_block: conflicting data buffer:
>     ino=97606, cno=281, offset=14, blocknr=3526535, vblocknr=1555981
>   Apr 23 15:24:11 : NILFS: GC failed during preparation: cannot read source
>     blocks: err=-17
> 
> It happened after I had to reboot with Alt+SysRq (system suddenly locked up).
> Then I booted SysRescueCD, mounted nilfs partition and found it filled up, but
> nilfs_cleanerd was working. I left it working for some time, it managed to free
> about 1.3Gb, but then died with error above. After that it does not start at
> all. Removing all checkpoints changed nothing. Partition works fine, but space
> is not freed anymore.

If you are still keeping the partition, could you test if the
following patch makes a difference ?

Thanks,
Ryusuke Konishi
---
From: Ryusuke Konishi <konishi.ryusuke-Zyj7fXuS5i5L9jVzuh4AOg@public.gmane.org>

nilfs_cleanerd: judge instantly deleted blocks as dead

Signed-off-by: Ryusuke Konishi <konishi.ryusuke-Zyj7fXuS5i5L9jVzuh4AOg@public.gmane.org>
---
 sbin/cleanerd/cleanerd.c |    3 +++
 1 files changed, 3 insertions(+), 0 deletions(-)

diff --git a/sbin/cleanerd/cleanerd.c b/sbin/cleanerd/cleanerd.c
index b0a77fe..703b43c 100644
--- a/sbin/cleanerd/cleanerd.c
+++ b/sbin/cleanerd/cleanerd.c
@@ -732,6 +732,9 @@ static int nilfs_vdesc_is_live(const struct nilfs_vdesc *vdesc,
 	long low, high, index;
 	int s;
 
+	if (vdesc->vd_period.p_end == vdesc->vd_period.p_start)
+		return 0;
+
 	if (vdesc->vd_period.p_end == NILFS_CNO_MAX ||
 	    vdesc->vd_period.p_end > protect)
 		return 1;
-- 
1.7.3.5

--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

[Ivan Telichko]

> If you are still keeping the partition, could you test if the
> following patch makes a difference ?

No observable difference, patched cleanerd still dies the same way.

There are more messages in the log if I start nilfs_cleanerd by hand:

  Apr 26 02:54:21 nilfs_cleanerd[4734]: start
  Apr 26 02:54:21 nilfs_cleanerd[4734]: pause (clean check)
  Apr 26 02:54:21 nilfs_cleanerd[4734]: resume (clean check)
  Apr 26 02:54:21 nilfs_cleanerd[4734]: ncleansegs = 244
  Apr 26 02:54:21 nilfs_cleanerd[4734]: 4 segments selected to be cleaned
  Apr 26 02:54:21 nilfs_cleanerd[4734]: protected checkpoints = [69325,69425]
    (protection period >= 1303760661)
  Apr 26 02:54:22 kernel: nilfs_ioctl_move_inode_block: conflicting data buffer:
    ino=97606, cno=281, offset=14, blocknr=3526535, vblocknr=1555981
  Apr 26 02:54:22 kernel: NILFS: GC failed during preparation: cannot read
    source blocks: err=-17
  Apr 26 02:54:23 nilfs_cleanerd[4734]: cannot clean segments: File exists
  Apr 26 02:54:23 nilfs_cleanerd[4734]: shutdown

---

Regards,
  Ivan Telichko

--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

[Ryusuke Konishi]

On Mon, 25 Apr 2011 05:28:10 +0000 (UTC), Ivan Telichko wrote:
> > If you are still keeping the partition, could you test if the
> > following patch makes a difference ?
> 
> No observable difference, patched cleanerd still dies the same way.
>
> There are more messages in the log if I start nilfs_cleanerd by hand:
> 
>   Apr 26 02:54:21 nilfs_cleanerd[4734]: start
>   Apr 26 02:54:21 nilfs_cleanerd[4734]: pause (clean check)
>   Apr 26 02:54:21 nilfs_cleanerd[4734]: resume (clean check)
>   Apr 26 02:54:21 nilfs_cleanerd[4734]: ncleansegs = 244
>   Apr 26 02:54:21 nilfs_cleanerd[4734]: 4 segments selected to be cleaned
>   Apr 26 02:54:21 nilfs_cleanerd[4734]: protected checkpoints = [69325,69425]
>     (protection period >= 1303760661)
>   Apr 26 02:54:22 kernel: nilfs_ioctl_move_inode_block: conflicting data buffer:
>     ino=97606, cno=281, offset=14, blocknr=3526535, vblocknr=1555981
>   Apr 26 02:54:22 kernel: NILFS: GC failed during preparation: cannot read
>     source blocks: err=-17
>   Apr 26 02:54:23 nilfs_cleanerd[4734]: cannot clean segments: File exists
>   Apr 26 02:54:23 nilfs_cleanerd[4734]: shutdown

Thanks,

According to the log, the same data block (i.e. blocks having the same
inode number, the same block offset, and the same checkpoint number)
appeared twice in a segment, and this causes a conflict of buffer on
GC page cache.

Umm, we need more information to narrow down this.

Could you take summaries of the segment 1721 and its adjacent segments ?

Summaries of a segment can be obtained as follows:

 # dumpseg /dev/sda6 1721
           ~~~~~~~~~
           your block device

where the segment 1721 contains the block 3526535 (a segment consists
of 2048 blocks by default).  It doesn't contain any user private data.


Regards,
Ryusuke Konishi

> ---
> 
> Regards,
>   Ivan Telichko
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

[Ivan Telichko]

It seems my reply was discarded, probably because it was too large. I
will try to use pastebin for summaries then.

> According to the log, the same data block (i.e. blocks having the same
> inode number, the same block offset, and the same checkpoint number)
> appeared twice in a segment, and this causes a conflict of buffer on
> GC page cache.

I tried to find blocks with same ino, cno and blkoff fields in one segment
with perl script. In 200 segments around 1721, there are about 1600 of
these, but none with ino=97606. Most of them (around 98%) have cno=0,
ino = one of 3,4,5.

Could you tell more about how bad blocks should look like? It is not
clear if blocks without blkoff=X or with level=X count as duplicates.

> Could you take summaries of the segment 1721 and its adjacent segments ?
> 
> Summaries of a segment can be obtained as follows:
> 
>  # dumpseg /dev/sda6 1721
>            ~~~~~~~~~
>            your block device
> 
> where the segment 1721 contains the block 3526535 (a segment consists
> of 2048 blocks by default).  It doesn't contain any user private data.

Here are summaries for blocks 1720,1721,1722:

  http://pastebin.com/vdC8WUWv

---

Regards,
  Ivan Telichko

--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

[Ryusuke Konishi]

On Tue, 26 Apr 2011 21:21:48 +0000 (UTC), Ivan Telichko wrote:
> It seems my reply was discarded, probably because it was too large. I
> will try to use pastebin for summaries then.
> 
> > According to the log, the same data block (i.e. blocks having the same
> > inode number, the same block offset, and the same checkpoint number)
> > appeared twice in a segment, and this causes a conflict of buffer on
> > GC page cache.
> 
> I tried to find blocks with same ino, cno and blkoff fields in one segment
> with perl script. In 200 segments around 1721, there are about 1600 of
> these, but none with ino=97606. Most of them (around 98%) have cno=0,
> ino = one of 3,4,5.
>
> Could you tell more about how bad blocks should look like? It is not
> clear if blocks without blkoff=X or with level=X count as duplicates.

The log says 4 segments were selected for GC at that time, so the
duplicated block would be present between segment 1718 and 1721 (if
exists).

Is there dumpseg data of the segment 1718 and 1719 ?

If the duplicated block exists, it will look like:

      finfo
        ino = 97606, cno = 281, nblocks = xx, ndatblk = xx
          ...
          vblocknr = xxxxxxx, blkoff = 14, blocknr = xxxxxxxx
          ...

B-tree node blocks, which appear without "blkoff = X" or with "level =
X", are irrelevant to this error.

Thanks,
Ryusuke Konishi
 
> > Could you take summaries of the segment 1721 and its adjacent segments ?
> > 
> > Summaries of a segment can be obtained as follows:
> > 
> >  # dumpseg /dev/sda6 1721
> >            ~~~~~~~~~
> >            your block device
> > 
> > where the segment 1721 contains the block 3526535 (a segment consists
> > of 2048 blocks by default).  It doesn't contain any user private data.
> 
> Here are summaries for blocks 1720,1721,1722:
> 
>   http://pastebin.com/vdC8WUWv
> 
> ---
> 
> Regards,
>   Ivan Telichko
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
> the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

[Ivan Telichko]

> Is there dumpseg data of the segment 1718 and 1719 ?

I put them here: http://pastebin.com/8aHrkv7V
 
> If the duplicated block exists, it will look like:
> 
>       finfo
>         ino = 97606, cno = 281, nblocks = xx, ndatblk = xx
>           ...
>           vblocknr = xxxxxxx, blkoff = 14, blocknr = xxxxxxxx
>           ...
> 

The first block in segment 1718 looks exactly like this. Is it wrong,
even if segments are different?

Also, I tried to change mc_nsegments_per_clean to 3 in
nilfs_cleanerd.conf. After that, cleanerd started and worked for
some time, but then died again. Now duplicate blocks were found
in segments 1363 and 1364. No free space was created in the
process.

---

Regards,
   Ivan Telichko


--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

[Ryusuke Konishi]

On Wed, 27 Apr 2011 09:27:59 +0000 (UTC), Ivan Telichko wrote:
> > Is there dumpseg data of the segment 1718 and 1719 ?
> 
> I put them here: http://pastebin.com/8aHrkv7V

Thanks, Ivan.

> > If the duplicated block exists, it will look like:
> > 
> >       finfo
> >         ino = 97606, cno = 281, nblocks = xx, ndatblk = xx
> >           ...
> >           vblocknr = xxxxxxx, blkoff = 14, blocknr = xxxxxxxx
> >           ...
> > 
> 
> The first block in segment 1718 looks exactly like this. Is it wrong,
> even if segments are different?

Yes, it's wrong.

Although garbage collection makes such situation transiently during
migration of live blocks, one of these segments must be marked invalid
on sufile (segment usage file).

I'm guessing a retry of writeback or garbage collection failure causes
this inconsistent situation.

How was the output of lssu command ?
 
> Also, I tried to change mc_nsegments_per_clean to 3 in
> nilfs_cleanerd.conf. After that, cleanerd started and worked for
> some time, but then died again. Now duplicate blocks were found
> in segments 1363 and 1364. No free space was created in the
> process.

Yes, decreasing mc_nsegments_per_clean may hide the error, but it
won't resolve the inconsistency.


Thanks,
Ryusuke Konishi

> ---
> 
> Regards,
>    Ivan Telichko
> 
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
> the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

[Ivan Telichko]

> How was the output of lssu command ?

Here: http://pastebin.com/DUn8UuvS

No difference between segments with
duplicates and normal ones in that output.
Only thing I can see here is that GC stopped
at segment 1363.
 
Is there any additional information I can
provide? Partition is filling up and will be
unusable in several days. I can keep image
of it if needed.

---

Regards,
    Ivan Telichko




--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: Regarding ``problem with nilfs_cleanerd - part 2'' and ``Nilfs_cleanerd err=-17''

[Ryusuke Konishi]

On Wed, 27 Apr 2011 12:29:20 +0000 (UTC), Ivan Telichko wrote:
> > How was the output of lssu command ?
> 
> Here: http://pastebin.com/DUn8UuvS
> 
> No difference between segments with
> duplicates and normal ones in that output.
> Only thing I can see here is that GC stopped
> at segment 1363.

Yeah, there are no erroneous segments.

Uum, after all, two nilfs_cleanerd instances seem to have caused this
duplication.  I will reconsider protection against the situation where
two or more cleaner daemons are invoked accidentaly.

> Is there any additional information I can
> provide? Partition is filling up and will be
> unusable in several days. I can keep image
> of it if needed.

OK, please reuse the partition for yourself.  We could get enough
information to narrow down the problem.

Thank you for your cooperation.

Ryusuke Konishi
--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html