From baa86df8a9b2ef30449ce39eb82b486a65e4a542 Mon Sep 17 00:00:00 2001 From: M Hightower <27247790+mhightower83@users.noreply.github.com> Date: Sun, 4 Jul 2021 19:48:05 -0700 Subject: [PATCH 1/5] Corrected missed edit in alternate build option --- cores/esp8266/hwdt_app_entry.cpp | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/cores/esp8266/hwdt_app_entry.cpp b/cores/esp8266/hwdt_app_entry.cpp index 4d00fdae95..1996d7b0ef 100644 --- a/cores/esp8266/hwdt_app_entry.cpp +++ b/cores/esp8266/hwdt_app_entry.cpp @@ -1175,9 +1175,8 @@ void IRAM_ATTR app_entry_start(void) { */ g_pcont = CONT_STACK; } -#if defined(DEBUG_ESP_HWDT_DEV_DEBUG) && !defined(USE_IRAM) - print_sanity_check_icache(); -#endif + + hwdt_pre_sdk_init_icache(); /* * Use new calculated SYS stack from top. * Call the entry point of the SDK code. From 7d85287db3b790854cb9ad14bbbdb3adba299066 Mon Sep 17 00:00:00 2001 From: M Hightower <27247790+mhightower83@users.noreply.github.com> Date: Tue, 6 Jul 2021 14:15:42 -0700 Subject: [PATCH 2/5] Add WDTacks --- .../examples/HwdtStackDump/HwdtStackDump.ino | 3 + .../esp8266/examples/HwdtStackDump/ReadMe.md | 60 ++++++ .../examples/HwdtStackDump/WDTracks.cpp | 175 ++++++++++++++++++ .../examples/HwdtStackDump/build_opt.txt | 3 + 4 files changed, 241 insertions(+) create mode 100644 libraries/esp8266/examples/HwdtStackDump/ReadMe.md create mode 100644 libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp create mode 100644 libraries/esp8266/examples/HwdtStackDump/build_opt.txt diff --git a/libraries/esp8266/examples/HwdtStackDump/HwdtStackDump.ino b/libraries/esp8266/examples/HwdtStackDump/HwdtStackDump.ino index fa01d2ec00..69f32f519c 100644 --- a/libraries/esp8266/examples/HwdtStackDump/HwdtStackDump.ino +++ b/libraries/esp8266/examples/HwdtStackDump/HwdtStackDump.ino @@ -13,6 +13,9 @@ To demonstrates this tool, this Sketch offers a few options for crashing the ESP8266 with and without a HWDT reset. + Supplimental - How to get an idea of where the sketch was last executing at + the time of the WDT. For this, review ReadMe.md in this example directory. + */ #include diff --git a/libraries/esp8266/examples/HwdtStackDump/ReadMe.md b/libraries/esp8266/examples/HwdtStackDump/ReadMe.md new file mode 100644 index 0000000000..56d4f534f5 --- /dev/null +++ b/libraries/esp8266/examples/HwdtStackDump/ReadMe.md @@ -0,0 +1,60 @@ +# WIP + +# Missing Dependency +A general way of specifying build options for a sketch. There are other active PRs pursuing this effort. This PR needs to be held back and updated after one of those is finalized. For testing this PR, a limited method for the Arduino IDE/Linux OS environment is provided. + +# Watch Dog Tracks +## An Overview +A problem with both Hardware WDT and Soft WDT resets, there is no indication of where the processor is stuck. + +This solution uses the [GCC Program Instrumentation Options'](https://gcc.gnu.org/onlinedocs/gcc/Instrumentation-Options.html) "instrument-functions" to call our tracking functions to capture the most recent functions called. It stores the last caller, callee, and Stack Pointer at each function entry and exit. + +Files needed: +* `build_opt.txt` - compiler "instrument-functions" options file in the sketch folder +* `platform.local.txt` - (temporary) causes the compiler to use the sketch's `build_opt.txt` file +* `WDTracks.cpp` - Add to the sketch folder. Handles tracking and printing/reporting. + +## Implementation +The overhead is very high with this option. The functions `__cyg_profile_func_enter` and `__cyg_profile_func_exit` are used to track execution. Every function entry and exit is instrumented by the compiler with a call to the respective tracking function. This increases code size and execution time. To reduce overhead, there are three ways to specify the code to exclude from the instrumentation: build options `-finstrument-functions-exclude-function-list=...` and `-finstrument-functions-exclude-file-list=...`; and function attribute `__attribute__((no_instrument_function))`. Note, if we limit the coverage too much, we may miss the event that caused the WDT. For an idea of sketch code size increase, a sketch with a code size of 520973 bytes, grew to 803566 bytes when recompiled with the instrument-functions options shown below. + +Both `-finstrument-functions-exclude-function-list=...` and `-finstrument-functions-exclude-file-list=...` exclude when an item in the list matches as a substring in the actual symbol name or file name, respectively. This feature implementation can easily capture and exclude more functions than you intended. A challenge with this approach is the overhead and tuning the excludes, to reduce overhead without losing too many of the activity tracking calls. Use and modify with caution. + +For reporting, we have two times that we can expand on the WDT reset reporting. +1) Hardware WDT - For this HWDT or HWDT_NO4KEXTRA must be enabled from the "Arduino IDE Tools->Debug Level". The newly added tracking results are printed by callback function `hwdt_pre_sdk_init`. This call is made early during the startup process before any substantial initialization occurs that would overwrite interesting information. Care still has to be taken to exclude functions from calling "instrument-functions" at startup leading up to the call to `hwdt_pre_sdk_init`. Otherwise, our tacking information will be lost. +2) Soft WDT - this occurs during postmortem report when `custom_crash_callback` is called. If you already have a `custom_crash_callback` you will need to disable it for this debugging session. + +Both of these callback functions are predefined as _weak_ allowing for simple override replacements without the need for registration calls. + +After a WDT reset, two or more lines starting with "epc1=0x40..." will appear after the stack dump. When you copy-paste this block into the Exception Decoder, it will only process the first one in the list. The Exception Decoder result of the first "epc1=0x40..." will show as the 1st line of the decode starting with "PC: 0x40...". If the results are not meaningful, you can get the decoder to use the next line by deleting the first "epc1=0x40..." line and press return. The decode results will update. Repeat the process as needed. + +## Files Needed +### `build_opt.txt` +Minimum suggested contents for file, `build_opt.txt`, (build options) to use the "-finstrument-functions" option. +``` +-finstrument-functions +-finstrument-functions-exclude-function-list=app_entry,stack_thunk_get_,ets_intr_,ets_post,Cache_Read_Enable +-finstrument-functions-exclude-file-list=umm_malloc,hwdt_app_entry,core_esp8266_postmortem,core_esp8266_app_entry_noextra4k + +``` +Additional exclusions may be needed when using functions that have critical code timing loops, like I2C or high-priority interrupt routines, etc. + + + +### `platform.local.txt` +Various efforts are already under development for specifying build options for a sketch in an IDE and OS flexible manner. +For now, under Arduino IDE and Linux OS, I have been using a `platform.local.txt` file with these lines to utilize my sketch `build_opt.txt` file. +``` +custom.flags_txt.source.pathname={build.source.path}/build_opt.txt +custom.flags_txt.build.pathname={build.path}/build_opt.txt +compiler.c.extra_flags=-include "{custom.flags_txt.build.pathname}.h" @{custom.flags_txt.build.pathname} +compiler.cpp.extra_flags=-include "{custom.flags_txt.build.pathname}.h" @{custom.flags_txt.build.pathname} + +recipe.hooks.prebuild.1.pattern=mkdir -p "{build.path}/custom" +recipe.hooks.prebuild.2.pattern=bash -c "if [ -f {custom.flags_txt.source.pathname} ]; then if [ {custom.flags_txt.source.pathname} -nt {custom.flags_txt.build.pathname} ]; then cp -u {custom.flags_txt.source.pathname} {custom.flags_txt.build.pathname}; touch {custom.flags_txt.build.pathname}.h; fi; fi;" +recipe.hooks.prebuild.3.pattern=bash -c "if [ ! -f {custom.flags_txt.source.pathname} ]; then if [ -s {custom.flags_txt.build.pathname} ]; then rm {custom.flags_txt.build.pathname}; touch {custom.flags_txt.build.pathname} {custom.flags_txt.build.pathname}.h; fi; fi;" +recipe.hooks.prebuild.4.pattern=bash -c "if [ ! -f {custom.flags_txt.build.pathname} ]; then touch -t 170001010000 {custom.flags_txt.build.pathname}; fi;" +recipe.hooks.prebuild.5.pattern=bash -c "if [ ! -f {custom.flags_txt.build.pathname}.h ]; then touch -t 170001010000 {custom.flags_txt.build.pathname}.h; fi;" +``` + +### `WDTracks.cpp` +Copy `WDTracks.cpp` from this example to your sketch folder. diff --git a/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp b/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp new file mode 100644 index 0000000000..7805011a79 --- /dev/null +++ b/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp @@ -0,0 +1,175 @@ +/* + For details about the GCC command line option "-finstrument-functions" see + https://gcc.gnu.org/onlinedocs/gcc/Instrumentation-Options.html + + This option allows us to track what our sketch was last doing before a crash + with Hard or Soft WDT. To do this we define functions that get called for each + function entry and exit. + + The overhead is very high with this option. So we do not want it applied + everywhere. At the same time if we limit the coverage too much, we may miss + the event that caused the WDT. + + To a build_opt.txt file in your sketch directory add the following build options: + -finstrument-functions + -finstrument-functions-exclude-function-list=app_entry,stack_thunk_get_,ets_intr_,ets_post,Cache_Read_Enable + -finstrument-functions-exclude-file-list=umm_malloc,hwdt_app_entry,core_esp8266_postmortem,core_esp8266_app_entry_noextra4k + + Various efforts are under devlopment to handle build options for a sketch. + For now to use your build_opt.txt file, create a platform.local.txt file with + these lines: + custom.flags_txt.source.pathname={build.source.path}/build_opt.txt + custom.flags_txt.build.pathname={build.path}/build_opt.txt + compiler.c.extra_flags=-include "{custom.flags_txt.build.pathname}.h" @{custom.flags_txt.build.pathname} + + recipe.hooks.prebuild.1.pattern=mkdir -p "{build.path}/custom" + recipe.hooks.prebuild.2.pattern=bash -c "if [ -f {custom.flags_txt.source.pathname} ]; then if [ {custom.flags_txt.source.pathname} -nt {custom.flags_txt.build.pathname} ]; then cp -u {custom.flags_txt.source.pathname} {custom.flags_txt.build.pathname}; touch {custom.flags_txt.build.pathname}.h; fi; fi;" + recipe.hooks.prebuild.3.pattern=bash -c "if [ ! -f {custom.flags_txt.source.pathname} ]; then if [ -s {custom.flags_txt.build.pathname} ]; then rm {custom.flags_txt.build.pathname}; touch {custom.flags_txt.build.pathname} {custom.flags_txt.build.pathname}.h; fi; fi;" + recipe.hooks.prebuild.4.pattern=bash -c "if [ ! -f {custom.flags_txt.build.pathname} ]; then touch -t 170001010000 {custom.flags_txt.build.pathname}; fi;" + recipe.hooks.prebuild.5.pattern=bash -c "if [ ! -f {custom.flags_txt.build.pathname}.h ]; then touch -t 170001010000 {custom.flags_txt.build.pathname}.h; fi;" + +*/ +#include +#include +#include + +extern "C" { + + struct WDTracksLastCall { + struct { + void *this_fn; + void *call_site; + void *sp; + } enter; + + struct { + void *this_fn; + void *call_site; + void *sp; + } exit; + + bool in; + }; + struct WDTracksLastCall wd_tracks; + + IRAM_ATTR void __cyg_profile_func_enter(void *this_fn, void *call_site) __attribute__((no_instrument_function)); + IRAM_ATTR void __cyg_profile_func_exit(void *this_fn, void *call_site) __attribute__((no_instrument_function)); + void print_wdtracks(void) __attribute__((no_instrument_function)); + + void custom_crash_callback(struct rst_info * rst_info, uint32_t stack, uint32_t stack_end) __attribute__((no_instrument_function)); + + /* + * Printing from hwdt_pre_sdk_init() requires special considerations. Normal + * "C" runtime initialization has not run at the time it is called. For + * printing from this context, we use umm_info_safe_printf_P. It is capable of + * handling this situation and is a function included in umm_malloc. + */ + int umm_info_safe_printf_P(const char *fmt, ...); + #define ETS_PRINTF(fmt, ...) umm_info_safe_printf_P(PSTR(fmt), ##__VA_ARGS__) + +#if defined(DEBUG_ESP_HWDT) || defined(DEBUG_ESP_HWDT_NOEXTRA4K) + void hwdt_pre_sdk_init(void) __attribute__((no_instrument_function)); + + // Called from HWDT just before starting SDK + // Serial speed has been initialized for us. + void hwdt_pre_sdk_init(void) { + if (REASON_WDT_RST == hwdt_info.reset_reason) { + /* + Note, we rely on the previous values of the wd_tracks structure, still + being set from before the crash. At the time we are called here, the SDK + has not been started. The "C" runtime code that will zero the structure + does not run until later when the SDK calls user_init(). + */ + print_wdtracks(); + } + } +#endif + + // Called from Postmortem + void custom_crash_callback(struct rst_info * rst_info, uint32_t stack, uint32_t stack_end) + { + (void)stack; + (void)stack_end; + if (REASON_SOFT_WDT_RST == rst_info->reason) { + print_wdtracks(); + } + } + + + /* + Called at function entry after stackframe setup and registers are saved. + */ + void __cyg_profile_func_enter(void *this_fn, void *call_site) + { + wd_tracks.enter.this_fn = this_fn; // The address of the function called + wd_tracks.enter.call_site = call_site; // The saved return address "a0" of the callee + asm volatile ( + "s32i a1, %[wd_tracks], %[enter_sp]\n\t" + : // No output constraints + : [wd_tracks]"a"(&wd_tracks), [enter_sp]"I"(offsetof(struct WDTracksLastCall, enter.sp)) + :); + wd_tracks.in = true; + } + + + /* + Called at function exit just before saved registers and stackframe are + restored. + */ + void __cyg_profile_func_exit(void *this_fn, void *call_site) + { + wd_tracks.exit.this_fn = this_fn; // The address of the function called + wd_tracks.exit.call_site = call_site; // The saved return address "a0" of the callee + asm volatile ( + "s32i a1, %[wd_tracks], %[exit_sp]\n\t" + : // No output constraints + : [wd_tracks]"a"(&wd_tracks), [exit_sp]"I"(offsetof(struct WDTracksLastCall, exit.sp)) + :); + wd_tracks.in = false; + } + + void print_wdtracks(void) + { + if (NULL == wd_tracks.enter.this_fn) { + // Compiler flags -finstrument-functions, etc. are most likely missing. + return; + } + if (wd_tracks.in) { + ETS_PRINTF("\nepc1=%p\nepc1=%p\n", + wd_tracks.enter.this_fn, wd_tracks.enter.call_site); + + if (wd_tracks.exit.this_fn != wd_tracks.enter.this_fn && + wd_tracks.exit.this_fn != wd_tracks.enter.call_site) + ETS_PRINTF("epc1=%p\n", wd_tracks.exit.this_fn); + if (wd_tracks.exit.call_site != wd_tracks.enter.this_fn && + wd_tracks.exit.call_site != wd_tracks.enter.call_site) + ETS_PRINTF("epc1=%p\n", wd_tracks.exit.call_site); + + } else { + ETS_PRINTF("\nepc1=%p\nepc1=%p\n", + wd_tracks.exit.this_fn, wd_tracks.exit.call_site); + + if (wd_tracks.enter.this_fn != wd_tracks.exit.this_fn && + wd_tracks.enter.this_fn != wd_tracks.exit.call_site) + ETS_PRINTF("epc1=%p\n", wd_tracks.enter.this_fn); + if (wd_tracks.enter.call_site != wd_tracks.exit.this_fn && + wd_tracks.enter.call_site != wd_tracks.exit.call_site) + ETS_PRINTF("epc1=%p\n", wd_tracks.enter.call_site); + } + ETS_PRINTF("\n--------- OR FOR WDT, CUT HERE FOR EXCEPTION DECODER ---------\n"); + + if (wd_tracks.in) { + ETS_PRINTF("\nLast function entered:\n" + " called function: %p\n" + " callee return: %p\n" + " SP: %p\n", + wd_tracks.enter.this_fn, wd_tracks.enter.call_site, wd_tracks.enter.sp); + } else { + ETS_PRINTF("\nLast function exited:\n" + " called function: %p\n" + " callee return: %p\n" + " SP: %p\n", + wd_tracks.exit.this_fn, wd_tracks.exit.call_site, wd_tracks.exit.sp); + } + } +}; diff --git a/libraries/esp8266/examples/HwdtStackDump/build_opt.txt b/libraries/esp8266/examples/HwdtStackDump/build_opt.txt new file mode 100644 index 0000000000..42b2d57d88 --- /dev/null +++ b/libraries/esp8266/examples/HwdtStackDump/build_opt.txt @@ -0,0 +1,3 @@ +-finstrument-functions +-finstrument-functions-exclude-function-list=app_entry,stack_thunk_get_,ets_intr_,ets_post,Cache_Read_Enable +-finstrument-functions-exclude-file-list=umm_malloc,hwdt_app_entry,core_esp8266_postmortem,core_esp8266_app_entry_noextra4k From 5a50935c73ac6269ec58ff37eaefdec9be463ca2 Mon Sep 17 00:00:00 2001 From: M Hightower <27247790+mhightower83@users.noreply.github.com> Date: Sun, 11 Jul 2021 16:04:31 -0700 Subject: [PATCH 3/5] Updated WDTracks.cpp to capture events into a circular buffer. Updated printout to dump WDTracks in a stack dump format that the Exception Decoder processes more effectivly. --- .../esp8266/examples/HwdtStackDump/ReadMe.md | 7 +- .../examples/HwdtStackDump/WDTracks.cpp | 162 ++++++++++-------- .../examples/HwdtStackDump/build_opt.txt | 2 +- 3 files changed, 92 insertions(+), 79 deletions(-) diff --git a/libraries/esp8266/examples/HwdtStackDump/ReadMe.md b/libraries/esp8266/examples/HwdtStackDump/ReadMe.md index 56d4f534f5..da5283d71e 100644 --- a/libraries/esp8266/examples/HwdtStackDump/ReadMe.md +++ b/libraries/esp8266/examples/HwdtStackDump/ReadMe.md @@ -25,16 +25,17 @@ For reporting, we have two times that we can expand on the WDT reset reporting. Both of these callback functions are predefined as _weak_ allowing for simple override replacements without the need for registration calls. -After a WDT reset, two or more lines starting with "epc1=0x40..." will appear after the stack dump. When you copy-paste this block into the Exception Decoder, it will only process the first one in the list. The Exception Decoder result of the first "epc1=0x40..." will show as the 1st line of the decode starting with "PC: 0x40...". If the results are not meaningful, you can get the decoder to use the next line by deleting the first "epc1=0x40..." line and press return. The decode results will update. Repeat the process as needed. +~After a WDT reset, two or more lines starting with "epc1=0x40..." will appear after the stack dump. When you copy-paste this block into the Exception Decoder, it will only process the first one in the list. The Exception Decoder result of the first "epc1=0x40..." will show as the 1st line of the decode starting with "PC: 0x40...". If the results are not meaningful, you can get the decoder to use the next line by deleting the first "epc1=0x40..." line and press return. The decode results will update. Repeat the process as needed.~ + +After a WDT reset, a fake stack dump identifyed as `ctx: WDTracks` is generated. Copy-paste that block into the Exception Decoder for a backtrace of the functions called. ## Files Needed ### `build_opt.txt` Minimum suggested contents for file, `build_opt.txt`, (build options) to use the "-finstrument-functions" option. ``` -finstrument-functions --finstrument-functions-exclude-function-list=app_entry,stack_thunk_get_,ets_intr_,ets_post,Cache_Read_Enable +-finstrument-functions-exclude-function-list=app_entry,stack_thunk_get_,ets_intr_,ets_post,Cache_Read_Enable,non32xfer_exception_handler -finstrument-functions-exclude-file-list=umm_malloc,hwdt_app_entry,core_esp8266_postmortem,core_esp8266_app_entry_noextra4k - ``` Additional exclusions may be needed when using functions that have critical code timing loops, like I2C or high-priority interrupt routines, etc. diff --git a/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp b/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp index 7805011a79..e780a9e23a 100644 --- a/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp +++ b/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp @@ -12,7 +12,7 @@ To a build_opt.txt file in your sketch directory add the following build options: -finstrument-functions - -finstrument-functions-exclude-function-list=app_entry,stack_thunk_get_,ets_intr_,ets_post,Cache_Read_Enable + -finstrument-functions-exclude-function-list=app_entry,stack_thunk_get_,ets_intr_,ets_post,Cache_Read_Enable,non32xfer_exception_handler -finstrument-functions-exclude-file-list=umm_malloc,hwdt_app_entry,core_esp8266_postmortem,core_esp8266_app_entry_noextra4k Various efforts are under devlopment to handle build options for a sketch. @@ -33,24 +33,24 @@ #include #include -extern "C" { - - struct WDTracksLastCall { - struct { - void *this_fn; - void *call_site; - void *sp; - } enter; +#ifndef ALWAYS_INLINE +#define ALWAYS_INLINE inline __attribute__((always_inline)) +#endif - struct { - void *this_fn; - void *call_site; - void *sp; - } exit; +extern "C" { - bool in; + constexpr size_t kMaxTracks = 64; + struct WDTrackMark { + void *this_fn; + void *call_site; + void *sp; + bool enter; + }; + struct WDTracksCBuf { + size_t idx; + struct WDTrackMark tracks[kMaxTracks]; }; - struct WDTracksLastCall wd_tracks; + struct WDTracksCBuf wd_tracks; IRAM_ATTR void __cyg_profile_func_enter(void *this_fn, void *call_site) __attribute__((no_instrument_function)); IRAM_ATTR void __cyg_profile_func_exit(void *this_fn, void *call_site) __attribute__((no_instrument_function)); @@ -61,11 +61,12 @@ extern "C" { /* * Printing from hwdt_pre_sdk_init() requires special considerations. Normal * "C" runtime initialization has not run at the time it is called. For - * printing from this context, we use umm_info_safe_printf_P. It is capable of - * handling this situation and is a function included in umm_malloc. + * printing from this context, we use umm_info_safe_printf_P. It is capable + * of handling this situation and is a function included in umm_malloc. */ int umm_info_safe_printf_P(const char *fmt, ...); - #define ETS_PRINTF(fmt, ...) umm_info_safe_printf_P(PSTR(fmt), ##__VA_ARGS__) +#define ETS_PRINTF(fmt, ...) umm_info_safe_printf_P(PSTR(fmt), ##__VA_ARGS__) +#define ETS_PRINTF_P(fmt, ...) umm_info_safe_printf_P(fmt, ##__VA_ARGS__) #if defined(DEBUG_ESP_HWDT) || defined(DEBUG_ESP_HWDT_NOEXTRA4K) void hwdt_pre_sdk_init(void) __attribute__((no_instrument_function)); @@ -94,21 +95,49 @@ extern "C" { print_wdtracks(); } } + // Functions __cyg_profile_func_enter and __cyg_profile_func_exit are + // identical except for the "bool enter" value. These are a very high call + // frequency functions. Avoid using a common function to save code space. By + // forceing inline, we avoid the time to creating a new stack frame and + // register save event to make the call. + // Side note, needed to keep __attribute__((no_instrument_function)); on + // forced inline parts otherwise the resulting ASM was strange and larger. + static ALWAYS_INLINE void __cyg_profile_func(void *this_fn, void *call_site, bool enter) __attribute__((no_instrument_function)); + void __cyg_profile_func(void *this_fn, void *call_site, bool enter) + { + uint32_t saved_ps = xt_rsil(DEFAULT_CRITICAL_SECTION_INTLEVEL); + size_t idx = wd_tracks.idx; + // Not using the .noinit attribute on structure at this time; however, + // doing range check here makes an uninitialized structure safe! + if (kMaxTracks <= idx) { + idx = 0; + } + + struct WDTrackMark *track = &wd_tracks.tracks[idx]; + asm volatile ( + "s32i a1, %[track], %[track_sp]\n\t" + : [track]"+a"(track) + : [track_sp]"I"(offsetof(struct WDTrackMark, sp)) + :); + // Extended ASM note, If "track" is an input register the compiler assumes + // it has been overwriten by the ASM code and recalculates its prior value. + // As an output read/write register the compiler skips the recalculation. + // This saved two bytes. + track->this_fn = this_fn; // The address of the function called + track->call_site = call_site; // The saved return address "a0" of the callee + track->enter = enter; + wd_tracks.idx = ++idx; + + xt_wsr_ps(saved_ps); + } /* Called at function entry after stackframe setup and registers are saved. */ void __cyg_profile_func_enter(void *this_fn, void *call_site) { - wd_tracks.enter.this_fn = this_fn; // The address of the function called - wd_tracks.enter.call_site = call_site; // The saved return address "a0" of the callee - asm volatile ( - "s32i a1, %[wd_tracks], %[enter_sp]\n\t" - : // No output constraints - : [wd_tracks]"a"(&wd_tracks), [enter_sp]"I"(offsetof(struct WDTracksLastCall, enter.sp)) - :); - wd_tracks.in = true; + __cyg_profile_func(this_fn, call_site, true); } @@ -118,58 +147,41 @@ extern "C" { */ void __cyg_profile_func_exit(void *this_fn, void *call_site) { - wd_tracks.exit.this_fn = this_fn; // The address of the function called - wd_tracks.exit.call_site = call_site; // The saved return address "a0" of the callee - asm volatile ( - "s32i a1, %[wd_tracks], %[exit_sp]\n\t" - : // No output constraints - : [wd_tracks]"a"(&wd_tracks), [exit_sp]"I"(offsetof(struct WDTracksLastCall, exit.sp)) - :); - wd_tracks.in = false; + __cyg_profile_func(this_fn, call_site, false); } void print_wdtracks(void) { - if (NULL == wd_tracks.enter.this_fn) { - // Compiler flags -finstrument-functions, etc. are most likely missing. - return; - } - if (wd_tracks.in) { - ETS_PRINTF("\nepc1=%p\nepc1=%p\n", - wd_tracks.enter.this_fn, wd_tracks.enter.call_site); - - if (wd_tracks.exit.this_fn != wd_tracks.enter.this_fn && - wd_tracks.exit.this_fn != wd_tracks.enter.call_site) - ETS_PRINTF("epc1=%p\n", wd_tracks.exit.this_fn); - if (wd_tracks.exit.call_site != wd_tracks.enter.this_fn && - wd_tracks.exit.call_site != wd_tracks.enter.call_site) - ETS_PRINTF("epc1=%p\n", wd_tracks.exit.call_site); - - } else { - ETS_PRINTF("\nepc1=%p\nepc1=%p\n", - wd_tracks.exit.this_fn, wd_tracks.exit.call_site); - - if (wd_tracks.enter.this_fn != wd_tracks.exit.this_fn && - wd_tracks.enter.this_fn != wd_tracks.exit.call_site) - ETS_PRINTF("epc1=%p\n", wd_tracks.enter.this_fn); - if (wd_tracks.enter.call_site != wd_tracks.exit.this_fn && - wd_tracks.enter.call_site != wd_tracks.exit.call_site) - ETS_PRINTF("epc1=%p\n", wd_tracks.enter.call_site); - } - ETS_PRINTF("\n--------- OR FOR WDT, CUT HERE FOR EXCEPTION DECODER ---------\n"); - - if (wd_tracks.in) { - ETS_PRINTF("\nLast function entered:\n" - " called function: %p\n" - " callee return: %p\n" - " SP: %p\n", - wd_tracks.enter.this_fn, wd_tracks.enter.call_site, wd_tracks.enter.sp); - } else { - ETS_PRINTF("\nLast function exited:\n" - " called function: %p\n" - " callee return: %p\n" - " SP: %p\n", - wd_tracks.exit.this_fn, wd_tracks.exit.call_site, wd_tracks.exit.sp); + // It is assumed we are called from a context that interrupts will not occur. + + // Print as a fake stack dump with our WDTrack info so that the + // Exception decoder will assit with a call trace printout. + size_t idx = wd_tracks.idx; + idx--; + if (kMaxTracks <= idx) { + idx = kMaxTracks - 1; + } + struct WDTrackMark *track = &wd_tracks.tracks[idx]; + ETS_PRINTF("\nepc1=%p\n", track->this_fn); + + uintptr_t fake_start = (uintptr_t)track->sp - 0x10; + uintptr_t fake_end = fake_start + (uintptr_t)(kMaxTracks * sizeof(struct WDTrackMark)); + ETS_PRINTF("\n>>>stack>>>\n\nctx: WDTracks\n"); + ETS_PRINTF("sp: %08x end: %08x offset: %04x\n", fake_start, fake_end, 0); + + // Print most recent first to stay consistent with how the stack dump/decode + // would normally appear. + for (size_t i = 0; i < kMaxTracks; i++) { + ETS_PRINTF("%08x: %08x %08x %08x %08x\n", fake_start + i * 0x10u, + track->this_fn, track->enter, track->sp, track->call_site); + idx--; + if (kMaxTracks <= idx) { + idx = kMaxTracks - 1; } + track = &wd_tracks.tracks[idx]; + } + + ETS_PRINTF("<< Date: Sun, 11 Jul 2021 16:53:26 -0700 Subject: [PATCH 4/5] corrected undefined macro reference. --- libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp b/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp index e780a9e23a..d7f0f61070 100644 --- a/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp +++ b/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp @@ -105,7 +105,7 @@ extern "C" { static ALWAYS_INLINE void __cyg_profile_func(void *this_fn, void *call_site, bool enter) __attribute__((no_instrument_function)); void __cyg_profile_func(void *this_fn, void *call_site, bool enter) { - uint32_t saved_ps = xt_rsil(DEFAULT_CRITICAL_SECTION_INTLEVEL); + uint32_t saved_ps = xt_rsil(15); size_t idx = wd_tracks.idx; // Not using the .noinit attribute on structure at this time; however, From 8cb1eac5bd1a8b750a2d44bc47c7559671cf3477 Mon Sep 17 00:00:00 2001 From: M Hightower <27247790+mhightower83@users.noreply.github.com> Date: Mon, 12 Jul 2021 08:25:41 -0700 Subject: [PATCH 5/5] Mostly updated comments and added explanation about initialization and minor code changes. --- .../esp8266/examples/HwdtStackDump/ReadMe.md | 4 +- .../examples/HwdtStackDump/WDTracks.cpp | 90 ++++++++++++------- 2 files changed, 60 insertions(+), 34 deletions(-) diff --git a/libraries/esp8266/examples/HwdtStackDump/ReadMe.md b/libraries/esp8266/examples/HwdtStackDump/ReadMe.md index da5283d71e..a9666f6507 100644 --- a/libraries/esp8266/examples/HwdtStackDump/ReadMe.md +++ b/libraries/esp8266/examples/HwdtStackDump/ReadMe.md @@ -25,8 +25,6 @@ For reporting, we have two times that we can expand on the WDT reset reporting. Both of these callback functions are predefined as _weak_ allowing for simple override replacements without the need for registration calls. -~After a WDT reset, two or more lines starting with "epc1=0x40..." will appear after the stack dump. When you copy-paste this block into the Exception Decoder, it will only process the first one in the list. The Exception Decoder result of the first "epc1=0x40..." will show as the 1st line of the decode starting with "PC: 0x40...". If the results are not meaningful, you can get the decoder to use the next line by deleting the first "epc1=0x40..." line and press return. The decode results will update. Repeat the process as needed.~ - After a WDT reset, a fake stack dump identifyed as `ctx: WDTracks` is generated. Copy-paste that block into the Exception Decoder for a backtrace of the functions called. ## Files Needed @@ -59,3 +57,5 @@ recipe.hooks.prebuild.5.pattern=bash -c "if [ ! -f {custom.flags_txt.build.pathn ### `WDTracks.cpp` Copy `WDTracks.cpp` from this example to your sketch folder. + +Change the value of kMaxTracks to control the number of track marks saved. diff --git a/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp b/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp index d7f0f61070..a9bfd79150 100644 --- a/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp +++ b/libraries/esp8266/examples/HwdtStackDump/WDTracks.cpp @@ -39,17 +39,26 @@ extern "C" { - constexpr size_t kMaxTracks = 64; + constexpr size_t kMaxTracks = 32; // Change to control the number of track marks saved. + struct WDTrackMark { - void *this_fn; - void *call_site; - void *sp; - bool enter; + void *this_fn; // The starting address if the function called + void *call_site; // On return, the next address to execute in callee function. + void *sp; // SP for "this_fn" not that of "call_site" (callee) + bool enter; // True when recording a __cyg_profile_func_enter call + // False when recording a __cyg_profile_func_exit call }; struct WDTracksCBuf { size_t idx; struct WDTrackMark tracks[kMaxTracks]; }; + /* + If you need to debug a WDT that occurs before user_init() is called to + perform "C"/"C++" runtime initialization, then add + "__attribute__((section(".noinit")))" to wd_tracks and do ets_memset from + hwdt_pre_sdk_init as shown below. And, build with "Debug Level: HWDT". + Otherwise, the data captured in wd_tracks starts after user_init(). + */ struct WDTracksCBuf wd_tracks; IRAM_ATTR void __cyg_profile_func_enter(void *this_fn, void *call_site) __attribute__((no_instrument_function)); @@ -59,11 +68,11 @@ extern "C" { void custom_crash_callback(struct rst_info * rst_info, uint32_t stack, uint32_t stack_end) __attribute__((no_instrument_function)); /* - * Printing from hwdt_pre_sdk_init() requires special considerations. Normal - * "C" runtime initialization has not run at the time it is called. For - * printing from this context, we use umm_info_safe_printf_P. It is capable - * of handling this situation and is a function included in umm_malloc. - */ + Printing from hwdt_pre_sdk_init() requires special considerations. Normal + "C" runtime initialization has not run at the time it is called. For + printing from this context, we use umm_info_safe_printf_P. It is capable + of handling this situation and is a function included in umm_malloc. + */ int umm_info_safe_printf_P(const char *fmt, ...); #define ETS_PRINTF(fmt, ...) umm_info_safe_printf_P(PSTR(fmt), ##__VA_ARGS__) #define ETS_PRINTF_P(fmt, ...) umm_info_safe_printf_P(fmt, ##__VA_ARGS__) @@ -77,12 +86,20 @@ extern "C" { if (REASON_WDT_RST == hwdt_info.reset_reason) { /* Note, we rely on the previous values of the wd_tracks structure, still - being set from before the crash. At the time we are called here, the SDK - has not been started. The "C" runtime code that will zero the structure - does not run until later when the SDK calls user_init(). + set from before the crash. At the time we are called here, the SDK has + not started. The "C" runtime code that will zero the structure does not + run until later when the SDK calls user_init(). */ print_wdtracks(); } + /* + You can skip direct initialization of wd_tracks without causing crashes. + After kMaxTracks calls, all uninitialized data is overwritten. In most + user-based WDT crashes, you can assume that a sufficient number + (kMaxTracks) of calls will fill the circular buffer before a crash + occurs. + */ + ets_memset(&wd_tracks, 0, sizeof(wd_tracks)); } #endif @@ -95,35 +112,40 @@ extern "C" { print_wdtracks(); } } - // Functions __cyg_profile_func_enter and __cyg_profile_func_exit are - // identical except for the "bool enter" value. These are a very high call - // frequency functions. Avoid using a common function to save code space. By - // forceing inline, we avoid the time to creating a new stack frame and - // register save event to make the call. - // Side note, needed to keep __attribute__((no_instrument_function)); on - // forced inline parts otherwise the resulting ASM was strange and larger. + /* + Functions __cyg_profile_func_enter and __cyg_profile_func_exit are + identical except for the "bool enter" value. These are very high call + frequency functions. Avoid using a common function to save code space. By + forcing inline, we avoid the time to creating a new stack frame and the + register save event for making a call. + Side note, needed to keep __attribute__((no_instrument_function)); on + forced inline parts otherwise the resulting ASM was strange and larger. + */ static ALWAYS_INLINE void __cyg_profile_func(void *this_fn, void *call_site, bool enter) __attribute__((no_instrument_function)); void __cyg_profile_func(void *this_fn, void *call_site, bool enter) { uint32_t saved_ps = xt_rsil(15); size_t idx = wd_tracks.idx; - // Not using the .noinit attribute on structure at this time; however, - // doing range check here makes an uninitialized structure safe! + // Doing range check here makes an uninitialized structure safe! if (kMaxTracks <= idx) { idx = 0; } struct WDTrackMark *track = &wd_tracks.tracks[idx]; + /* + Extended ASM note, If "track" is an input register the compiler assumes + it has been overwriten by the ASM code and recalculates its prior value. + As an output read/write register the compiler skips the recalculation. + This saved two bytes. At this time, with GCC-10.2.0, the resulting code + generated by this Extended ASM, integrated into the "C" code ASM in an + optimum way. + */ asm volatile ( "s32i a1, %[track], %[track_sp]\n\t" : [track]"+a"(track) : [track_sp]"I"(offsetof(struct WDTrackMark, sp)) :); - // Extended ASM note, If "track" is an input register the compiler assumes - // it has been overwriten by the ASM code and recalculates its prior value. - // As an output read/write register the compiler skips the recalculation. - // This saved two bytes. track->this_fn = this_fn; // The address of the function called track->call_site = call_site; // The saved return address "a0" of the callee track->enter = enter; @@ -152,10 +174,14 @@ extern "C" { void print_wdtracks(void) { - // It is assumed we are called from a context that interrupts will not occur. - - // Print as a fake stack dump with our WDTrack info so that the - // Exception decoder will assit with a call trace printout. + /* + Print as a fake stack dump with our WDTrack info so that the ESP Exception + Decoder will assist with a call trace printout by putting source code + location to the addresses presented in the stack dump. + + It is assumed we are called from a context that interrupts will not occur. + Also, all function called from here must not be "instrumented" + */ size_t idx = wd_tracks.idx; idx--; if (kMaxTracks <= idx) { @@ -164,10 +190,10 @@ extern "C" { struct WDTrackMark *track = &wd_tracks.tracks[idx]; ETS_PRINTF("\nepc1=%p\n", track->this_fn); - uintptr_t fake_start = (uintptr_t)track->sp - 0x10; + uintptr_t fake_start = (uintptr_t)0x3FFFE000; // Arbitrary value - using ending address of SYS stack space. uintptr_t fake_end = fake_start + (uintptr_t)(kMaxTracks * sizeof(struct WDTrackMark)); ETS_PRINTF("\n>>>stack>>>\n\nctx: WDTracks\n"); - ETS_PRINTF("sp: %08x end: %08x offset: %04x\n", fake_start, fake_end, 0); + ETS_PRINTF("sp: %08x end: %08x offset: 0000\n", fake_start, fake_end); // Print most recent first to stay consistent with how the stack dump/decode // would normally appear.