lfs_rename sometimes very slow

[kevinior]

I'm working on a system where we're logging data to LittleFS (v2.1.2). We periodically rotate the log by renaming the file. There's also some logging of debug and error messages going on in a similar way.

Usually the call to lfs_rename takes less than 100 ms but I've seen a pattern where the execution time slowly starts to increase. When it reaches about 250 ms it will usually drop back down to <100 ms but sometimes it instead suddenly takes 2 or 3 seconds.

I haven't been able to come up with a minimal test program that reproduces the behaviour. In our real application we use FreeRTOS and have a few tasks using the filesystem. There's a mutex controlling access to the filesystem, so only one task can perform LittleFS operations at a time. In fact there's only ever one file open at a time.

I've also timed the underlying flash operations (it's a Winbond W25Q64JV) and none of those are ever taking more than 100 ms.

So is this expected behaviour for lfs_rename and is there some way of tuning LittleFS so that this doesn't happen?

[kevinior]

I've tried suspending all other tasks during flash operation and suspending all other tasks during the lfs_rename but still saw the same problem in both cases.

[kevinior]

Our LittleFS configuration is:

#define CACHE_SIZE 16
#define LOOKAHEAD_SIZE 16
#define LFS_BLOCK_SIZE 4096

...

    // block device configuration
    .context = NULL,
    .read_size = 16,
    .prog_size = 16,
    .block_size = LFS_BLOCK_SIZE,
    .block_count = 1776,
    .block_cycles = 500,
    .cache_size = CACHE_SIZE,
    .lookahead_size = LOOKAHEAD_SIZE,
    .read_buffer = &ReadBuffer,
    .prog_buffer = &ProgBuffer,
    .lookahead_buffer = &LookAheadBuffer,
    .name_max = 0,
    .file_max = 0,
    .attr_max = 0

One thing that might unusual about what we're doing is that the log files are almost always very small when they're renamed, usually 112 bytes but sometimes up to 336. I'm assuming that means that the file data will be stored inline.

[geky]

Hi @kevinior thanks for reporting. Is it possible LittleFS is hitting a block allocation scan cycle?

I should add a debug statement, if it is it would be hitting this line:
https://github.com/ARMmbed/littlefs/blob/master/lfs.c#L468

If this is the case it's unfortunately an outstanding issue that we're working on but don't have a good fix for yet:
#75

You can try increasing the block_size to a multiple of the underlying device's block size. This may help as a short-term solution by reducing the number of logical blocks that need to be scanned when finding free blocks.

[kevinior]

Thanks for the reply @geky

I'm currently running a test with debug output at that line to check if that's what's happening in our case.

After that I'll try increasing the block_size.

Would there be any benefit for us in increasing lookahead_size? We can afford to exchange some more RAM for filesystem performance.

[kevinior]

I've just run a test where the problem was observed but didn't hit that line in lfs_alloc() https://github.com/ARMmbed/littlefs/blob/master/lfs.c#L468

Now I'll see if increasing the block_size helps.

[kevinior]

After increasing the block_size to 32 KB (which is the next size that's convenient for erasing blocks in the flash device we're using) I get behaviour that looks like this:

So we're not getting quite such high peaks in lfs_rename() times but both the peaks and the minimum times are gradually increasing.

[pjsg]

I can reproduce the slow rename issue using the test program with emubd and the settings from the test program. When it goes slow, it does more read i/o. Normally it reads less than 5k bytes to do a rename. When it takes a long time, this increases to > 50k bytes. The number of bytes programmed goes up a bit -- say from 50 to 150. [I'm using the bd.stats as the source of these numbers].

[genotix]

I have this issue too; mainly after doing a lot of writes and it appears as if the rename function is the only one that has issues.
Has anybody found a workaround yet or does anyone have some advice on how to deal with this?

I have switched from SPIFFS to LITTLEFS due to the performance but these hickups make my FreeRTOS have timing issues.

[jeroenbouma]

We are also seeing long lfs_rename execution times, same as described: normally very quick, but every 10-16 renames takes 2-3 minutes to complete. Lots of reads indeed, no errors that we've seen, it just takes forever. Any insights on what to try would be appreciated.

[kevinior]

@geky We changed our application so that we weren't renaming files as often but the problem has appeared again (it just takes longer to appear). We're now on LittleFS v2.3.

Are there any configuration tweaks that will help?

Our current configuration is:

const struct lfs_config LfsCfg = {
    .context = NULL,

    // block device operations
    .read  = blockDeviceRead,
    .prog  = blockDeviceProg,
    .erase = blockDeviceErase,
    .sync  = blockDeviceSync,

    .lock = lockDevice,
    .unlock = unlockDevice,

    // block device configuration
    .read_size = 16,
    .prog_size = 16,
    .block_size = LFS_BLOCK_SIZE,  // 4096
    .block_count = LFS_BLOCK_COUNT,  // 1776
    .block_cycles = 500,
    .cache_size = CACHE_SIZE,  // 16
    .lookahead_size = LOOKAHEAD_SIZE,  // 16
    .read_buffer = &ReadBuffer,
    .prog_buffer = &ProgBuffer,
    .lookahead_buffer = &LookAheadBuffer,
    .name_max = 0,
    .file_max = 0,
    .attr_max = 0
};

[kevinior]

It looks like (at least in our case) this is related to #376 .

I have a test program using rambd on Linux that creates a data directory (in /) and fills it with some files. Each time round the loop it (recursively) deletes any directories called trashX, renames the old data directory to trashX (X is a unique number) and creates a new data directory.

Using the settings in my previous comment I was seeing peaks where an lfs_rename took over 16000 reads, within the first 50 test iterations. Tweaking read_size, prog_size, lookahead_size and cache_size didn't have much beneficial effect.

After reading #376 I tried making sure that both the data directory and trashX directories were created in subdirectories rather than root. This dropped the peak read count for lfs_rename to less than 3000 in a run of 10000 test iterations. If I let the test run for 100000 iterations I eventually got a single peak at about iteration 42000.

[invoxiaamo]

We experience very long locking of the FS if we perform a single rename (more 12s)

The hardware is pretty solid:

ARM @ 250+ MHz
NOR spi @ 100 Mhz bus (octo SPI) - sector size in 4KB
FS size : 32 MB

littlefs version 2.4.1 (issue also existing on 2.2.0)
Zephyr OS (but doesn't matter here)

Too simplify the issue and reproduce easily.

erase the whole flash
mount littlefs
create 100 small files (256 bytes each)

Then in loop

open("test", FS_O_CREATE | FS_O_WRITE)
write(1024 bytes)
close()
rename("test", "test_rename")

Usually each rename of the loop requires 4000+ flash read operations (96K of data) and a single write, no erase.
BUT: every 33 loop, a single rename last 2s, requires ~300K flash read operations (4.7MB of data), a single sector erase, 7 writes.

... It looks to be a lot for a FS filled with 100 files and 26KB of data (the more files and/or data, the longer is the lock)

I will try to analyze what is done, but this scenario may sound a bell to the littlefs developers.
Arnaud

[invoxiaamo]

Hello.
If you are impacted by this issue, please get time to review #621 and see if I didn't miss a corner case.
Regards
Arnaud