Abnormal behavior with JFFS2 on latest kernel

Abnormal behavior with JFFS2 on latest kernel

[Kyungmin Park]

Hi,

I got following messages.
INFO: task pdflush:56 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

What are the meanings?
Too mush running GC in JFFS2 or others?

BR,
Kyungmin Park

/ # /mtd-utils/eraseall /dev/mtd4
/ # mount -t jffs2 /dev/mtdblock4 /jffs2
/ # iozone -A -s 128m -q 32k -U /jffs2 -f /jffs2/test -e
        Iozone: Performance Test of File I/O
                Version $Revision: 3.260 $
                Compiled for 32 bit mode.
                Build: linux-arm

	Run began: Fri Feb 15 15:39:56 2008

        Auto Mode 2. This option is obsolete. Use -az -i0 -i1
        File size set to 131072 KB
        Using Maximum Record Size 32 KB
        Include fsync in write timing
        Command line used: iozone -A -s 128m -q 32k -U /jffs2 -f /jffs2/test -e
        Output is in Kbytes/sec
        Time Resolution = 0.000030 seconds.
        Processor cache size set to 1024 Kbytes.
        Processor cache line size set to 32 bytes.
        File stride size set to 17 * record size.

              KB  reclen   write rewrite    read    reread
          131072       4    3708    3693    15294    15295
          131072       8    3736    3732    15482    15479
          131072      16INFO: task pdflush:56 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
pdflush       D c0216a1c     0    56      2
[<c0216680>] (schedule+0x0/0x41c) from [<c0216f68>] (io_schedule+0x2c/0x48)
[<c0216f3c>] (io_schedule+0x0/0x48) from [<c0063b54>] (sync_page+0x50/0x5c)
 r5:00000000 r4:c3c63c38
[<c0063b04>] (sync_page+0x0/0x5c) from [<c02172b8>] (__wait_on_bit_lock+0x60/0x)
[<c0217258>] (__wait_on_bit_lock+0x0/0x94) from [<c006469c>] (__lock_page+0x88/)
[<c0064614>] (__lock_page+0x0/0x98) from [<c00654ac>] (read_cache_page_async+0x)
 r5:00000000 r4:c03178c0
[<c006536c>] (read_cache_page_async+0x0/0x1b8) from [<c0124fcc>] (jffs2_gc_fetc)
[<c0124fa0>] (jffs2_gc_fetch_page+0x0/0x64) from [<c0121780>] (jffs2_garbage_co)
 r4:0682c000
[<c0120cd4>] (jffs2_garbage_collect_live+0x0/0x11ac) from [<c01225cc>] (jffs2_g)
[<c0121e80>] (jffs2_garbage_collect_pass+0x0/0x844) from [<c0126b18>] (jffs2_fl)
[<c0126a58>] (jffs2_flush_wbuf_gc+0x0/0x18c) from [<c0124bf8>] (jffs2_write_sup)
 r8:c3c63f40 r7:c02ae520 r6:c02aea94 r5:00000000 r4:c3d22a00
[<c0124bb4>] (jffs2_write_super+0x0/0x48) from [<c008a314>] (sync_supers+0x94/0)
 r5:c3d22c40 r4:c3d22c00
[<c008a280>] (sync_supers+0x0/0xd8) from [<c006b578>] (wb_kupdate+0x54/0x144)
 r6:c02a62d0 r5:c3c63fa0 r4:c3c63fac
[<c006b524>] (wb_kupdate+0x0/0x144) from [<c006c828>] (pdflush+0x118/0x1e8)
 r8:c02a62d0 r7:c02ae560 r6:c3c62000 r5:c3c63fa0 r4:c3c63fac
[<c006c710>] (pdflush+0x0/0x1e8) from [<c0050038>] (kthread+0x54/0x80)
 r8:00000000 r7:00000000 r6:00000000 r5:c006c710 r4:fffffffc
[<c004ffe4>] (kthread+0x0/0x80) from [<c003de0c>] (do_exit+0x0/0x66c)
 r5:00000000 r4:00000000
