Writing files result in thousands of mmap calls

[timkoers]

I'm writing some files to the FS (about 200) and whenever I do so the console output gets flooded with V (548824) mmap: actual_mapped_len is 0x10000 logs.

I've traced this down to the esp_mmu_map.c:s_do_mapping function@410, but I assume that it's rather expensive to perform so many memory mappings.

Am I doing something wrong, do I have the wrong settings enabled in menuconfig?

Config:

#
# LittleFS
#
CONFIG_LITTLEFS_MAX_PARTITIONS=3
CONFIG_LITTLEFS_PAGE_SIZE=256
CONFIG_LITTLEFS_OBJ_NAME_LEN=64
CONFIG_LITTLEFS_READ_SIZE=128
CONFIG_LITTLEFS_WRITE_SIZE=128
CONFIG_LITTLEFS_LOOKAHEAD_SIZE=128
CONFIG_LITTLEFS_CACHE_SIZE=512
CONFIG_LITTLEFS_BLOCK_CYCLES=512
CONFIG_LITTLEFS_USE_MTIME=y
# CONFIG_LITTLEFS_USE_ONLY_HASH is not set
CONFIG_LITTLEFS_HUMAN_READABLE=y
CONFIG_LITTLEFS_MTIME_USE_SECONDS=y
# CONFIG_LITTLEFS_MTIME_USE_NONCE is not set
# CONFIG_LITTLEFS_SPIFFS_COMPAT is not set
# CONFIG_LITTLEFS_FLUSH_FILE_EVERY_WRITE is not set
CONFIG_LITTLEFS_FCNTL_GET_PATH=y
CONFIG_LITTLEFS_FCNTL_F_GETPATH_VALUE=20
# CONFIG_LITTLEFS_MULTIVERSION is not set
# end of LittleFS
# end of Component config

Log:

