Hi,

Jörn Engel wrote:
> On Thu, 17 January 2008 17:12:29 +0100, Matthieu CASTET wrote:
>> we have a 240 MB jffs2 partition with summary enabled and no 
>> compression. We use 2ad8ee713566671875216ebcec64f2eda47bd19d git jffs2 
>> version 
>> (http://git.infradead.org/?p=mtd-2.6.git;a=commit;h=2ad8ee713566671875216ebcec64f2eda47bd19d)
>> If we do a ls without waiting that jffs2_garbage_collect_pass finish, ls 
>> takes 12 minutes to complete.
> 
> Impressive!  JFFS2 may be slow, but it shouldn't be _that_ slow.  Not
> sure who cares enough to look at this.  My approach would be to 
> $ echo t > /proc/sysrq_trigger
> several times during those 12 minutes and take a close look at the code
> paths showing up.  Most likely it will spend 99% of the time in one
> place.
I have a jtag debugger that allow me to know where the code take time.
When I mount the partition, thanks to the summary the mount is very 
short (less than 10s).

Then the garbage collector start to check nodes [1]. It spend 12 minutes 
in jffs2_garbage_collect_pass.

Then the system goes idle.

Then if I try to access the file [2]. It take 12 minutes to finish 
jffs2_lookup.

I have attached the result of booting with 'profile=1'. (HZ=200)

The code spend lot's of time in the rbtree code (7 minutes) and 4 
minutes in jffs2_get_inode_nodes.


Matthieu

[1]
#0  rb_next (node=0xc1c76e80) at lib/rbtree.c:325
#1  0xc00c5568 in jffs2_get_inode_nodes (c=0xc0a5a800, f=0xc0a5a200,
     rii=0xc1c19dbc) at fs/jffs2/readinode.c:317
#2  0xc00c59d4 in jffs2_do_read_inode_internal (c=0xc0a5a800, f=0xc0a5a200,
     latest_node=0xc1c19e14) at fs/jffs2/readinode.c:1124
#3  0xc00c63a0 in jffs2_do_crccheck_inode (c=0xc0a5a800, ic=0xc03993c8)
     at fs/jffs2/readinode.c:1379
#4  0xc00c9afc in jffs2_garbage_collect_pass (c=0xc0a5a800)
     at fs/jffs2/gc.c:208
#5  0xc00cc56c in jffs2_garbage_collect_thread (_c=<value optimized out>)
     at fs/jffs2/background.c:138
#6  0xc003766c in sys_waitid (which=19019, pid=20115456, infop=0x4a0e,
     options=-1044275912, ru=0x0) at kernel/exit.c:1634

[2]
#0  0xc00e8c14 in rb_prev (node=<value optimized out>) at lib/rbtree.c:368
#1  0xc00c5624 in jffs2_get_inode_nodes (c=0xc0a5a800, f=0xc1c16ca0,
     rii=0xc0fadbf4) at fs/jffs2/readinode.c:355
#2  0xc00c59d4 in jffs2_do_read_inode_internal (c=0xc0a5a800, f=0xc1c16ca0,
     latest_node=0xc0fadca8) at fs/jffs2/readinode.c:1124
#3  0xc00c6604 in jffs2_do_read_inode (c=0xc0a5a800, f=0xc1c16ca0, ino=165,
     latest_node=0xc0fadca8) at fs/jffs2/readinode.c:1364
#4  0xc00cd5c8 in jffs2_read_inode (inode=0xc1c16cd0) at fs/jffs2/fs.c:247
#5  0xc00c0204 in jffs2_lookup (dir_i=0xc1c16310, target=0xc1c0d0d8,
     nd=<value optimized out>) at include/linux/fs.h:1670
#6  0xc0080100 in do_lookup (nd=0xc0fadf08, name=0xc0fadd8c, 
path=0xc0fadd98)
     at fs/namei.c:494
#7  0xc0081e24 in __link_path_walk (name=0xc085300f "", nd=0xc0fadf08)
     at fs/namei.c:940
#8  0xc008245c in link_path_walk (name=0xc0853000 "/mnt/toto/media",
     nd=0xc0fadf08) at fs/namei.c:1011
#9  0xc00829b0 in do_path_lookup (dfd=<value optimized out>,
     name=0xc0853000 "/mnt/toto/media", flags=<value optimized out>,
     nd=0xc0fadf08) at fs/namei.c:1157