Re: Jffs2 and big file = very slow jffs2_garbage_collect_pass

[Matthieu CASTET <matthieu.castet@parrot.com>]

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

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

[-- Attachment #2: profile.txt --]
[-- Type: text/plain, Size: 1710 bytes --]

 54366 rb_prev                                  543,6600
 28345 rb_next                                  283,4500
  8602 default_idle                              71,6833
 10251 __raw_readsl                              40,0430
 49648 jffs2_get_inode_nodes                     11,8097
   251 s3c2412_nand_devready                      7,8438
  1222 crc32_le                                   4,8492
    58 __delay                                    4,8333
   164 touch_softlockup_watchdog                  4,1000
   245 nand_wait_ready                            2,7841
    78 s3c2440_nand_hwcontrol                     1,6250
    37 s3c2412_nand_enable_hwecc                  1,0278
    44 s3c2412_nand_calculate_ecc                 0,8462
    30 mutex_lock                                 0,7500
    65 kmem_cache_alloc                           0,6250
    12 down_read                                  0,6000
    13 __aeabi_uidivmod                           0,5417
   163 nand_read_page_hwecc                       0,4970
    53 s3c2412_nand_read_buf                      0,4907
    46 jffs2_lookup_node_frag                     0,4423
    24 s3c2412_clkcon_enable                      0,4286
    39 clk_disable                                0,3750
    10 __const_udelay                             0,3571
    39 clk_enable                                 0,3362
    18 strcmp                                     0,3214
    32 sysfs_dirent_exist                         0,2759
    33 __wake_up                                  0,2750
     9 mutex_unlock                               0,2500
    37 kmem_cache_free                            0,2202
   177 memcpy                                     0,2169