D (548814) Telephone: Opening filename
V (548814) esp_littlefs: Searching for existing filesystem for partition "s"
V (548814) esp_littlefs: Found existing filesystem "s" at index 0
V (548814) esp_littlefs: Opening filename
V (548814) esp_littlefs: O_WRONLY
V (548814) esp_littlefs: O_CREAT
V (548814) esp_littlefs: O_TRUNC
V (548814) esp_littlefs: ------------------------ Sem Taking [main]
V (548814) esp_littlefs: --------------------->>> Sem Taken [main]
V (548814) mmap: actual_mapped_len is 0x10000
V (548824) mmap: actual_mapped_len is 0x10000
V (548824) mmap: actual_mapped_len is 0x10000
V (548824) mmap: actual_mapped_len is 0x10000
V (548824) mmap: actual_mapped_len is 0x10000
V (548824) mmap: actual_mapped_len is 0x10000
V (548824) mmap: actual_mapped_len is 0x10000
V (548824) mmap: actual_mapped_len is 0x10000
V (548824) mmap: actual_mapped_len is 0x10000
V (548824) mmap: actual_mapped_len is 0x10000
V (548824) mmap: actual_mapped_len is 0x10000
V (548834) mmap: actual_mapped_len is 0x10000
V (548834) mmap: actual_mapped_len is 0x10000
V (548834) mmap: actual_mapped_len is 0x10000
V (548834) mmap: actual_mapped_len is 0x10000
V (548834) mmap: actual_mapped_len is 0x10000
V (548834) mmap: actual_mapped_len is 0x10000
V (548834) mmap: actual_mapped_len is 0x10000
V (548834) mmap: actual_mapped_len is 0x10000
V (548844) mmap: actual_mapped_len is 0x10000
V (548844) mmap: actual_mapped_len is 0x10000
V (548844) mmap: actual_mapped_len is 0x10000
V (548844) mmap: actual_mapped_len is 0x10000
V (548844) mmap: actual_mapped_len is 0x10000
V (548844) mmap: actual_mapped_len is 0x10000
V (548844) mmap: actual_mapped_len is 0x10000
V (548844) mmap: actual_mapped_len is 0x10000
V (548844) mmap: actual_mapped_len is 0x10000
V (548854) mmap: actual_mapped_len is 0x10000
V (548854) mmap: actual_mapped_len is 0x10000
V (548854) mmap: actual_mapped_len is 0x10000
V (548854) mmap: actual_mapped_len is 0x10000
V (548854) mmap: actual_mapped_len is 0x10000
V (548854) mmap: actual_mapped_len is 0x10000
V (548854) mmap: actual_mapped_len is 0x10000
V (548854) mmap: actual_mapped_len is 0x10000
V (548854) mmap: actual_mapped_len is 0x10000
V (548864) mmap: actual_mapped_len is 0x10000
V (548864) mmap: actual_mapped_len is 0x10000
V (548864) mmap: actual_mapped_len is 0x10000
V (548864) mmap: actual_mapped_len is 0x10000
V (548864) mmap: actual_mapped_len is 0x10000
V (548864) mmap: actual_mapped_len is 0x10000
V (548864) mmap: actual_mapped_len is 0x10000
V (548864) mmap: actual_mapped_len is 0x10000
V (548864) mmap: actual_mapped_len is 0x10000
V (548864) mmap: actual_mapped_len is 0x10000
V (548874) mmap: actual_mapped_len is 0x10000
V (548874) mmap: actual_mapped_len is 0x10000
V (548874) mmap: actual_mapped_len is 0x10000
V (548874) mmap: actual_mapped_len is 0x10000
V (548874) mmap: actual_mapped_len is 0x10000
V (548874) mmap: actual_mapped_len is 0x10000
V (548874) mmap: actual_mapped_len is 0x10000
V (548874) mmap: actual_mapped_len is 0x10000
V (548874) mmap: actual_mapped_len is 0x10000
V (548884) mmap: actual_mapped_len is 0x10000
V (548884) mmap: actual_mapped_len is 0x10000
V (548884) mmap: actual_mapped_len is 0x10000
V (548884) mmap: actual_mapped_len is 0x10000
V (548884) mmap: actual_mapped_len is 0x10000
V (548884) mmap: actual_mapped_len is 0x10000
V (548884) mmap: actual_mapped_len is 0x10000
V (548884) mmap: actual_mapped_len is 0x10000
V (548884) mmap: actual_mapped_len is 0x10000
V (548894) mmap: actual_mapped_len is 0x10000
V (548894) mmap: actual_mapped_len is 0x10000
V (548894) mmap: actual_mapped_len is 0x10000
V (548894) mmap: actual_mapped_len is 0x10000
V (548894) mmap: actual_mapped_len is 0x10000
V (548894) mmap: actual_mapped_len is 0x10000
V (548894) mmap: actual_mapped_len is 0x10000
V (548894) mmap: actual_mapped_len is 0x10000
V (548894) mmap: actual_mapped_len is 0x10000
V (548894) mmap: actual_mapped_len is 0x10000
V (548904) mmap: actual_mapped_len is 0x10000
V (548904) mmap: actual_mapped_len is 0x10000
V (548904) mmap: actual_mapped_len is 0x10000
V (548904) mmap: actual_mapped_len is 0x10000
V (548904) mmap: actual_mapped_len is 0x10000
V (548904) mmap: actual_mapped_len is 0x10000
V (548904) mmap: actual_mapped_len is 0x10000
V (548904) mmap: actual_mapped_len is 0x10000
V (548904) mmap: actual_mapped_len is 0x10000
V (548914) mmap: actual_mapped_len is 0x10000
V (548914) mmap: actual_mapped_len is 0x10000
V (548914) mmap: actual_mapped_len is 0x10000
V (548914) mmap: actual_mapped_len is 0x10000
V (548914) mmap: actual_mapped_len is 0x10000
V (548914) esp_littlefs: ------------------------ Sem Taking [main]
V (548914) esp_littlefs: --------------------->>> Sem Taken [main]
V (548914) mmap: actual_mapped_len is 0x10000
V (548924) mmap: actual_mapped_len is 0x10000
V (548924) mmap: actual_mapped_len is 0x10000
V (548924) mmap: actual_mapped_len is 0x10000
V (548924) mmap: actual_mapped_len is 0x10000
V (548924) mmap: actual_mapped_len is 0x10000
V (548924) mmap: actual_mapped_len is 0x10000
V (548924) mmap: actual_mapped_len is 0x10000
V (548924) mmap: actual_mapped_len is 0x10000
V (548924) mmap: actual_mapped_len is 0x10000
V (548924) mmap: actual_mapped_len is 0x10000
V (548934) mmap: actual_mapped_len is 0x10000
V (548934) mmap: actual_mapped_len is 0x10000
V (548934) mmap: actual_mapped_len is 0x10000
V (548934) mmap: actual_mapped_len is 0x10000
V (548934) mmap: actual_mapped_len is 0x10000
V (548934) mmap: actual_mapped_len is 0x10000
V (548934) mmap: actual_mapped_len is 0x10000
V (548934) mmap: actual_mapped_len is 0x10000
V (548934) mmap: actual_mapped_len is 0x10000
V (548944) mmap: actual_mapped_len is 0x10000
V (548944) mmap: actual_mapped_len is 0x10000
V (548944) mmap: actual_mapped_len is 0x10000
V (548944) mmap: actual_mapped_len is 0x10000
V (548944) mmap: actual_mapped_len is 0x10000
V (548944) mmap: actual_mapped_len is 0x10000
V (548944) mmap: actual_mapped_len is 0x10000
V (548944) mmap: actual_mapped_len is 0x10000
V (548944) mmap: actual_mapped_len is 0x10000
V (548954) mmap: actual_mapped_len is 0x10000
V (548954) mmap: actual_mapped_len is 0x10000
V (548954) mmap: actual_mapped_len is 0x10000
V (548954) mmap: actual_mapped_len is 0x10000
V (548954) mmap: actual_mapped_len is 0x10000
V (548954) mmap: actual_mapped_len is 0x10000
V (548954) mmap: actual_mapped_len is 0x10000
V (548954) mmap: actual_mapped_len is 0x10000
V (548954) mmap: actual_mapped_len is 0x10000
V (548964) mmap: actual_mapped_len is 0x10000
V (548964) mmap: actual_mapped_len is 0x10000
V (548964) mmap: actual_mapped_len is 0x10000
V (548964) mmap: actual_mapped_len is 0x10000
V (548964) mmap: actual_mapped_len is 0x10000
V (548964) mmap: actual_mapped_len is 0x10000
V (548964) mmap: actual_mapped_len is 0x10000
V (548964) mmap: actual_mapped_len is 0x10000
V (548964) mmap: actual_mapped_len is 0x10000
V (548974) mmap: actual_mapped_len is 0x10000
V (548974) mmap: actual_mapped_len is 0x10000
V (548974) mmap: actual_mapped_len is 0x10000
V (548974) mmap: actual_mapped_len is 0x10000
V (548974) mmap: actual_mapped_len is 0x10000
V (548974) mmap: actual_mapped_len is 0x10000
V (548974) mmap: actual_mapped_len is 0x10000
V (548974) mmap: actual_mapped_len is 0x10000
V (548974) mmap: actual
                       V (548994) mmap: actual_mapped_len is 0x10000
