Re: New experience with the odd problem starting nilfs_cleanerd due to an eMMC misbehaviour

[Paul Fertser <fercerpav-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org>]

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

On Thu, Jan 10, 2013 at 05:34:22PM +0400, Vyacheslav Dubeyko wrote:
> > On nilfs_cleanerd start i was consistently getting these messages:
> > [   46.122096] mmcblk0: error -110 transferring data, sector 26671630, nr 10, card status 0x200900
> > [   48.934623] mmcblk0: error -110 transferring data, sector 26671631, nr 9, card status 0x200900
> > (and similar output for two other sectors)
> > 
> > However, this time was different, several full power cycles didn't
> > help and the read was still failing and cleanerd refused to start.
> > 
> 
> Could you share system log content and strace of nilfs_cleanerd's trying
> to start in the case of the issue? It needs for the beginning of the
> issue understanding. Please, set in the nilfs_cleanerd.conf debug level.

Now I've took my time to gather all the info I could (and it wasn't
that easy to calculate the offsets, I have nilfs2 on an LVM volume on
a GPT disk:), LVM partition offset is 34816 sectors, 1st PE is 384
sectors inside the partition, the NILFS volume starts on the 256th PE)

This command produced error messages so I think the offset is right:
sudo dd if=/dev/mapper/emmc--lvm-rootfs of=rawdump_2713.bin bs=$((4096*2048)) count=1 skip=2713

[ 5142.730071] mmcblk0: retrying using single block read
[ 5145.599122] mmcblk0: error -110 transferring data, sector 46594382, nr 434, card status 0x200900
[ 5145.624308] end_request: I/O error, dev mmcblk0, sector 46594382
[ 5148.442955] mmcblk0: error -110 transferring data, sector 46594383, nr 433, card status 0x200900
[ 5148.467911] end_request: I/O error, dev mmcblk0, sector 46594383
[ 5148.489628] Buffer I/O error on device dm-0, logical block 5557753
[ 5151.436927] mmcblk0: error -110 transferring data, sector 46594574, nr 242, card status 0x200900
[ 5151.462374] end_request: I/O error, dev mmcblk0, sector 46594574
[ 5154.286162] mmcblk0: error -110 transferring data, sector 46594575, nr 241, card status 0x200900
[ 5154.311555] end_request: I/O error, dev mmcblk0, sector 46594575
[ 5154.333388] Buffer I/O error on device dm-0, logical block 5557777

Attaching dumpseg output for segment 2713, strace for nilfs_cleanerd,
etc, HTH.

Thank you in advance!
-- 
Be free, use free (http://www.gnu.org/philosophy/free-sw.html) software!
mailto:fercerpav-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org

[-- Attachment #2: dumpseg_2713.txt.bz2 --]
[-- Type: application/octet-stream, Size: 12943 bytes --]

[-- Attachment #3: lssu.txt.bz2 --]
[-- Type: application/octet-stream, Size: 13342 bytes --]

[-- Attachment #4: nilfs_tune_l.txt --]
[-- Type: text/plain, Size: 1030 bytes --]

nilfs-tune 2.1.0
Filesystem volume name:	  (none)
Filesystem UUID:	  822e1c89-0714-42e7-9f5c-2a11234cec85
Filesystem magic number:  0x3434
Filesystem revision #:	  2.0
Filesystem features:      (none)
Filesystem state:	  invalid or mounted
Filesystem OS type:	  Linux
Block size:		  4096
Filesystem created:	  Sat Jan 14 12:43:52 2012
Last mount time:	  Sun Jun 30 10:08:09 2013
Last write time:	  Sun Jun 30 11:01:35 2013
Mount count:		  403
Maximum mount count:	  50
Reserve blocks uid:	  0 (user root)
Reserve blocks gid:	  0 (group root)
First inode:		  11
Inode size:		  128
DAT entry size:		  32
Checkpoint size:	  192
Segment usage size:	  16
Number of segments:	  3685
Device size:		  30916214784
First data block:	  1
# of blocks per segment:  2048
Reserved segments %:	  5
Last checkpoint #:	  470550
Last block address:	  4689935
Last sequence #:	  35454
Free blocks count:	  862208
Commit interval:	  0
# of blks to create seg:  0
CRC seed:		  0x08347184
CRC check sum:		  0x6969faa9
CRC check data size:	  0x00000118

[-- Attachment #5: syslog.bz2 --]
[-- Type: application/octet-stream, Size: 11175 bytes --]

[-- Attachment #6: cleanerd_debug_log.txt.bz2 --]
[-- Type: application/octet-stream, Size: 3454 bytes --]

[-- Attachment #7: daemon_debug.log --]
[-- Type: text/plain, Size: 1727 bytes --]

Jun 30 10:22:33 ac100-debian wpa_supplicant[1149]: WPA: Group rekeying completed with 00:27:19:ce:3b:ce [GTK=TKIP]
Jun 30 10:32:33 ac100-debian wpa_supplicant[1149]: WPA: Group rekeying completed with 00:27:19:ce:3b:ce [GTK=TKIP]
Jun 30 10:34:56 ac100-debian nilfs_cleanerd[1908]: start
Jun 30 10:34:56 ac100-debian nilfs_cleanerd[1908]: pause (clean check)
Jun 30 10:34:56 ac100-debian nilfs_cleanerd[1908]: resume (clean check)
Jun 30 10:34:56 ac100-debian nilfs_cleanerd[1908]: ncleansegs = 428
Jun 30 10:34:56 ac100-debian nilfs_cleanerd[1908]: 4 segments selected to be cleaned
Jun 30 10:34:56 ac100-debian nilfs_cleanerd[1908]: cannot clean segments: File exists
Jun 30 10:34:56 ac100-debian nilfs_cleanerd[1908]: shutdown
Jun 30 10:35:34 ac100-debian nilfs_cleanerd[1914]: start
Jun 30 10:35:34 ac100-debian nilfs_cleanerd[1914]: pause (clean check)
Jun 30 10:35:34 ac100-debian nilfs_cleanerd[1914]: resume (clean check)
Jun 30 10:35:34 ac100-debian nilfs_cleanerd[1914]: ncleansegs = 428
Jun 30 10:35:34 ac100-debian nilfs_cleanerd[1914]: 4 segments selected to be cleaned
Jun 30 10:35:34 ac100-debian nilfs_cleanerd[1914]: cannot clean segments: File exists
Jun 30 10:35:34 ac100-debian nilfs_cleanerd[1914]: shutdown
Jun 30 10:38:37 ac100-debian nilfs_cleanerd[2011]: start
Jun 30 10:38:37 ac100-debian nilfs_cleanerd[2011]: pause (clean check)
Jun 30 10:38:37 ac100-debian nilfs_cleanerd[2011]: resume (clean check)
Jun 30 10:38:37 ac100-debian nilfs_cleanerd[2011]: ncleansegs = 428
Jun 30 10:38:37 ac100-debian nilfs_cleanerd[2011]: 4 segments selected to be cleaned
Jun 30 10:38:37 ac100-debian nilfs_cleanerd[2011]: cannot clean segments: File exists
Jun 30 10:38:37 ac100-debian nilfs_cleanerd[2011]: shutdown