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

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 [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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 [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Hi,

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

Thanks,
Ryusuke Konishi
---
From: Ryusuke Konishi <[email protected]>

nilfs_cleanerd: judge instantly deleted blocks as dead

---
 sbin/cleanerd/cleanerd.c |    3 +++
 1 files changed, 3 insertions(+), 0 deletions(-)

index b0a77fe..703b43c 100644
@@ -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 [email protected]
More majordomo info at  http://vger.kernel.org/majordomo-info.html

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 [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

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

--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

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

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.

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 [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

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

--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

I put them here: http://pastebin.com/8aHrkv7V

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 [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

Thanks, Ivan.

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 ?

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

Thanks,
Ryusuke Konishi

--
To unsubscribe from this list: send the line "unsubscribe linux-nilfs" in the body of a message to [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

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 [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html

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.

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 [email protected] More majordomo info at http://vger.kernel.org/majordomo-info.html