Skip to content
New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

#

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

Jump to bottom

Writing files result in thousands of mmap calls #169

Open
timkoers opened this issue Jan 3, 2024 · 6 comments
Open

Writing files result in thousands of mmap calls #169

timkoers opened this issue Jan 3, 2024 · 6 comments

Comments

@timkoers
Copy link

timkoers commented Jan 3, 2024

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
Copy link
Member

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
Copy link
Author

timkoers commented Jan 3, 2024 •
edited
Loading

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
Copy link
Member

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
Copy link
Author

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
Copy link
Member

BrianPugh commented Jan 20, 2024 •
edited
Loading

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
Copy link
Author

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.

espressif/esp-idf#13023

# for free to join this conversation on GitHub. Already have an account? # to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@timkoers @BrianPugh