V (548994) mmap: actual_mapped_len is 0x10000
V (548994) mmap: actual_mapped_len is 0x10000
V (548994) mmap: actual_mapped_len is 0x10000
V (548994) mmap: actual_mapped_len is 0x10000
V (548994) mmap: actual_mapped_len is 0x10000
V (548994) mmap: actual_mapped_len is 0x10000
V (548994) mmap: actual_mapped_len is 0x10000
V (548994) mmap: actual_mapped_len is 0x10000
V (549004) mmap: actual_mapped_len is 0x10000
V (549004) mmap: actual_mapped_len is 0x10000
V (549004) mmap: actual_mapped_len is 0x10000
V (549004) mmap: actual_mapped_len is 0x10000
V (549004) mmap: actual_mapped_len is 0x10000
V (549004) mmap: actual_mapped_len is 0x10000
V (549004) mmap: actual_mapped_len is 0x10000
V (549004) mmap: actual_mapped_len is 0x10000
V (549004) mmap: actual_mapped_len is 0x10000
V (549014) mmap: actual_mapped_len is 0x10000
V (549014) mmap: actual_mapped_len is 0x10000
V (549014) mmap: actual_mapped_len is 0x10000
V (549014) mmap: actual_mapped_len is 0x10000
V (549014) mmap: actual_mapped_len is 0x10000
V (549014) esp_littlefs: ---------------------<<< Sem Give [main]
V (549014) esp_littlefs: ---------------------<<< Sem Give [main]
V (549014) esp_littlefs: Done opening /contacts/default/193.vcf
V (549024) esp_littlefs: ------------------------ Sem Taking [main]
V (549024) esp_littlefs: --------------------->>> Sem Taken [main]
V (549024) esp_littlefs: ------------------------ Sem Taking [main]
V (549024) esp_littlefs: --------------------->>> Sem Taken [main]
V (549034) mmap: actual_mapped_len is 0x10000
V (549034) esp_littlefs: ---------------------<<< Sem Give [main]
V (549034) esp_littlefs: ---------------------<<< Sem Give [main]
V (549034) esp_littlefs: ------------------------ Sem Taking [main]
V (549034) esp_littlefs: --------------------->>> Sem Taken [main]
V (549034) esp_littlefs: Clearing FD
V (549034) esp_littlefs: ---------------------<<< Sem Give [main]

[BrianPugh]

what version of esp-idf are you using? I haven't seen this message before, but I also haven't tested/experimented with more recent esp-idf versions.

[timkoers]

I'm using esp-idf 5.1.1.

I've disabled the flushing of the file to flash and the issue is still there.

[BrianPugh]

so I'm not actually sure if this is an issue, googling around doesn't surface much. I don't have knowledge of the inner workings of the esp-idf spi-flash drivers; this might just be business as usual. If you have any further insights, such as proof that the resulting operation is inefficient/bottlenecking, it would be much appreciated!

[timkoers]

The issue is that whenever ESP-IDF was configured to use encrypted read/writes, it needs to cache something, which is done through memory mapping, I guess

Checkout line 46 https://github.com/espressif/esp-idf/blob/b3f7e2c8a4d354df8ef8558ea7caddc07283a57b/components/esp_partition/partition_target.c#L46

[BrianPugh]

It might be worth opening up an issue in the esp-idf repo, I'm not sure of the performance implications, but it certainly seems out of the control of this repo.

[timkoers]

According to @igrr we could try and optimize this common use case, so that I'll map just once and not for every read operation.

https://github.com/espressif/esp-idf/issues/13023