FPU registers not properly switched for ESP32-S3 (IDFGH-10439)

[NaivelyWritten]

Answers checklist.

• I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
• I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
• I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

5.1-rc1

Operating System used.

macOS

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

None

Development Kit.

ESP32-S3-MINI1N8

Power Supply used.

USB

What is the expected behavior?

FPU registers properly filled at context switch.

What is the actual behavior?

race condition where sometimes the FPU registers stay the same.

Steps to reproduce.

This behavior depends heavily on internal code but I can describe the problem:

I have a quite similar issue recently with an assertion in fmtlib hits which checks for wrong signs of a float value. However in a previous function this value has been set with a non-negative value. And upon more checking it revealed that this negative value is the register content of another thread. This indicates that the FPU context switch is indeed not done correctly (in IDF v5.1-rc).

Debug Logs.

++
R, 2219316183, dc:54:75:c2:00:10:00:00, 45.34956
I, 2219316638,    -488.4880,    +867.1760,      +2.1960,   +0.00489,   -0.00611,   -0.00122
R, 2219318006, 60:55:f9:f5:7f:b0:00:00, 38.438126

abort() was called at PC 0x42029603 on core 0
0x42029603: __cxxabiv1::__terminate(void (*)()) at /Users/brnomac003/.gitlab-runner/builds/qR2TxTby/1/idf/crosstool-NG/.build/xtensa-esp32s3-elf/src/gcc/libstdc++-v3/libsupc++/eh_terminate.cc:48



Backtrace: 0x40375c2a:0x3fca2cd0 0x4037bf91:0x3fca2cf0 0x4038256e:0x3fca2d10 0x42029603:0x3fca2d80 0x42029638:0x3fca2da0 0x420085cf:0x3fca2dc0 0x4200e353:0x3fca2de0 0x42010cad:0x3fca2e90 0x420113c7:0x3fca3110 0x4201393b:0x3fca3280 0x4037e8cd:0x3fca3470
0x40375c2a: panic_abort at /Users/<redacted>/esp/esp-idf/components/esp_system/panic.c:452

0x4037bf91: esp_system_abort at /Users/<redacted>/esp/esp-idf/components/esp_system/port/esp_system_chip.c:84

0x4038256e: abort at /Users/<redacted>/esp/esp-idf/components/newlib/abort.c:38

0x42029603: __cxxabiv1::__terminate(void (*)()) at /Users/brnomac003/.gitlab-runner/builds/qR2TxTby/1/idf/crosstool-NG/.build/xtensa-esp32s3-elf/src/gcc/libstdc++-v3/libsupc++/eh_terminate.cc:48

0x42029638: std::terminate() at /Users/brnomac003/.gitlab-runner/builds/qR2TxTby/1/idf/crosstool-NG/.build/xtensa-esp32s3-elf/src/gcc/libstdc++-v3/libsupc++/eh_terminate.cc:58

0x420085cf: fmt::v10::detail::assert_fail(char const*, int, char const*) at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/format-inl.h:36

0x4200e353: int fmt::v10::detail::format_float<double>(double, int, fmt::v10::detail::float_specs, fmt::v10::detail::buffer<char>&) at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/format.h:3494 (discriminator 1)

0x42010cad: std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > fmt::v10::detail::write_float<char, std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, float>(std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, float, fmt::v10::format_specs<char>, fmt::v10::detail::locale_ref) at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/format.h:3861 (discriminator 1)