INFO: task iozone:219 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
iozone        D c0216a1c     0   219    215
[<c0216680>] (schedule+0x0/0x41c) from [<c02164d4>] (__down+0xa4/0xfc)
[<c0216430>] (__down+0x0/0xfc) from [<c02163cc>] (__down_failed+0xc/0x20)
 r8:c381ae00 r7:00000000 r6:c381adc0 r5:00000000 r4:0000682a
[<c01182b8>] (jffs2_write_begin+0x0/0x3c0) from [<c00660cc>] (generic_file_buff)
[<c0065fbc>] (generic_file_buffered_write+0x0/0x65c) from [<c0066e58>] (__gener)
[<c0066908>] (__generic_file_aio_write_nolock+0x0/0x580) from [<c0066f00>] (gen)
[<c0066e88>] (generic_file_aio_write+0x0/0xf4) from [<c008870c>] (do_sync_write)
[<c008865c>] (do_sync_write+0x0/0xf4) from [<c0088810>] (vfs_write+0xc0/0xf8)
 r8:c0020224 r7:c3c2ff78 r6:41200000 r5:c3d9a5e0 r4:00004000
[<c0088750>] (vfs_write+0x0/0xf8) from [<c0088904>] (sys_write+0x48/0x74)
 r7:00000004 r6:c3d9a5e0 r5:00000000 r4:06828000
[<c00888bc>] (sys_write+0x0/0x74) from [<c001fa20>] (ret_fast_syscall+0x0/0x2c)
 r6:00000000 r5:00004000 r4:00002000

Re: Abnormal behavior with JFFS2 on latest kernel

[Joakim Tjernlund]

On Fri, 2008-02-15 at 16:12 +0900, Kyungmin Park wrote:
> Hi,
> 
> I got following messages.
> INFO: task pdflush:56 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> 
> What are the meanings?
> Too mush running GC in JFFS2 or others?
> 
> BR,
> Kyungmin Park

It is probably erasing lots of blocks and that takes a while, minutes
some times. I once sent a patch to address this but the patch is racy
w.r.t module unload. Look in the archive after patches from me.

 Jocke

Re: Abnormal behavior with JFFS2 on latest kernel

[Artem Bityutskiy]

On Fri, 2008-02-15 at 16:12 +0900, Kyungmin Park wrote:
> I got following messages.
> INFO: task pdflush:56 blocked for more than 120 seconds.
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> 
> What are the meanings?
> Too mush running GC in JFFS2 or others?

Hi Kyungmin,

did not look at this, but off the top of my head this might be related
to the latest VFS changes (write_begin()/write_end() instead of
prepare_write()/commit_write()). Just a hint where you might try to
look.

-- 
Best regards,
Artem Bityutskiy (Битюцкий Артём)

RE: Abnormal behavior with JFFS2 on latest kernel

[Kyungmin Park]

> > I got following messages.
> > INFO: task pdflush:56 blocked for more than 120 seconds.
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >
> > What are the meanings?
> > Too mush running GC in JFFS2 or others?
> >
> > BR,
> > Kyungmin Park
> 
> It is probably erasing lots of blocks and that takes a while, minutes
> some times. I once sent a patch to address this but the patch is racy
> w.r.t module unload. Look in the archive after patches from me.
> 

