free_list / free_size messages

free_list / free_size messages

[Brian T]

Hi,

Since moving from JFFS2 2.1 to 2.2, I have noticed klog messages I didn't
see before.  It only seems to happen after a fresh flash when writing data
to the romfs.  sometimes I get a few messages, but this time I only got the
one:

Mar 10 12:07:25 klogd: Eep. Block 0x00120000 taken from free_list had
free_size of 0x00000038!!

It seems to recover, and I cannot find any corrupt files.  I see this error
also listed in the 2.1 source code, but never actually *got* the error
before.

Could someone explain what would cause it?  Sorry if this has been discussed
before, I didn't see anything on it when searching.

Thanks,

-Brian

Re: free_list / free_size messages

[Brian T]

Just wondering if anyone had some insight on this error message.

-Brian

> Since moving from JFFS2 2.1 to 2.2, I have noticed klog messages I didn't
> see before.  It only seems to happen after a fresh flash when writing data
> to the romfs.  sometimes I get a few messages, but this time I only got
the
> one:
>
> Mar 10 12:07:25 klogd: Eep. Block 0x00120000 taken from free_list had
> free_size of 0x00000038!!
>
> It seems to recover, and I cannot find any corrupt files.  I see this
error
> also listed in the 2.1 source code, but never actually *got* the error
> before.
>
> Could someone explain what would cause it?  Sorry if this has been
discussed
> before, I didn't see anything on it when searching.

Re: free_list / free_size messages

[David Woodhouse]

On Wed, 2004-03-10 at 12:12 -0600, Brian T wrote:
> Hi,
> 
> Since moving from JFFS2 2.1 to 2.2, I have noticed klog messages I didn't
> see before.  It only seems to happen after a fresh flash when writing data
> to the romfs.  sometimes I get a few messages, but this time I only got the
> one:
> 
> Mar 10 12:07:25 klogd: Eep. Block 0x00120000 taken from free_list had
> free_size of 0x00000038!!

I've no idea what could cause this; it's a sanity check which I don't
recall ever happening to anyone else. Can you run with a serial console
and CONFIG_JFFS2_FS_DEBUG=1, and with 'debug' on the kernel command
line. Log _everything_ it says, and hopefully it'll give us a clue.

-- 
dwmw2

Re: free_list / free_size messages

[Brad Campbell]

David Woodhouse wrote:
> On Wed, 2004-03-10 at 12:12 -0600, Brian T wrote:
>>Mar 10 12:07:25 klogd: Eep. Block 0x00120000 taken from free_list had
>>free_size of 0x00000038!!
> 
> 
> I've no idea what could cause this; it's a sanity check which I don't
> recall ever happening to anyone else. Can you run with a serial console
> and CONFIG_JFFS2_FS_DEBUG=1, and with 'debug' on the kernel command
> line. Log _everything_ it says, and hopefully it'll give us a clue.
> 

I have seen this a bit on my iPAQ 3800 with a familiar 2.4.19-hh36 kernel. I just guessed it was 
informative and I tend to ignore it. Should I try and reproduce it for debugging?

Regards,
Brad

Re: free_list / free_size messages

[David Woodhouse]

On Tue, 2004-03-16 at 08:46 +0400, Brad Campbell wrote:
> I have seen this a bit on my iPAQ 3800 with a familiar 2.4.19-hh36 kernel. I just guessed it was 
> informative and I tend to ignore it. Should I try and reproduce it for debugging?

Yes please. It should be harmless; it's just an accounting screwup. We
seem to have placed a block on the free_list which doesn't actually have
any significant amount of free space in it at all.

-- 
dwmw2

Re: free_list / free_size messages

[Brian T]

>
> Yes please. It should be harmless; it's just an accounting screwup. We
> seem to have placed a block on the free_list which doesn't actually have
> any significant amount of free space in it at all.
>
> -- 

I am limited to my debugging output, but here is what I caught from syslog
around the "eep".

Thanks for any help.

-Brian

