Re: Jffs2 and big file = very slow jffs2_garbage_collect_pass

Matthieu CASTET
2008-01-18T09:46:26Z

[-- 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