[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

Re: What on Earth is JFFS2 GC doing?



If the system is reset and then your tests continue do we still get 18
seconds at start?

If the filesystem is emptied do the numbers go back down?

Vipin Malik wrote:
> 
> Ok,
> I've been doing some more fun tests on JFFS2. In particular how long a
> task can get blocked if it tries to write to the JFFS2 fs.
> 
> I'm using JFFS2, cfi_cmdset_0002.c (on a AMD CFI compatable flash
> 29LV107B on a SC520 486 processor).
> 
> The following test was setup:
> A program was written to run as a POSIX RT task in the standard Linux
> kernel ver 2.4.1
> This task sets up an alarm every 100ms and in the alarm handler, it
> writes a given amount of data to a file on the JFFS2 fs.
> Every time it wakes up, it writes the "jitter" from the time it expected
> to wake up to the (serial) console where the data is logged to a file.
> 
> Additionally a script file is setup to copy a 3KB binary file to the
> same JFFS2 fs partition and then delete it. This is done every 3
> seconds.
> This causes "junk"data to be created on the fs that will cause bg GC.
> 
> This file also does a "df" and outputs the JFFS2 partition result to the
> console.
> The mtd driver was also modified to printk the address of any sector
> that is requested to be deleted.
> 
> The following are the synopsis of the results:
> 
> <time since last wakeup>     <"Jitter in ms"> ("!" marks new high value)
> 
> <SNIP>
>  99.420000 ms   -0.580000 ms
>  99.987000 ms   -0.013000 ms
>  110.035000 ms   10.035000 ms!
> /dev/mtdblock1            8192      1284      6908  16% /mnt/jffs1
> <--"16%" is blank JFFS2 fs!
>  99.950000 ms   -0.050000 ms
>  99.975000 ms   -0.025000 ms
> 
> <SNIP>
> 
>  100.132000 ms   0.132000 ms
> /dev/mtdblock1            8192      1672      6520  20% /mnt/jffs1
>  249.872000 ms   149.872000 ms!
>  159.991000 ms   59.991000 ms
>  109.999000 ms   9.999000 ms
>  140.067000 ms   40.067000 ms
>  139.999000 ms   39.999000 ms
>  119.933000 ms   19.933000 ms
>  130.080000 ms   30.080000 ms
>  99.978000 ms   -0.022000 ms
>  99.942000 ms   -0.058000 ms
>  99.957000 ms   -0.043000 ms
>  109.994000 ms   9.994000 ms
>  100.008000 ms   0.008000 ms
>  99.997000 ms   -0.003000 ms
>  100.020000 ms   0.020000 ms
> CHIP_ERASE:Erasing_at_address: 0x7c0000
>  2727.731000 ms   2627.731000 ms!  <--blocked 2.6seconds due to sector
> erase.
>  582.331000 ms   482.331000 ms
>  99.983000 ms   -0.017000 ms
> 
> <SNIP>
> 
>  100.000000 ms   0.000000 ms
>  100.000000 ms   0.000000 ms
> CHIP_ERASE:Erasing_at_address: 0x300000
>  3119.759000 ms   3019.759000 ms <--blocking time increasing with
> increasing usage.
>  620.302000 ms   520.302000 ms
>  100.005000 ms   0.005000 ms
>  109.979000 ms   9.979000 ms
>  100.065000 ms   0.065000 ms
> /dev/mtdblock1            8192      2364      5828  29% /mnt/jffs1
>  99.939000 ms   -0.061000 ms
>  99.947000 ms   -0.053000 ms
> 
> <SNIP>
> 
>  109.997000 ms   9.997000 ms
>  110.000000 ms   10.000000 ms
> CHIP_ERASE:Erasing_at_address: 0x500000
>  3183.600000 ms   3083.600000 ms!
>  616.491000 ms   516.491000 ms
>  99.985000 ms   -0.015000 ms
>  111.883000 ms   11.883000 ms
> /dev/mtdblock1            8192      3388      4804  41% /mnt/jffs1
>  188.048000 ms   88.048000 ms
>  99.995000 ms   -0.005000 ms
> 
> <SNIP>
> 
>  110.007000 ms   10.007000 ms
>  109.998000 ms   9.998000 ms
> CHIP_ERASE:Erasing_at_address: 0x6c0000
>  3195.940000 ms   3095.940000 ms!
>  584.113000 ms   484.113000 ms
>  110.005000 ms   10.005000 ms
>  109.991000 ms   9.991000 ms
>  119.996000 ms   19.996000 ms
> /dev/mtdblock1            8192      5156      3036  63% /mnt/jffs1
>  109.957000 ms   9.957000 ms
>  109.991000 ms   9.991000 ms
> 
> <SNIP>
> 
>  130.069000 ms   30.069000 ms
>  129.938000 ms   29.938000 ms
> CHIP_ERASE:Erasing_at_address: 0x200000
>  5131.391000 ms   5031.391000 ms!
>  588.602000 ms   488.602000 ms
>  110.025000 ms   10.025000 ms
>  109.985000 ms   9.985000 ms
>  140.004000 ms   40.004000 ms
>  109.996000 ms   9.996000 ms
> /dev/mtdblock1            8192      6096      2096  74% /mnt/jffs1
>  109.982000 ms   9.982000 ms
>  114.997000 ms   14.997000 ms
> 
> <SNIP>
> 
>  109.952000 ms   9.952000 ms
>  129.995000 ms   29.995000 ms
> CHIP_ERASE:Erasing_at_address: 0x780000
>  6969.470000 ms   6869.470000 ms!
> /dev/mtdblock1            8192      6520      1672  80% /mnt/jffs1
>  630.676000 ms   530.676000 ms
>  119.866000 ms   19.866000 ms
> 
> <SNIP>
> 
>  120.514000 ms   20.514000 ms
>  127.197000 ms   27.197000 ms
> CHIP_ERASE:Erasing_at_address: 0x780000
>  8694.196000 ms   8594.196000 ms!
>  618.173000 ms   518.173000 ms
>  109.948000 ms   9.948000 ms
>  109.981000 ms   9.981000 ms
>  115.573000 ms   15.573000 ms
>  114.427000 ms   14.427000 ms
> /dev/mtdblock1            8192      6508      1684  79% /mnt/jffs1
>  170.020000 ms   70.020000 ms
>  169.998000 ms   69.998000 ms
> 
> <SNIP>
> 
>  110.007000 ms   10.007000 ms
>  170.217000 ms   70.217000 ms
> /dev/mtdblock1            8192      6964      1228  85% /mnt/jffs1
>  113.095000 ms   13.095000 ms
>  166.734000 ms   66.734000 ms
> CHIP_ERASE:Erasing_at_address: 0x80000
>  11413.439000 ms   11313.439000 ms!
>  596.556000 ms   496.556000 ms
>  109.938000 ms   9.938000 ms
>  110.000000 ms   10.000000 ms
>  133.062000 ms   33.062000 ms
> /dev/mtdblock1            8192      6964      1228  85% /mnt/jffs1
>  137.145000 ms   37.145000 ms
>  149.799000 ms   49.799000 ms
> 
> <SNIP>
> 
>  144.125000 ms   44.125000 ms
>  162.037000 ms   62.037000 ms
> CHIP_ERASE:Erasing_at_address: 0x440000
>  15496.547000 ms   15396.547000 ms!
>  623.509000 ms   523.509000 ms
>  109.977000 ms   9.977000 ms
>  109.950000 ms   9.950000 ms
>  110.026000 ms   10.026000 ms
> /dev/mtdblock1            8192      7576       616  92% /mnt/jffs1
>  270.017000 ms   170.017000 ms
>  180.029000 ms   80.029000 ms
> 
> <SNIP>
> 
>  110.011000 ms   10.011000 ms
>  230.027000 ms   130.027000 ms
> /dev/mtdblock1            8192      7712       480  94% /mnt/jffs1
> CHIP_ERASE:Erasing_at_address: 0x3c0000
>  16910.777000 ms   16810.777000 ms!
>  599.180000 ms   499.180000 ms
>  110.007000 ms   10.007000 ms
> 
> <SNIP>
> /dev/mtdblock1            8192      7912       280  97% /mnt/jffs1
>  130.022000 ms   30.022000 ms
>  131.448000 ms   31.448000 ms
>  134.375000 ms   34.375000 ms
> CHIP_ERASE:Erasing_at_address: 0x200000
>  18051.887000 ms   17951.887000 ms!  <-- This is **17SECONDS!!** @~97%
> usage.
>  602.286000 ms   502.286000 ms
>  110.351000 ms   10.351000 ms
> 
> So, my question is: What on Earth is the JFFS2 fs doing that its
> blocking time is linearly proportional to the amount of disk usage.  We
> go from a a write "block" time of ~2.5secs to ~18secs on  an almost full
> fs.
> 
> As you can see, I'm outputting "CHIP_ERASE" messages. So it's obviously
> NOT erasing sectors for these 17seconds as the same sector can be erased
> in <2.5 seconds when the fs is less full?
> 
> Vipin
> 
> To unsubscribe from this list: send the line "unsubscribe jffs-dev" in
> the body of a message to majordomo@xxxxxxx.com

-- 
Tim Riker - http://rikers.org/ - short SIGs! <g>
All I need to know I could have learned in Kindergarten
... if I'd just been paying attention.

To unsubscribe from this list: send the line "unsubscribe jffs-dev" in
the body of a message to majordomo@xxxxxxx.com