[CH6178] Tracer/checkpoints (rebase) #1451

avtolstoy · 2017-12-19T17:54:38Z

submission notes

**Important:** Please sanitize/remove any confidential info like usernames, passwords, org names, product names/ids, access tokens, client ids/secrets, or anything else you don't wish to share.

Please Read and Sign the Contributor License Agreement ([Info here](https://github.com/spark/firmware/blob/develop/CONTRIBUTING.md)).

You may also delete this submission notes header if you'd like. Thank you for contributing!

Problem

This is a rebase of #1369 on develop with renaming according to [CH8404] and some additional backup SRAM overflow checks.

Solution

When a device hard faults, crashes, freezes or is otherwise misbehaving, it is presently difficult to know what the last action the device took is and whether the fault lies in application code, system code, peripheral code etc..

A checkpoints API would allow application and system firmware to record their current execution progress and provide an indication of where execution halted prior to the crash. This information is then published to the cloud on next successful connection.

It is also possible to get stack trace of all the threads using a naive stack unwinder, that just scans through the thread stack, looking for flash addresses (within system and user part bounds) and checks if there is a branching instruction at that location.

It would be useful to store per-thread stack traces in addition to checkpoint info whenever the device enters a hardfault, a panic state, or on demand. This will provide a better overview of the system state and help understand the cause of the crash or deadlock for difficult to reproduce issues.

System code may use the following macros defined in tracer_service.h:

TRACER_CHECKPOINT() - regular instruction address type checkpoint
TRACER_PANIC_CHECKPOINT() - special instruction address type checkpoint which should only be called from a panic handler, which will prevent further modification of diagnostic data
TRACER_CRASH_CHECKPOINT(pc) - special instruction address type checkpoint which should only be called from a crash (hardfault) handler, which will prevent further modification of diagnostic data. An instruction address needs to be manually passed as an argument.
TRACER_UPDATE() - forces a full system state update (including stacktraces).

All LOG statements, except for LOG_DUMP, make a call to TRACER_CHECKPOINT().
Both hardfault and panic handlers make a call to their respective macros: TRACER_CRASH_CHECKPOINT(), TRACER_PANIC_CHECKPOINT()

Application code may use the following macros defined in spark_wiring_tracer.h:

CHECKPOINT() - a standard variant of CHECKPOINT() macro. Implementation depends on a preprocessor macro TRACER_ELF_AVAILABLE.
- When defined and equal to 1, CHECKPOINT() macro internally calls TRACER_CHECKPOINT(), making it an instruction address type checkpoint
- When undefined or set to 0, CHECKPOINT() macro internally makes a call to TRACER_TEXT_CHECKPOINT(), which saves the location of the checkpoint in textual format: __FILENAME__:__LINE__
CHECKPOINT(text) - a specialized variant of CHECKPOINT() macro, which forces a textual checkpoint with the text passed as an argument

All Logger class calls, except for print, printf, write and dump, internally include a call to _LOG_CHECKPOINT() macro defined in spark_wiring_diagnostic.h, which is only enabled when TRACER_ELF_AVAILABLE == 1. It acquires an address of the calling function and uses that as the checkpoint instruction address.

Steps to Test

unit tests
app/checkpoint (see README.md)

Example App

app/checkpoint

References

Closes [CH6178] Checkpoints/diagnostics #1369 (supersedes)
[CH6178]
[CH8404]

Completeness

User is totes amazing for contributing!
Contributor has signed CLA (Info here)
Problem and Solution clearly stated
Run unit/integration/application tests on device
Added documentation
Added to CHANGELOG.md after merging (add links to docs and issues)

m-mcgowan

An excellent piece of work and fantastic to have this feature available! We will release it in 0.8.0-rc.2 so please ensure corresponding docs are available. In general, I'd like to see more source code comments describing why we are done - I've added some inline comments for areas that I feel need some explanation.

m-mcgowan · 2018-01-16T12:27:25Z

hal/inc/concurrent_hal.h

+os_thread_t os_thread_current();
+
+typedef struct {
+  uint8_t reserved;


do we need a size field here for extensibility?

That's a question in the original PR as well :)

It's currently only used within a single module and is not exported, so that shouldn't be a concern at the moment. If we later decide to export it, the first reserved becomes a version field as usual.

m-mcgowan · 2018-01-16T12:28:12Z

build/arm-tools.mk

@@ -15,14 +15,14 @@ AR = $(GCC_ARM_PATH)$(GCC_PREFIX)gcc-ar
 #

 # C compiler flags
-CFLAGS +=  -g3 -gdwarf-2 -Os -mcpu=cortex-m3 -mthumb
+CFLAGS +=  -g3 -gdwarf-2 -Os -mcpu=cortex-m3 -mthumb -fomit-frame-pointer


could you say a few words about the omit-frame-pointer option. is it only an optimization or does it have a functional purpose?

This optimization is already enabled by -Os (actually by -O1, see https://gcc.gnu.org/onlinedocs/gcc/Optimize-Options.html), but it's better to explicitly specify it.

Disabling this option will lead to increased flash and stack usage (at the very least +16 bytes on each function call without tail-call optimization) and will interfere with stacktracer implemented in this PR. MbedTLS bignum assembly optimizations will also fail to build as R7 is not available and stores the frame pointer.

m-mcgowan · 2018-01-16T12:32:57Z

hal/src/stm32f2xx/concurrent_hal.cpp

+#include <malloc.h>
+#include "timer_hal.h"
+
+extern "C" void vTaskGetStackInfo( TaskHandle_t pxTask, void** stack_ptr, void** start_stack_ptr, void** end_stack_ptr );


Can this be pushed to a FreeRTOS header?

m-mcgowan · 2018-01-16T12:35:15Z

hal/src/stm32f2xx/concurrent_hal.cpp

+    return 0;
+}
+
+os_result_t os_thread_dump(os_thread_t thread, os_thread_dump_callback_t callback, void* ptr)


We should document that the callback is executed in a critical section and should ensure it completes independently of the progress of other threads.

👍
TracerService also only calls it with interrupts disabled.

m-mcgowan · 2018-01-16T12:37:36Z

hal/src/stm32f2xx/core_hal_stm32f2xx.c

+
+    int count = 0;
+
+    for (uint32_t* sp = (uint32_t*)info->stack_start; sp <= (uint32_t*)info->stack_end; sp++) {


black magic! 🤘

Somewhat documented blackmagic :)

m-mcgowan · 2018-01-16T13:43:22Z

system/src/system_tracer_service_impl.h

+  } else {
+    // Insert new at the end
+    if (freeSpace() < (sizeof(ThreadEntry) + size(chkpt) + strnlen(info->name, maxThreadNameLength) + 1)) {
+      return TRACER_ERROR_NO_SPACE;


should we use a circular buffer so that the most recent entries are preserved?

That's a good idea, however in theory we should not run out of space easily. There is at least 1k (~700 on Electron) bytes in system retained RAM and we do not have that many threads (especially on Electron).

We do not generate full stacktraces on every call (only when needed, e.g. using USB request or in hardfault/watchdog ISR) and every thread entry only has a header struct (8 bytes) + its name (up to 16 bytes) + a checkpoint stored (4 bytes).

m-mcgowan · 2018-01-16T13:50:23Z

user/import.mk

@@ -26,6 +26,8 @@ CFLAGS += -DINCLUDE_PLATFORM=1
 # platforms.h
 ifeq ($(PLATFORM_ID),3)
 INCLUDE_DIRS += $(PROJECT_ROOT)/platform/shared/inc
+INCLUDE_DIRS += $(PROJECT_ROOT)/platform/MCU/gcc/inc


This is unexpected - could you explain why the gcc platform is brought in for all user apps?

Only for GCC platform: ifeq ($(PLATFORM_ID),3)

m-mcgowan · 2018-01-16T13:54:44Z

communication/makefile

@@ -7,6 +7,6 @@ TARGET_TYPE = a

 BUILD_PATH_EXT=$(COMMUNICATION_BUILD_PATH_EXT)

-DEPENDENCIES = hal dynalib services wiring crypto
+DEPENDENCIES = hal dynalib services wiring crypto platform


I imagine this is because of the traces in the logs?

Correct. platform_tracer.h mainly.

m-mcgowan · 2018-01-16T13:55:30Z

modules/electron/system-part1/module_system_part3_export.ld

@@ -1,8 +1,8 @@

 system_part3_start = 0x8060000;

-system_part3_ram_end = 0x2001D800 /* 0x20200000-10K */;
-system_part3_ram_start = 0x2001c000 /* end of SRAM - 16K */;
+system_part3_ram_end = 0x2001D800 - 1K /* 0x20200000-10K-1K */;


what's the 1K reserved for?

At the time of writing system-part3 RAM was overflowing, this change might no longer be needed.

m-mcgowan · 2018-01-16T14:03:14Z

services/src/tracer_service.cpp

+
+int tracer_save_checkpoint__(tracer_checkpoint_t* chkpt, uint32_t flags, void* reserved) {
+    if (callbacks2.tracer_save_checkpoint) {
+        return callbacks2.tracer_save_checkpoint(chkpt, flags, reserved);


Can you explain please why we need two distinct callback stores?

One for system-part1, the other for system-part3. Ideally these should be moved into an .inc and built as part of module-specific source files or I guess both should be enabled simultaneously and built as weak, as otherwise these will probably cause issues with non-clean builds. 👍

…sition (see particle-iot/photon-wiced#18)

…ition

…ed_system section size

…hen built by C (as opposed to C++) compiler. Replace const variables like OS_THREAD_INVALID_HANDLE in concurrent_hal.h with defines when being built by C compiler

…d of passing an integer argument to __builtin_return_address

…opy of previous trace data

avtolstoy mentioned this pull request Dec 21, 2017

[CH6178] Checkpoints/diagnostics #1369

Closed

6 tasks

m-mcgowan reviewed Jan 16, 2018

View reviewed changes

m-mcgowan added this to the 0.8.0-rc.2 milestone Jan 18, 2018

avtolstoy and others added 22 commits January 19, 2018 05:05

Photon/P1: FreeRTOS 'enhancements' for thread list / stacktrace acqui…

b6b28c0

…sition (see particle-iot/photon-wiced#18)

Electron: FreeRTOS 'enhancements' for thread list / stacktrace acquis…

cccb85a

…ition

Force -fomit-frame-pointer on ARM

03e698c

Add link_global_retained_system_end_section symbol to indicate retain…

4366e24

…ed_system section size

const variables declared in header files will have external linkage w…

b55fec8

…hen built by C (as opposed to C++) compiler. Replace const variables like OS_THREAD_INVALID_HANDLE in concurrent_hal.h with defines when being built by C compiler

os_thread_dump and HAL_Core_Generate_Stacktrace implementation

4dc9c04

platform-specific diagnostic definitions and implementations

f41b6ae

Adds platform dependency to communication and services libs

77a6165

communication: set LOG_COMPILE_TIME_LEVEL=LOG_LEVEL_ERROR

5967cad

DiagnosticService implementation

051aa28

LOG() statements should be checkpoints

32a077c

wiring: CHECKPOINT() implementation

c325052

Logger class log methods should be checkpoints as well

2a0dc89

JSONWriter: long int and long unsigned value overloads

ec29e51

DiagnosticService: unit tests

33de2e9

USB_REQUEST_GET_DIAGNOSTIC and USB_REQUEST_UPDATE_DIAGNOSTIC support

497df51

Small sample checkpoint demo app. TODO: tools

e735903

Sample CLI for checkpoint test app

830c66a

A hack to make certain versions of gcc happy: using constants, instea…

d708794

…d of passing an integer argument to __builtin_return_address

diagnostic -> tracer renaming

91d0e56

A bit better retained_system overflow checks, dynamically allocated c…

a266d1d

…opy of previous trace data

Some comments and minor fixes

95628c0

avtolstoy force-pushed the feature/tracer-rebase branch from 8e40494 to 95628c0 Compare January 18, 2018 22:05

m-mcgowan modified the milestones: 0.8.0-rc.2, 0.8.0-rc.3 Jan 24, 2018

avtolstoy modified the milestones: 0.8.0-rc.3, 0.8.0-rc.4 Mar 26, 2018

technobly modified the milestones: 0.8.0-rc.4, 0.8.0-rc.5 May 6, 2018

technobly added feature in progress labels May 31, 2019

technobly removed this from the 0.8.0-rc.5 milestone May 31, 2019

avtolstoy force-pushed the develop branch from c253104 to 55f59c1 Compare June 3, 2020 19:02

avtolstoy force-pushed the develop branch from 77b2534 to 5c09a50 Compare December 9, 2020 22:05

avtolstoy mentioned this pull request Feb 7, 2022

Add in os introspection functions to wrap the FreeRTOS functions #2394

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[CH6178] Tracer/checkpoints (rebase) #1451

[CH6178] Tracer/checkpoints (rebase) #1451

avtolstoy commented Dec 19, 2017

m-mcgowan left a comment

m-mcgowan Jan 16, 2018

avtolstoy Jan 16, 2018

m-mcgowan Jan 16, 2018

avtolstoy Jan 16, 2018

m-mcgowan Jan 16, 2018

avtolstoy Jan 16, 2018

m-mcgowan Jan 16, 2018

avtolstoy Jan 16, 2018

m-mcgowan Jan 16, 2018

avtolstoy Jan 16, 2018

m-mcgowan Jan 16, 2018

avtolstoy Jan 16, 2018

m-mcgowan Jan 16, 2018

avtolstoy Jan 16, 2018

m-mcgowan Jan 16, 2018

avtolstoy Jan 16, 2018

m-mcgowan Jan 16, 2018

avtolstoy Jan 16, 2018

m-mcgowan Jan 16, 2018

avtolstoy Jan 16, 2018 •

edited

Loading


		int count = 0;

		for (uint32_t* sp = (uint32_t)info->stack_start; sp <= (uint32_t)info->stack_end; sp++) {

[CH6178] Tracer/checkpoints (rebase) #1451

Are you sure you want to change the base?

[CH6178] Tracer/checkpoints (rebase) #1451

Conversation

avtolstoy commented Dec 19, 2017

Problem

Solution

Steps to Test

Example App

References

Completeness

m-mcgowan left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

avtolstoy Jan 16, 2018 • edited Loading

Choose a reason for hiding this comment

avtolstoy Jan 16, 2018 •

edited

Loading