[Ovmsdev] VFS / FAT deadlock
Mark Webb-Johnson
mark at webb-johnson.net
Sun Apr 8 22:00:58 HKT 2018
That timing issue on headless boot-up, with 3.1 hardware, seems to be a deadlock within Espressif vfs/fat.
I can repeat the issue by:
Create a script /store/events/sd.mounted/logging:
log file
log file /sd/ovms.log
log level verbose
log level info ssh
Unplug USB
Power up module from 12V supply
Any tasks accessing SD CARD will lock-up, sometime during the boot. Accessing other VFS areas seems ok.
Can re-connect USB and come in with terminal emulator, ten seconds or more after boot, to examine the stack/etc.
Here is the task status:
OVMS# module tasks stack
Number of Tasks = 16 Stack: Now Max Total Heap 32-bit SPIRAM
3FFAFB48 1 Blk esp_timer 388 548 4096 38080 644 21756
0x400dc0e3 0x4008ebed
3FFBDD5C 2 Blk eventTask 440 1208 4608 0 0 0
0x401b3814 0x4008ebed 0x401bcc06
3FFBFB58 3 Blk OVMS Events 1204 3812 6144 77388 0 6608
0x4008526a 0x4008ebed 0x4015e6b5 0x4008533c 0x401e2e53 0x40096a8c 0x4015eb7d 0x400e585a 0x400e6ece 0x400e4450 0x40085148 0x400eaec3 0x400eb768 0x400e9d1c 0x400ea6ec 0x400ea7f8 0x4008ebed 0x400ea808
3FFC4794 4 Blk OVMS CanRx 432 432 1024 0 0 0
0x400d39fd 0x4008ebed
3FFC884C 5 Blk ipc0 392 424 1024 7776 0 0
0x4008240b 0x4008ebed 0x400814fd
3FFC8E4C 6 Blk ipc1 392 504 1024 12 0 0
0x4008240b 0x4008ebed 0x40081590
3FFCAC74 9 Rdy IDLE 368 496 1024 0 0 0
0x4008fd60
3FFCB208 10 Rdy IDLE 356 484 1024 0 0 0
0x4008fd60 0x4008e0b7 0x4008e0b7
3FFCBF9C 11 Blk Tmr Svc 392 872 3072 0 0 168816
0x40090cdf 0x40090be4
3FFCF9F4 16 Blk tiT 492 700 3072 232 0 148
0x401fc049 0x4008ebed 0x40091ef6 0x401effe8 0x401f000c 0x401e7562 0x401e7562
3FFD5CA4 17 Blk OVMS SIMCOM 1584 2400 4096 284 0 0
0x4008526a 0x4008ebed 0x4015e6b5 0x4008533c 0x40000000 0x401e2e53 0x4015eb7d 0x400e585a 0x400e6ece 0x400e4450 0x40085148 0x40216acc 0x402177dc 0x401df626 0x401df4d5 0x401dfa38 0x401dfa8b 0x401e189e 0x401e2e69 0x4015eb7d 0x400e585a 0x400e6ece 0x400e4450 0x40085148 0x401379b5 0x400e58a1 0x40137a1b 0x40137a68
3FFD7C54 18 Blk wifi 432 1824 4096 240 0 1092
0x4008ab40 0x4008ebed
3FFDA3EC 19 Blk pmT 408 568 2560 0 0 0
0x401cb6c9 0x4008ebed 0x401cb751
3FFDAA04 20 Blk OVMS Vehicle 452 452 3072 0 0 0
0x4013ce45 0x4008ebed 0x4021f6e9
3FFDEC24 21 Rdy OVMS Console 760 3048 6144 220 15488 12000
0x400e6790 0x400f2a3b 0x400f6517 0x400f6585 0x400f2a72 0x400e9830 0x40197436 0x4021f01e 0x400e4508 0x400e986c 0x400e9a68 0x400e43ac 0x400e43bb 0x400f5280
3FFDF604 22 Blk mdns 412 412 4096 0 0 0
0x4020bae6 0x4008ebed
The interesting tasks are OVMS Events:
$ ~/esp/xtensa-esp32-elf/bin/xtensa-esp32-elf-addr2line -pfiaC -e build/ovms3.elf 0x4008526a 0x4008ebed 0x4015e6b5 0x4008533c 0x401e2e53 0x40096a8c 0x4015eb7d 0x400e585a 0x400e6ece 0x400e4450 0x40085148 0x400eaec3 0x400eb768 0x400e9d1c 0x400ea6ec 0x400ea7f8 0x4008ebed 0x400ea808
0x4008526a: lock_acquire_generic at /Users/mark/esp/esp-idf/components/newlib/./locks.c:157
0x4008ebed: xQueueGenericReceive at /Users/mark/esp/esp-idf/components/freertos/./queue.c:2037
0x4015e6b5: esp_vfs_write at /Users/mark/esp/esp-idf/components/vfs/./vfs.c:540
0x4008533c: _lock_acquire at /Users/mark/esp/esp-idf/components/newlib/./locks.c:165
0x401e2e53: vfs_fat_fsync at /Users/mark/esp/esp-idf/components/fatfs/src/vfs_fat.c:350
0x40096a8c: _fflush_r at /home/jeroen/esp8266/esp32/newlib_xtensa-2.2.0-bin/newlib_xtensa-2.2.0/xtensa-esp32-elf/newlib/libc/stdio/../../../.././newlib/libc/stdio/fflush.c:282
0x4015eb7d: fsync at /Users/mark/esp/esp-idf/components/vfs/./vfs.c:552 (discriminator 3)
0x400e585a: OvmsCommandApp::LogBuffer(LogBuffers*, char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e6ece: OvmsCommandApp::Log(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e4450: ConsoleAsync::ConsoleLogger(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./console_async.cpp:118
0x40085148: esp_log_write at /Users/mark/esp/esp-idf/components/log/./log.c:215
0x400eaec3: Housekeeping::Metrics(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_housekeeping.cpp:221
0x400eb768: std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_data() const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:135
(inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_is_local() const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:170
(inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_dispose() at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:179
(inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:544
(inlined by) void std::_Mem_fn_base<void (Housekeeping::*)(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*), true>::operator()<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*, void>(Housekeeping*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&&, void*&&) const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:600
(inlined by) void std::_Bind<std::_Mem_fn<void (Housekeeping::*)(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*)> (Housekeeping*, std::_Placeholder<1>, std::_Placeholder<2>)>::__call<void, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&&, void*&&, 0u, 1u, 2u>(std::tuple<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&&, void*&&>&&, std::_Index_tuple<0u, 1u, 2u>) at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:1074
(inlined by) void std::_Bind<std::_Mem_fn<void (Housekeeping::*)(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*)> (Housekeeping*, std::_Placeholder<1>, std::_Placeholder<2>)>::operator()<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*, void>(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&&, void*&&) at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:1133
(inlined by) std::_Function_handler<void (std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*), std::_Bind<std::_Mem_fn<void (Housekeeping::*)(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*)> (Housekeeping*, std::_Placeholder<1>, std::_Placeholder<2>)> >::_M_invoke(std::_Any_data const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >&&, void*&&) at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:1871
0x400e9d1c: std::function<void (std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*)>::operator()(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, void*) const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/functional:2271
0x400ea6ec: std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_data() const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:135
(inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_is_local() const at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:170
(inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::_M_dispose() at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:179
(inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >::~basic_string() at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/basic_string.h:544
(inlined by) OvmsEvents::HandleQueueSignalEvent(event_queue_t*) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_events.cpp:152
0x400ea7f8: OvmsEvents::EventTask() at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_events.cpp:126
0x4008ebed: xQueueGenericReceive at /Users/mark/esp/esp-idf/components/freertos/./queue.c:2037
0x400ea808: std::_Rb_tree<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> >, std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::__cxx11::list<EventCallbackEntry*, std::allocator<EventCallbackEntry*> >*>, std::_Select1st<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::__cxx11::list<EventCallbackEntry*, std::allocator<EventCallbackEntry*> >*> >, std::less<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, std::allocator<std::pair<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const, std::__cxx11::list<EventCallbackEntry*, std::allocator<EventCallbackEntry*> >*> > >::_M_get_insert_unique_pos(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) at /Users/mark/esp/xtensa-esp32-elf/xtensa-esp32-elf/include/c++/5.2.0/bits/stl_tree.h:1800
And OVMS SIMCOM:
$ ~/esp/xtensa-esp32-elf/bin/xtensa-esp32-elf-addr2line -pfiaC -e build/ovms3.elf 0x4008526a 0x4008ebed 0x4015e6b5 0x4008533c 0x40000000 0x401e2e53 0x4015eb7d 0x400e585a 0x400e6ece 0x400e4450 0x40085148 0x40216acc 0x402177dc 0x401df626 0x401df4d5 0x401dfa38 0x401dfa8b 0x401e189e 0x401e2e69 0x4015eb7d 0x400e585a 0x400e6ece 0x400e4450 0x40085148 0x401379b5 0x400e58a1 0x40137a1b 0x40137a68
0x4008526a: lock_acquire_generic at /Users/mark/esp/esp-idf/components/newlib/./locks.c:157
0x4008ebed: xQueueGenericReceive at /Users/mark/esp/esp-idf/components/freertos/./queue.c:2037
0x4015e6b5: esp_vfs_write at /Users/mark/esp/esp-idf/components/vfs/./vfs.c:540
0x4008533c: _lock_acquire at /Users/mark/esp/esp-idf/components/newlib/./locks.c:165
0x40000000: ?? ??:0
0x401e2e53: vfs_fat_fsync at /Users/mark/esp/esp-idf/components/fatfs/src/vfs_fat.c:350
0x4015eb7d: fsync at /Users/mark/esp/esp-idf/components/vfs/./vfs.c:552 (discriminator 3)
0x400e585a: OvmsCommandApp::LogBuffer(LogBuffers*, char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e6ece: OvmsCommandApp::Log(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e4450: ConsoleAsync::ConsoleLogger(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./console_async.cpp:118
0x40085148: esp_log_write at /Users/mark/esp/esp-idf/components/log/./log.c:215
0x40216acc: sdmmc_write_sectors_dma at /Users/mark/esp/esp-idf/components/sdmmc/./sdmmc_cmd.c:361 (discriminator 4)
0x402177dc: sdmmc_write_sectors at /Users/mark/esp/esp-idf/components/sdmmc/./sdmmc_cmd.c:750
0x401df626: ff_sdmmc_write at /Users/mark/esp/esp-idf/components/fatfs/src/diskio_sdmmc.c:51
0x401df4d5: ff_disk_write at /Users/mark/esp/esp-idf/components/fatfs/src/diskio.c:74
0x401dfa38: sync_window at /Users/mark/esp/esp-idf/components/fatfs/src/ff.c:4730
0x401dfa8b: move_window at /Users/mark/esp/esp-idf/components/fatfs/src/ff.c:4730
0x401e189e: f_sync at /Users/mark/esp/esp-idf/components/fatfs/src/ff.c:4730
0x401e2e69: vfs_fat_fsync at /Users/mark/esp/esp-idf/components/fatfs/src/vfs_fat.c:351
0x4015eb7d: fsync at /Users/mark/esp/esp-idf/components/vfs/./vfs.c:552 (discriminator 3)
0x400e585a: OvmsCommandApp::LogBuffer(LogBuffers*, char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e6ece: OvmsCommandApp::Log(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x400e4450: ConsoleAsync::ConsoleLogger(char const*, __va_list_tag) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./console_async.cpp:118
0x40085148: esp_log_write at /Users/mark/esp/esp-idf/components/log/./log.c:215
0x401379b5: simcom::Task() at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/components/simcom/src/simcom.cpp:88
0x400e58a1: OvmsCommandApp::HexDump(char const*, char const*, char const*, unsigned int, unsigned int) at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/main/./ovms_command.cpp:94
0x40137a1b: simcom::Task() at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/components/simcom/src/simcom.cpp:105
0x40137a68: simcom::State1Ticker1() at /Users/mark/Documents/ovms/Open-Vehicle-Monitoring-System-3/vehicle/OVMS.V3/components/simcom/src/simcom.cpp:523
The other tasks all look ok.
From what I can see, the task producing the log entry is dong a fsync, which presumably locks fat then locks vfs. Then another task tries to do a log as well, and gets locked up.
If I comment-out the fsync in OvmsCommandApp::LogBuffer of ovms_command.cpp (line 614), it seems to avoid the problem.
I’ve partially worked around the problem by introducing a mutex lock in ovms_command.cpp, when writing to the log file. That avoids the issue in ESP IDF. I’ve also raised it to Espressif.
* b38b0ef (HEAD -> master, origin/master, origin/HEAD)
Mutex protect fsync function call, on logging, to workaround ESP IDF bug
https://github.com/espressif/esp-idf/issues/1837
It is an ugly solution, and doesn’t seem 100% effective. I’m really not sure what is going on. Any ideas?
Regards, Mark.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openvehicles.com/pipermail/ovmsdev/attachments/20180408/f9f31462/attachment-0001.html>
More information about the OvmsDev
mailing list