You mean this one?
diff --git a/fs/jffs2/wbuf.c b/fs/jffs2/wbuf.c
index d1d4f27..b2e71c7 100644
--- a/fs/jffs2/wbuf.c
+++ b/fs/jffs2/wbuf.c
@@ -115,7 +115,7 @@ static inline void jffs2_refile_wbuf_blocks(struct jffs2_sb_

                D1(printk(KERN_DEBUG "Removing eraseblock at 0x%08x from erasabl
                list_del(this);
-               if ((jiffies + (n++)) & 127) {
+               if ((jiffies + (n++)) & 127 && !list_empty(&c->erasable_list)) {
                        /* Most of the time, we just erase it immediately. Other
                           spend ages scanning it on mount, etc. */
                        D1(printk(KERN_DEBUG "...and adding to erase_pending_lis

It's already applied, but it's same.

BR,
Kyungmin Park

RE: Abnormal behavior with JFFS2 on latest kernel

[Joakim Tjernlund]

On Fri, 2008-02-15 at 17:56 +0900, Kyungmin Park wrote:
> > > I got following messages.
> > > INFO: task pdflush:56 blocked for more than 120 seconds.
> > > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > >
> > > What are the meanings?
> > > Too mush running GC in JFFS2 or others?
> > >
> > > BR,
> > > Kyungmin Park
> > 
> > It is probably erasing lots of blocks and that takes a while, minutes
> > some times. I once sent a patch to address this but the patch is racy
> > w.r.t module unload. Look in the archive after patches from me.
> > 
> 
> You mean this one?
> diff --git a/fs/jffs2/wbuf.c b/fs/jffs2/wbuf.c
> index d1d4f27..b2e71c7 100644
> --- a/fs/jffs2/wbuf.c
> +++ b/fs/jffs2/wbuf.c
> @@ -115,7 +115,7 @@ static inline void jffs2_refile_wbuf_blocks(struct jffs2_sb_
> 
>                 D1(printk(KERN_DEBUG "Removing eraseblock at 0x%08x from erasabl
>                 list_del(this);
> -               if ((jiffies + (n++)) & 127) {
> +               if ((jiffies + (n++)) & 127 && !list_empty(&c->erasable_list)) {
>                         /* Most of the time, we just erase it immediately. Other
>                            spend ages scanning it on mount, etc. */
>                         D1(printk(KERN_DEBUG "...and adding to erase_pending_lis
> 
> It's already applied, but it's same.

Nope, the patch is probably named 
"[JFFS2] Stop erasing blocks when rebooting."

  Jocke

RE: Abnormal behavior with JFFS2 on latest kernel

[Kyungmin Park]

> On Fri, 2008-02-15 at 16:12 +0900, Kyungmin Park wrote:
> > I got following messages.
> > INFO: task pdflush:56 blocked for more than 120 seconds.
> > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >
> > What are the meanings?
> > Too mush running GC in JFFS2 or others?
> 
> Hi Kyungmin,
> 
> did not look at this, but off the top of my head this might be related
> to the latest VFS changes (write_begin()/write_end() instead of
> prepare_write()/commit_write()). Just a hint where you might try to
> look.
> 

Then can I use the ubifs? I mean ubifs is already changed for latest VFS changes.
Now I just want to test new driver with latest kernel.

Thank you,
Kyungmin Park

RE: Abnormal behavior with JFFS2 on latest kernel

[Artem Bityutskiy]

On Fri, 2008-02-15 at 18:02 +0900, Kyungmin Park wrote:
> > On Fri, 2008-02-15 at 16:12 +0900, Kyungmin Park wrote:
> > > I got following messages.
> > > INFO: task pdflush:56 blocked for more than 120 seconds.
> > > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> > >
> > > What are the meanings?
> > > Too mush running GC in JFFS2 or others?
> > 
> > Hi Kyungmin,
> > 
> > did not look at this, but off the top of my head this might be related
> > to the latest VFS changes (write_begin()/write_end() instead of
> > prepare_write()/commit_write()). Just a hint where you might try to
> > look.
> > 
> 
> Then can I use the ubifs? I mean ubifs is already changed for latest VFS changes.
> Now I just want to test new driver with latest kernel.

No, in opposite, we have not changed it yet. The old calls were not
removed from VFS and will be kept there for few releases. So we still
use them - this helps to use the same UBIFS sources for older kernels.
But later we'll switch to newer calls which are in fact much better for
UBIFS then the old ones.

But yes, you of course can use UBIFS.

-- 
Best regards,
Artem Bityutskiy (Битюцкий Артём)

RE: Abnormal behavior with JFFS2 on latest kernel

[Kyungmin Park]

> 
> Nope, the patch is probably named
> "[JFFS2] Stop erasing blocks when rebooting."
> 

No it's same; we have to find another one.

KB  reclen   write rewrite    read    reread
          131072       4    3420    3683    15320    15341
          131072       8INFO: task iozone:227 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
iozone        D c021685c     0   227    222
[<c02164c0>] (schedule+0x0/0x41c) from [<c0216314>] (__down+0xa4/0xfc)
[<c0216270>] (__down+0x0/0xfc) from [<c021620c>] (__down_failed+0xc/0x20)
 r8:c3815c70 r7:00000000 r6:c3815c30 r5:00000000 r4:00004078
[<c01182b8>] (jffs2_write_begin+0x0/0x3c0) from [<c00660cc>] (generic_file_buff)
[<c0065fbc>] (generic_file_buffered_write+0x0/0x65c) from [<c0066e58>] (__gener)
[<c0066908>] (__generic_file_aio_write_nolock+0x0/0x580) from [<c0066f00>] (gen)
[<c0066e88>] (generic_file_aio_write+0x0/0xf4) from [<c008870c>] (do_sync_write)
[<c008865c>] (do_sync_write+0x0/0xf4) from [<c0088810>] (vfs_write+0xc0/0xf8)
 r8:c0020224 r7:c3d5df78 r6:41200000 r5:c3d9a220 r4:00002000
[<c0088750>] (vfs_write+0x0/0xf8) from [<c0088904>] (sys_write+0x48/0x74)
 r7:00000004 r6:c3d9a220 r5:00000000 r4:04078000
[<c00888bc>] (sys_write+0x0/0x74) from [<c001fa20>] (ret_fast_syscall+0x0/0x2c)
 r6:00000000 r5:00002000 r4:00004000
INFO: task jffs2_gcd_mtd4:257 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
jffs2_gcd_mtd D c021685c     0   257      2
[<c02164c0>] (schedule+0x0/0x41c) from [<c0216da8>] (io_schedule+0x2c/0x48)
[<c0216d7c>] (io_schedule+0x0/0x48) from [<c0063b54>] (sync_page+0x50/0x5c)
 r5:00000000 r4:c3f07cb0
[<c0063b04>] (sync_page+0x0/0x5c) from [<c02170f8>] (__wait_on_bit_lock+0x60/0x)
[<c0217098>] (__wait_on_bit_lock+0x0/0x94) from [<c006469c>] (__lock_page+0x88/)
[<c0064614>] (__lock_page+0x0/0x98) from [<c00654ac>] (read_cache_page_async+0x)
 r5:00000000 r4:c0320ea0
[<c006536c>] (read_cache_page_async+0x0/0x1b8) from [<c0124fcc>] (jffs2_gc_fetc)
[<c0124fa0>] (jffs2_gc_fetch_page+0x0/0x64) from [<c0121758>] (jffs2_garbage_co)
 r4:0407a000
[<c0120cac>] (jffs2_garbage_collect_live+0x0/0x11ac) from [<c01225a4>] (jffs2_g)
[<c0121e58>] (jffs2_garbage_collect_pass+0x0/0x844) from [<c0123cb0>] (jffs2_ga)
[<c0123b88>] (jffs2_garbage_collect_thread+0x0/0x168) from [<c003de0c>] (do_exi)
 r8:00000000 r7:00000000 r6:00000000 r5:00000000 r4:00000000

Thank you,
Kyungmin Park

RE: Abnormal behavior with JFFS2 on latest kernel

[Joakim Tjernlund]

On Fri, 2008-02-15 at 18:35 +0900, Kyungmin Park wrote:
> > 
> > Nope, the patch is probably named
> > "[JFFS2] Stop erasing blocks when rebooting."
> > 
> 
> No it's same; we have to find another one.

OK, it was worth a try. Sorry but I don't have
any more ideas.

 Jocke