Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in 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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in 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