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

What on Earth is JFFS2 GC doing?



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