0x420113c7: std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > fmt::v10::detail::write<char, std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, float, 0>(std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, float, fmt::v10::format_specs<char>, fmt::v10::detail::locale_ref) at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/format.h:3874
 (inlined by) decltype (({parm#2}.out)()) fmt::v10::formatter<float, char, void>::format<fmt::v10::basic_format_context<std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, char> >(float const&, fmt::v10::basic_format_context<std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, char>&) const at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/format.h:4723
 (inlined by) decltype (({parm#2}.out)()) fmt::v10::formatter<fmt::v10::join_view<float*, float*, char>, char, void>::format<fmt::v10::basic_format_context<std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, char> >(fmt::v10::join_view<float*, float*, char> const&, fmt::v10::basic_format_context<std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, char>&) const at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/format.h:4476

0x4201393b: std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 2>::format<std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long, fmt::v10::join_view<float*, float*, char>, fmt::v10::join_view<float*, float*, char> >(std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long const&, fmt::v10::join_view<float*, float*, char> const&, fmt::v10::join_view<float*, float*, char> const&) const at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/compile.h:273
 (inlined by) std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 2>, fmt::v10::detail::code_unit<char> >::format<std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long, fmt::v10::join_view<float*, float*, char>, fmt::v10::join_view<float*, float*, char> >(std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long const&, fmt::v10::join_view<float*, float*, char> const&, fmt::v10::join_view<float*, float*, char> const&) const at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/compile.h:287
 (inlined by) std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 2>, fmt::v10::detail::code_unit<char> > >::format<std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long, fmt::v10::join_view<float*, float*, char>, fmt::v10::join_view<float*, float*, char> >(std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long const&, fmt::v10::join_view<float*, float*, char> const&, fmt::v10::join_view<float*, float*, char> const&) const at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/compile.h:288
 (inlined by) std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 1>, fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 2>, fmt::v10::detail::code_unit<char> > > >::format<std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long, fmt::v10::join_view<float*, float*, char>, fmt::v10::join_view<float*, float*, char> >(std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long const&, fmt::v10::join_view<float*, float*, char> const&, fmt::v10::join_view<float*, float*, char> const&) const at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/compile.h:288
 (inlined by) std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 1>, fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 2>, fmt::v10::detail::code_unit<char> > > > >::format<std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long, fmt::v10::join_view<float*, float*, char>, fmt::v10::join_view<float*, float*, char> >(std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long const&, fmt::v10::join_view<float*, float*, char> const&, fmt::v10::join_view<float*, float*, char> const&) const at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/compile.h:288
 (inlined by) std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > fmt::v10::detail::concat<fmt::v10::detail::field<char, long long, 0>, fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 1>, fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 2>, fmt::v10::detail::code_unit<char> > > > > >::format<std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long, fmt::v10::join_view<float*, float*, char>, fmt::v10::join_view<float*, float*, char> >(std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long const&, fmt::v10::join_view<float*, float*, char> const&, fmt::v10::join_view<float*, float*, char> const&) const at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/compile.h:288
 (inlined by) std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > > fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::field<char, long long, 0>, fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 1>, fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 2>, fmt::v10::detail::code_unit<char> > > > > > >::format<std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long, fmt::v10::join_view<float*, float*, char>, fmt::v10::join_view<float*, float*, char> >(std::back_insert_iterator<std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > >, long long const&, fmt::v10::join_view<float*, float*, char> const&, fmt::v10::join_view<float*, float*, char> const&) const at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/compile.h:288
 (inlined by) std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > fmt::v10::format<fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::field<char, long long, 0>, fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 1>, fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 2>, fmt::v10::detail::code_unit<char> > > > > > >, long long, fmt::v10::join_view<float*, float*, char>, fmt::v10::join_view<float*, float*, char>, char, 0>(fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::field<char, long long, 0>, fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 1>, fmt::v10::detail::concat<fmt::v10::detail::text<char>, fmt::v10::detail::concat<fmt::v10::detail::spec_field<char, fmt::v10::join_view<float*, float*, char>, 2>, fmt::v10::detail::code_unit<char> > > > > > > const&, long long const&, fmt::v10::join_view<float*, float*, char> const&, fmt::v10::join_view<float*, float*, char> const&) at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/compile.h:510
 (inlined by) format<imu_task(void*)::<lambda()>::FMT_COMPILE_STRING, long long int, fmt::v10::join_view<float*, float*, char>, fmt::v10::join_view<float*, float*, char> > at /Users/<redacted>/project_fw/esp_fw/s3_fw/cxxsp_component/fmtlib/fmt/include/fmt/compile.h:544
 (inlined by) imu_task(void*) at /Users/<redacted>/project_fw/esp_fw/s3_fw/main/imu_task.cpp:258

0x4037e8cd: vPortTaskWrapper at /Users/<redacted>/esp/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

More Information.

Similar to #11225

[NaivelyWritten]

a pair of vTaskSuspendAll() and xTaskResumeAll() calls fixed the issue immediately, so it's definitely something related to a context switch.

[NaivelyWritten]

Since the context switch is caused by an interrupt I suspect portYIELD_FROM_ISR is not FPU-safe.

[tmiw]

I think I'm running into this issue with my own project as well. It manifests itself as mainly assertion failures in the library I'm using (Codec2). An example of such a failure is below:

assert failed: ofdm_esno_est_calc ofdm.c:1891 (isnan(EsNodB) == 0)


Backtrace: 0x40375fc6:0x3fccfdd0 0x40380bfd:0x3fccfdf0 0x4038870e:0x3fccfe10 0x42059fa7:0x3fccff30 0x4205a158:0x3fccff70 0x4204fece:0x3fccffa0 0x4204eebc:0x3fcd1330 0x4204ef86:0x3fcd1350 0x4200dc8e:0x3fcd1380 0x4201f12b:0x3fcd2950 0x4201f141:0x3fcd2970 0x40384141:0x3fcd2990
0x40375fc6: panic_abort at /Users/mooneer/esp-idf/components/esp_system/panic.c:452

0x40380bfd: esp_system_abort at /Users/mooneer/esp-idf/components/esp_system/port/esp_system_chip.c:84

0x4038870e: __assert_func at /Users/mooneer/esp-idf/components/newlib/assert.c:81

0x42059fa7: ofdm_esno_est_calc at /Users/mooneer/ezDV/firmware/build/_deps/codec2-src/src/ofdm.c:1891 (discriminator 1)

0x4205a158: ofdm_get_demod_stats at /Users/mooneer/ezDV/firmware/build/_deps/codec2-src/src/ofdm.c:2230

0x4204fece: freedv_comp_short_rx_ofdm at /Users/mooneer/ezDV/firmware/build/_deps/codec2-src/src/freedv_700.c:508

0x4204eebc: freedv_shortrx at /Users/mooneer/ezDV/firmware/build/_deps/codec2-src/src/freedv_api.c:812

0x4204ef86: freedv_rx at /Users/mooneer/ezDV/firmware/build/_deps/codec2-src/src/freedv_api.c:753

0x4200dc8e: ezdv::audio::FreeDVTask::onTaskTick_() at /Users/mooneer/ezDV/firmware/main/audio/FreeDVTask.cpp:157

0x4201f12b: ezdv::task::DVTask::threadEntry_() at /Users/mooneer/ezDV/firmware/main/task/DVTask.cpp:323

0x4201f141: ezdv::task::DVTask::ThreadEntry_(ezdv::task::DVTask*) at /Users/mooneer/ezDV/firmware/main/task/DVTask.cpp:341

0x40384141: vPortTaskWrapper at /Users/mooneer/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:162

For me, this didn't start happening until I switched from ESP-IDF 5.0 to 5.1. Additionally, I seem to be able to work around this by pinning the Codec2-using task on core 1 and all other tasks that use the FPU onto core 0 (but I could easily be running into issues with incorrect calculations on core 0 tasks instead, just harder to tell as no assertions are thrown).

Anyway, I can try backing out the changes I made and recompiling using ESP-IDF master to see if that helps. It sounds like it might per #11225, anyway.

[NaivelyWritten]

@tmiw In the meantime you can try vTaskSuspendAll() during your FP operations, for me this fixed everything.

[NaivelyWritten]

@igrr Sorry to disturb you again, but this is a pretty serious problem (computation result is silently corrupted instead of failing)

[tmiw]

@tmiw In the meantime you can try vTaskSuspendAll() during your FP operations, for me this fixed everything.

I actually tried this on the Codec2 task and while it did work, it introduced unacceptable latency in the resulting network traffic (the output from the library I mentioned basically gets sent to a radio on the same LAN as the ESP32-S3).

However, ensuring that only one task per core uses FP operations seems to be working so far. I'll probably try vTaskSuspendAll() on the battery task (which still manipulates the battery data received via I2C as FP) as that only fires once every 10 seconds or so.

[o-marshmallow]

Hello @NaivelyWritten ,

This issue is currently under investigation on our side, we will come back to you as soon as we have information.

[o-marshmallow]

@NaivelyWritten @tmiw,

Can you please try the following patch and tell me if it fixes your issues?
fpu.diff.txt

You need to be able to modify your IDF v5.1-rc1 installation:

cd $IDF_PATH
patch -p1 < /path/to/fpu.diff.txt 

If it does fix your issue, it will first be merged internally before making it to the next release.

[tmiw]

@o-marshmallow, I was looking at the patch and wanted to confirm that spinlock_release should unlock a4 and a3. I ask because it looks like spinlock_take locks a4 and a2, which is a different set of registers. If that's okay, I'll give it a try.

[NaivelyWritten]

Same question as @tmiw, it seems they are not paired.

[igrr]

The register numbers passed to this macro are scratch registers used within the macro. The actual spinlock variable is the third argument. So the patch is fine, please give it a try!

[wuyuanyi135]

glad to see someone manage to pin the root of this issue. I got into this in #11225 but didn't dig much because it was unable to reproduce promptly. Thanks for the efforts!

[tmiw]

I'm currently running that patch here. So far, so good, although the original issue was pretty intermittent for me before. I'll keep running with it over the long weekend and see how it goes.

[ProfFan]

Is this in 5.1.1 now? Didn't see this in the release notes, maybe worth to check

[o-marshmallow]

Hello @ProfFan ,

This fix is part of the release v5.1.1. In the release notes, look for the line:

xtensa: Fixed a bug that altered Tasks' FPU registers (#11690) (cadf80e)

[anvgfr]

Hello,

i have a similar problem using ESP32 WROOM with previous IDF (using arduino-esp32 2.1.7 / IDF 4.4).
Floating point calculation get wierd sometimes with NaN or inf values in place of 0 result.
I am using also context switching. (i am using a task to make ADC acquisition and do floating point calculation afterward to transform step to volt).
I can not upgrade to latest arduino-esp32 (v3.0.4) so can't check with lastest IDF release.
I will try to revert to an older version of arduino-esp32