Mar 17 11:34:28 klogd: <7>Node read from 0024702c: node_crc 2760a1ac,
calculated CRC 2760a1ac. dsize c, csize c, offset 0, buf c11bf9a0
Mar 17 11:34:28 klogd: <7>Node read from 0024702c: node_crc 2760a1ac,
calculated CRC 2760a1ac. dsize c, csize c, offset 0, buf c11bf9a0
Mar 17 11:34:28 klogd: <7>Node read from 0024702c: node_crc 2760a1ac,
calculated CRC 2760a1ac. dsize c, csize c, offset 0, buf c11bf9a0
Mar 17 11:34:28 klogd: <7>Node read from 0024702c: node_crc 2760a1ac,
calculated CRC 2760a1ac. dsize c, csize c, offset 0, buf c11bf9a0
Mar 17 11:34:28 klogd: <7>jffs2_prepare_write()
Mar 17 11:34:28 klogd: <7>end prepare_write(). pg->flags 41
Mar 17 11:34:28 klogd: <7>jffs2_commit_write(): ino #1051, page at 0x11000,
range 0-4096, flags 41
Mar 17 11:34:28 klogd: <7>jffs2_write_inode_range(): Ino #1051, ofs 0x11000,
len 0x1000
Mar 17 11:34:28 klogd: <7>jffs2_reserve_space(): Requested 0xc4 bytes
Mar 17 11:34:28 klogd: <7>jffs2_reserve_space(): alloc sem got
Mar 17 11:34:28 klogd: <7>jffs2_do_reserve_space(): Giving 0x494 bytes at
0x83fb6c
Mar 17 11:34:28 klogd: <7>calling deflate with avail_in 1092, avail_out 1092
Mar 17 11:34:28 klogd: <7>deflate returned with avail_in 0, avail_out 0,
total_in 1092, total_out 1092
Mar 17 11:34:28 klogd: <7>final deflate returned 0
Mar 17 11:34:28 klogd: <7>jffs2_add_physical_node_ref(): Node at
0x83fb6c(2), size 0x494
Mar 17 11:34:28 klogd: <7>Adding full erase block at 0x00820000 to
clean_list (free 0x00000000, dirty 0x00000000, used 0x0001f9f4
Mar 17 11:34:28 klogd: <7>jffs2_write_dnode wrote node at 0x0083fb6c(2) with
dsize 0x450, csize 0x450, node_crc 0x9cb7a611, data_crc 0x0600b9fb, totlen
0x00000494
Mar 17 11:34:28 klogd: <7>jffs2_add_full_dnode_to_inode(ino #1051, f
c0026780, fn c02f9520)
Mar 17 11:34:28 klogd: <7>jffs2_complete_reservation()
Mar 17 11:34:28 klogd: <7>jffs2_thread_should_wake(): nr_free_blocks 1,
nr_erasing_blocks 53, dirty_size 0x148: no
Mar 17 11:34:28 klogd: <7>increasing writtenlen by 1104
Mar 17 11:34:28 klogd: <7>jffs2_reserve_space(): Requested 0xc4 bytes
Mar 17 11:34:28 klogd: <7>jffs2_reserve_space(): alloc sem got
Mar 17 11:34:28 klogd: <4>Eep. Block 0x00120000 taken from free_list had
free_size of 0x00000034!!
Mar 17 11:34:28 klogd: <7>Adding full erase block at 0x00120000 to
clean_list (free 0x00000000, dirty 0x00000000, used 0x0001ffcc
Mar 17 11:34:28 klogd: <7>Starting erase of pending block 0x00900000
Mar 17 11:34:28 klogd: <7>Freeing all node refs for eraseblock offset
0x00900000
Mar 17 11:34:28 klogd: <7>Node read from 0024702c: node_crc 2760a1ac,
calculated CRC 2760a1ac. dsize c, csize c, offset 0, buf c11bf9a0
Mar 17 11:34:28 klogd: <7>Node read from 0024702c: node_crc 2760a1ac,
calculated CRC 2760a1ac. dsize c, csize c, offset 0, buf c11bf9a0
Mar 17 11:34:28 klogd: <7>Node read from 0024702c: node_crc 2760a1ac,
calculated CRC 2760a1ac. dsize c, csize c, offset 0, buf c11bf9a0

Re: free_list / free_size messages

[David Woodhouse]

On Wed, 2004-03-17 at 11:32 -0600, Brian T wrote:
> >
> > Yes please. It should be harmless; it's just an accounting screwup. We
> > seem to have placed a block on the free_list which doesn't actually have
> > any significant amount of free space in it at all.
> >
> > -- 
> 
> I am limited to my debugging output, but here is what I caught from syslog
> around the "eep".

That's not useful; we need to see what it was thinking at the time it
put it _on_ the list, not at the time it later takes it off and finds it
shouldn't have been there in the first place.

If you update to the current code, does it still happen?


-- 
dwmw2