This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

app_sched_evt_put() & NRF_ERROR_NO_MEM

Hi,

I've stumbled upon a problem that I haven't been able to solve for an extended period of time. I've found several other posts on this forum describing something vaguely similar but none of the solutions apply in our case.

It's a bug with our firmware that I haven't been able to reproduce under test conditions.

We have a custom board based on nrf52832 with S132.

Every once in a while it will die with error code #4 (NRF_ERROR_NO_MEM) during a call to  app_sched_evt_put().

We have implemented a solution for tracking the errors in the wild using RAM retention and the reports show that this error occurs all over the place, namely almost every line in our code where there's a reference to app_sched_evt_put() has produced this error.

Running the scheduler with the profiler enabled shows that under normal operating conditions the maximum queue utilization reaches 5 or 6 scheduled events at most.

I highly doubt that the problem is the OP_QUEUE size as we have it defined at 40 which to me seems like it should be more than enough under normal circumstances.

My suspicion is that the problem lies elsewhere and the queue gets filled up with events queued in the timer & interrupt context and there is something preventing the code execution from reaching app_sched_execute() in the main while loop.

There's one particular behavior that I've observed which occurs after 6 (!) seconds of a particular event not bein executed.

The way i've been trying to debug this is to significantly lower the watchdog timeout - from 10 seconds (on our production devices) to 2 seconds (on our debug devices) in hopes of catching the offending piece of code (my hope is that it triggers a watchdog reset instead of a soft reset) which seems to hang for 6 (!) seconds on certain occasions. I've implemented a ram retention based logging system that reports the PC before a watchdog interrupt has occured but so far I ahven't been able to zero-in on the source of the bug.

I'm mostly interested in strategy suggestions for trying to debug something like this. Or perhaps some tools that can speed up this process.

I would try tackling the problem with a debugger & dissassembly but sometimes it can take days for the problem to manifest

Parents
  • I highly doubt that the problem is the OP_QUEUE size

    As you're already recording stats, can you include recording what it thinks the queue size is at the time?

    Also Heap size?

  • heap size and stack size in the build settings are:

    __HEAP_SIZE=4096 __STACK_SIZE=8192

    I made a type earlier, the OP_QUEUE size is actually defined as 50

    I'm getting the queue utilization and queue space using

    app_sched_queue_utilization_get() & app_sched_queue_space_get() calls respectively 

    here's what my log looks like

    00> [00056276] <info> app: LITTLEFS: ALLOCATED BLOCKS: 62
    00> [00056276] <info> app: trying to save packet!
    00> [00056276] <info> app: Paket: 4 - Start recording
    00> [00056276] <info> app: Sucessfully Written: 5084 Bytes in File: 92
    00> [00056276] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056276] <info> app: Updated MQTT Send from Flash File Variable to Count: 60
    00> [00056276] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056277] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056277] <info> app: No Movement in 40 seconds! Bordnetz -> 1 Nachlauf -> 0
    00> [00056277] <info> app: Garage timer started
    00> [00056277] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056277] <info> app: Send From Flash 61: Saved in Flash: 92
    00> [00056277] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056277] <info> app: Updated MQTT Send from Flash File Variable to Count: 61
    00> [00056277] <info> app: Sucessfully Read: 5084 Bytes from File: 61
    00> [00056277] <info> app: removed file name: 61
    00> [00056277] <info> app: LITTLEFS: ALLOCATED BLOCKS: 62
    00> [00056278] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056278] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056279] <info> app: Send From Flash 62: Saved in Flash: 92
    00> [00056279] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056279] <info> app: Updated MQTT Send from Flash File Variable to Count: 62
    00> [00056279] <info> app: Sucessfully Read: 5084 Bytes from File: 62
    00> [00056279] <info> app: removed file name: 62
    00> [00056279] <info> app: LITTLEFS: ALLOCATED BLOCKS: 60
    00> [00056279] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056279] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056280] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056280] <info> app: Send From Flash 63: Saved in Flash: 92
    00> [00056280] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056280] <info> app: Updated MQTT Send from Flash File Variable to Count: 63
    00> [00056280] <info> app: Sucessfully Read: 5084 Bytes from File: 63
    00> [00056280] <info> app: removed file name: 63
    00> [00056280] <info> app: LITTLEFS: ALLOCATED BLOCKS: 58
    00> [00056280] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056281] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056282] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056282] <info> app: Send From Flash 64: Saved in Flash: 92
    00> [00056282] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056282] <info> app: Updated MQTT Send from Flash File Variable to Count: 64
    00> [00056282] <info> app: Sucessfully Read: 5084 Bytes from File: 64
    00> [00056282] <info> app: removed file name: 64
    00> [00056282] <info> app: LITTLEFS: ALLOCATED BLOCKS: 56
    00> [00056282] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056283] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056283] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056283] <info> app: Send From Flash 65: Saved in Flash: 92
    00> [00056283] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056283] <info> app: Updated MQTT Send from Flash File Variable to Count: 65
    00> [00056283] <info> app: Sucessfully Read: 5084 Bytes from File: 65
    00> [00056283] <info> app: removed file name: 65
    00> [00056283] <info> app: LITTLEFS: ALLOCATED BLOCKS: 54
    00> [00056284] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056284] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056285] <info> app: Send From Flash 66: Saved in Flash: 92
    00> [00056285] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056285] <info> app: Updated MQTT Send from Flash File Variable to Count: 66
    00> [00056285] <info> app: Sucessfully Read: 5084 Bytes from File: 66
    00> [00056285] <info> app: removed file name: 66
    00> [00056285] <info> app: LITTLEFS: ALLOCATED BLOCKS: 52
    00> [00056285] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056285] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056286] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056286] <info> app: Send From Flash 67: Saved in Flash: 92
    00> [00056286] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056286] <info> app: Updated MQTT Send from Flash File Variable to Count: 67
    00> [00056286] <info> app: Sucessfully Read: 5084 Bytes from File: 67
    00> [00056286] <info> app: removed file name: 67
    00> [00056286] <info> app: LITTLEFS: ALLOCATED BLOCKS: 50
    00> [00056286] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056287] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056288] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056288] <info> app: Send From Flash 68: Saved in Flash: 92
    00> [00056288] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056288] <info> app: Updated MQTT Send from Flash File Variable to Count: 68
    00> [00056288] <info> app: Sucessfully Read: 5084 Bytes from File: 68
    00> [00056288] <info> app: removed file name: 68
    00> [00056288] <info> app: LITTLEFS: ALLOCATED BLOCKS: 48
    00> [00056288] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056289] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056289] <info> app: Send From Flash 69: Saved in Flash: 92
    00> [00056289] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056289] <info> app: Updated MQTT Send from Flash File Variable to Count: 69
    00> [00056289] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056289] <info> app: Sucessfully Read: 5084 Bytes from File: 69
    00> [00056289] <info> app: removed file name: 69
    00> [00056289] <info> app: LITTLEFS: ALLOCATED BLOCKS: 46
    00> [00056290] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056290] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056291] <info> app: Send From Flash 70: Saved in Flash: 92
    00> [00056291] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056291] <info> app: Updated MQTT Send from Flash File Variable to Count: 70
    00> [00056291] <info> app: Sucessfully Read: 5084 Bytes from File: 70
    00> [00056291] <info> app: removed file name: 70
    00> [00056291] <info> app: LITTLEFS: ALLOCATED BLOCKS: 44
    00> [00056291] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056292] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056292] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056292] <info> app: Send From Flash 71: Saved in Flash: 92
    00> [00056292] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056292] <info> app: Updated MQTT Send from Flash File Variable to Count: 71
    00> [00056292] <info> app: Sucessfully Read: 5084 Bytes from File: 71
    00> [00056292] <info> app: removed file name: 71
    00> [00056292] <info> app: LITTLEFS: ALLOCATED BLOCKS: 42
    00> [00056293] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056293] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056294] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056294] <info> app: Send From Flash 72: Saved in Flash: 92
    00> [00056294] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056294] <info> app: Updated MQTT Send from Flash File Variable to Count: 72
    00> [00056294] <info> app: Sucessfully Read: 5084 Bytes from File: 72
    00> [00056294] <info> app: removed file name: 72
    00> [00056294] <info> app: LITTLEFS: ALLOCATED BLOCKS: 40
    00> [00056294] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056295] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056295] <info> app: Send From Flash 73: Saved in Flash: 92
    00> [00056295] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056295] <info> app: Updated MQTT Send from Flash File Variable to Count: 73
    00> [00056295] <info> app: Sucessfully Read: 5084 Bytes from File: 73
    00> [00056295] <info> app: removed file name: 73
    00> [00056295] <info> app: LITTLEFS: ALLOCATED BLOCKS: 38
    00> [00056295] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056296] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056296] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056297] <info> app: Send From Flash 74: Saved in Flash: 92
    00> [00056297] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056297] <info> app: Updated MQTT Send from Flash File Variable to Count: 74
    00> [00056297] <info> app: Sucessfully Read: 5084 Bytes from File: 74
    00> [00056297] <info> app: removed file name: 74
    00> [00056297] <info> app: LITTLEFS: ALLOCATED BLOCKS: 36
    00> [00056297] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056298] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056298] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056298] <info> app: Send From Flash 75: Saved in Flash: 92
    00> [00056298] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056298] <info> app: Updated MQTT Send from Flash File Variable to Count: 75
    00> [00056298] <info> app: Sucessfully Read: 5084 Bytes from File: 75
    00> [00056298] <info> app: removed file name: 75
    00> [00056298] <info> app: LITTLEFS: ALLOCATED BLOCKS: 34
    00> [00056299] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056299] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056300] <info> app: Send From Flash 76: Saved in Flash: 92
    00> [00056300] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056300] <info> app: Updated MQTT Send from Flash File Variable to Count: 76
    00> [00056300] <info> app: Sucessfully Read: 5084 Bytes from File: 76
    00> [00056300] <info> app: removed file name: 76
    00> [00056300] <info> app: LITTLEFS: ALLOCATED BLOCKS: 32
    00> [00056300] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056300] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056301] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056301] <info> app: Send From Flash 77: Saved in Flash: 92
    00> [00056301] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056301] <info> app: Updated MQTT Send from Flash File Variable to Count: 77
    00> [00056301] <info> app: Sucessfully Read: 5084 Bytes from File: 77
    00> [00056301] <info> app: removed file name: 77
    00> [00056301] <info> app: LITTLEFS: ALLOCATED BLOCKS: 30
    00> [00056302] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056302] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056303] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056303] <info> app: Send From Flash 78: Saved in Flash: 92
    00> [00056303] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056303] <info> app: Updated MQTT Send from Flash File Variable to Count: 78
    00> [00056303] <info> app: Sucessfully Read: 5084 Bytes from File: 78
    00> [00056303] <info> app: removed file name: 78
    00> [00056303] <info> app: LITTLEFS: ALLOCATED BLOCKS: 28
    00> [00056303] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056304] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056304] <info> app: Send From Flash 79: Saved in Flash: 92
    00> [00056304] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056304] <info> app: Updated MQTT Send from Flash File Variable to Count: 79
    00> [00056304] <info> app: Sucessfully Read: 5084 Bytes from File: 79
    00> [00056304] <info> app: removed file name: 79
    00> [00056305] <info> app: LITTLEFS: ALLOCATED BLOCKS: 26
    00> [00056305] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056305] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056306] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056306] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056306] <info> app: Send From Flash 80: Saved in Flash: 92
    00> [00056306] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056306] <info> app: Updated MQTT Send from Flash File Variable to Count: 80
    00> [00056306] <info> app: Sucessfully Read: 5084 Bytes from File: 80
    00> [00056306] <info> app: removed file name: 80
    00> [00056306] <info> app: LITTLEFS: ALLOCATED BLOCKS: 24
    00> [00056307] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056307] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056308] <info> app: Send From Flash 81: Saved in Flash: 92
    00> [00056308] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056308] <info> app: Updated MQTT Send from Flash File Variable to Count: 81
    00> [00056308] <info> app: Sucessfully Read: 5084 Bytes from File: 81
    00> [00056308] <info> app: removed file name: 81
    00> [00056308] <info> app: LITTLEFS: ALLOCATED BLOCKS: 22
    00> [00056308] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056309] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056309] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056309] <info> app: Send From Flash 82: Saved in Flash: 92
    00> [00056309] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056309] <info> app: Updated MQTT Send from Flash File Variable to Count: 82
    00> [00056309] <info> app: Sucessfully Read: 5084 Bytes from File: 82
    00> [00056309] <info> app: removed file name: 82
    00> [00056309] <info> app: LITTLEFS: ALLOCATED BLOCKS: 20
    00> [00056310] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056310] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056311] <info> app: Send From Flash 83: Saved in Flash: 92
    00> [00056311] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056311] <info> app: Updated MQTT Send from Flash File Variable to Count: 83
    00> [00056311] <info> app: Sucessfully Read: 5084 Bytes from File: 83
    00> [00056311] <info> app: removed file name: 83
    00> [00056311] <info> app: LITTLEFS: ALLOCATED BLOCKS: 18
    00> [00056311] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056311] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056312] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056312] <info> app: Send From Flash 84: Saved in Flash: 92
    00> [00056312] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056312] <info> app: Updated MQTT Send from Flash File Variable to Count: 84
    00> [00056312] <info> app: Sucessfully Read: 5084 Bytes from File: 84
    00> [00056312] <info> app: removed file name: 84
    00> [00056312] <info> app: LITTLEFS: ALLOCATED BLOCKS: 16
    00> [00056312] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056313] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056314] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056314] <info> app: Send From Flash 85: Saved in Flash: 92
    00> [00056314] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056314] <info> app: Updated MQTT Send from Flash File Variable to Count: 85
    00> [00056314] <info> app: Sucessfully Read: 5084 Bytes from File: 85
    00> [00056314] <info> app: removed file name: 85
    00> [00056314] <info> app: LITTLEFS: ALLOCATED BLOCKS: 14
    00> [00056314] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056315] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056315] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056315] <info> app: Send From Flash 86: Saved in Flash: 92
    00> [00056315] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056315] <info> app: Updated MQTT Send from Flash File Variable to Count: 86
    00> [00056315] <info> app: Sucessfully Read: 5084 Bytes from File: 86
    00> [00056316] <info> app: removed file name: 86
    00> [00056316] <info> app: LITTLEFS: ALLOCATED BLOCKS: 12
    00> [00056316] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056317] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056317] <info> app: Send From Flash 87: Saved in Flash: 92
    00> [00056317] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056317] <info> app: Updated MQTT Send from Flash File Variable to Count: 87
    00> [00056317] <info> app: Sucessfully Read: 5084 Bytes from File: 87
    00> [00056317] <info> app: removed file name: 87
    00> [00056317] <info> app: LITTLEFS: ALLOCATED BLOCKS: 10
    00> [00056318] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056318] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056319] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056319] <info> app: Send From Flash 88: Saved in Flash: 92
    00> [00056319] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056319] <info> app: Updated MQTT Send from Flash File Variable to Count: 88
    00> [00056319] <info> app: Sucessfully Read: 5084 Bytes from File: 88
    00> [00056319] <info> app: removed file name: 88
    00> [00056319] <info> app: LITTLEFS: ALLOCATED BLOCKS: 8
    00> [00056319] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056320] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056320] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056320] <info> app: Send From Flash 89: Saved in Flash: 92
    00> [00056320] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056320] <info> app: Updated MQTT Send from Flash File Variable to Count: 89
    00> [00056320] <info> app: Sucessfully Read: 5084 Bytes from File: 89
    00> [00056320] <info> app: removed file name: 89
    00> [00056320] <info> app: LITTLEFS: ALLOCATED BLOCKS: 6
    00> [00056321] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056321] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056322] <info> app: Send From Flash 90: Saved in Flash: 92
    00> [00056322] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056322] <info> app: Updated MQTT Send from Flash File Variable to Count: 90
    00> [00056322] <info> app: Sucessfully Read: 5084 Bytes from File: 90
    00> [00056322] <info> app: removed file name: 90
    00> [00056322] <info> app: LITTLEFS: ALLOCATED BLOCKS: 4
    00> [00056322] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056322] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056323] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056323] <info> app: Send From Flash 91: Saved in Flash: 92
    00> [00056323] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056323] <info> app: Updated MQTT Send from Flash File Variable to Count: 91
    00> [00056323] <info> app: Sucessfully Read: 5084 Bytes from File: 91
    00> [00056323] <info> app: removed file name: 91
    00> [00056323] <info> app: LITTLEFS: ALLOCATED BLOCKS: 2
    00> [00056323] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056324] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056324] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056324] <info> app: Send From Flash 92: Saved in Flash: 92
    00> [00056324] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056324] <info> app: Updated MQTT Send from Flash File Variable to Count: 92
    00> [00056325] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056326] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056326] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056327] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056327] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056328] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056329] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056329] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056330] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056330] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056331] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056332] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056332] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056333] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056333] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056334] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056335] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056335] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056336] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056336] <info> app: trying to send direct!
    00> [00056336] <info> app: Paket: 5 - Start recording
    00> [00056336] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056337] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056338] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056338] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056339] <info> app: Send direct 1
    00> [00056339] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056339] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056340] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056340] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056341] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056342] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056342] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056343] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056344] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056344] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056345] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056345] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056346] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056347] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056347] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056348] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056348] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056349] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056350] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056350] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056351] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056351] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056352] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056353] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056353] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056354] <info> app: maximum observed queue utilization 6 - free space in the queue: 49

    Here's the device is doing pretty much everything that's required of it:

    Collecting data from multiple external sensors over i2c & spi, Streaming this data over BLE, communicating with a modem over UART, Reading&writing data to SPI NOR flash, Multiple timers running, etc.

    and still utilization doesn't go above six, and as you can see the events are being dealt with sucessfully.

    The closest i've come to recreating this error is by just putting putting nrf_delay_ms(7500) (somewhat arbitrary timeout) in code and shaking the device vigorously to generate motion interrupts.

    I also doubt it's one of the interrupts going crazy & scheduling countless events as i would expect the same location in code to be reported every time...

Reply
  • heap size and stack size in the build settings are:

    __HEAP_SIZE=4096 __STACK_SIZE=8192

    I made a type earlier, the OP_QUEUE size is actually defined as 50

    I'm getting the queue utilization and queue space using

    app_sched_queue_utilization_get() & app_sched_queue_space_get() calls respectively 

    here's what my log looks like

    00> [00056276] <info> app: LITTLEFS: ALLOCATED BLOCKS: 62
    00> [00056276] <info> app: trying to save packet!
    00> [00056276] <info> app: Paket: 4 - Start recording
    00> [00056276] <info> app: Sucessfully Written: 5084 Bytes in File: 92
    00> [00056276] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056276] <info> app: Updated MQTT Send from Flash File Variable to Count: 60
    00> [00056276] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056277] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056277] <info> app: No Movement in 40 seconds! Bordnetz -> 1 Nachlauf -> 0
    00> [00056277] <info> app: Garage timer started
    00> [00056277] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056277] <info> app: Send From Flash 61: Saved in Flash: 92
    00> [00056277] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056277] <info> app: Updated MQTT Send from Flash File Variable to Count: 61
    00> [00056277] <info> app: Sucessfully Read: 5084 Bytes from File: 61
    00> [00056277] <info> app: removed file name: 61
    00> [00056277] <info> app: LITTLEFS: ALLOCATED BLOCKS: 62
    00> [00056278] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056278] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056279] <info> app: Send From Flash 62: Saved in Flash: 92
    00> [00056279] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056279] <info> app: Updated MQTT Send from Flash File Variable to Count: 62
    00> [00056279] <info> app: Sucessfully Read: 5084 Bytes from File: 62
    00> [00056279] <info> app: removed file name: 62
    00> [00056279] <info> app: LITTLEFS: ALLOCATED BLOCKS: 60
    00> [00056279] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056279] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056280] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056280] <info> app: Send From Flash 63: Saved in Flash: 92
    00> [00056280] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056280] <info> app: Updated MQTT Send from Flash File Variable to Count: 63
    00> [00056280] <info> app: Sucessfully Read: 5084 Bytes from File: 63
    00> [00056280] <info> app: removed file name: 63
    00> [00056280] <info> app: LITTLEFS: ALLOCATED BLOCKS: 58
    00> [00056280] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056281] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056282] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056282] <info> app: Send From Flash 64: Saved in Flash: 92
    00> [00056282] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056282] <info> app: Updated MQTT Send from Flash File Variable to Count: 64
    00> [00056282] <info> app: Sucessfully Read: 5084 Bytes from File: 64
    00> [00056282] <info> app: removed file name: 64
    00> [00056282] <info> app: LITTLEFS: ALLOCATED BLOCKS: 56
    00> [00056282] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056283] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056283] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056283] <info> app: Send From Flash 65: Saved in Flash: 92
    00> [00056283] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056283] <info> app: Updated MQTT Send from Flash File Variable to Count: 65
    00> [00056283] <info> app: Sucessfully Read: 5084 Bytes from File: 65
    00> [00056283] <info> app: removed file name: 65
    00> [00056283] <info> app: LITTLEFS: ALLOCATED BLOCKS: 54
    00> [00056284] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056284] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056285] <info> app: Send From Flash 66: Saved in Flash: 92
    00> [00056285] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056285] <info> app: Updated MQTT Send from Flash File Variable to Count: 66
    00> [00056285] <info> app: Sucessfully Read: 5084 Bytes from File: 66
    00> [00056285] <info> app: removed file name: 66
    00> [00056285] <info> app: LITTLEFS: ALLOCATED BLOCKS: 52
    00> [00056285] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056285] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056286] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056286] <info> app: Send From Flash 67: Saved in Flash: 92
    00> [00056286] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056286] <info> app: Updated MQTT Send from Flash File Variable to Count: 67
    00> [00056286] <info> app: Sucessfully Read: 5084 Bytes from File: 67
    00> [00056286] <info> app: removed file name: 67
    00> [00056286] <info> app: LITTLEFS: ALLOCATED BLOCKS: 50
    00> [00056286] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056287] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056288] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056288] <info> app: Send From Flash 68: Saved in Flash: 92
    00> [00056288] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056288] <info> app: Updated MQTT Send from Flash File Variable to Count: 68
    00> [00056288] <info> app: Sucessfully Read: 5084 Bytes from File: 68
    00> [00056288] <info> app: removed file name: 68
    00> [00056288] <info> app: LITTLEFS: ALLOCATED BLOCKS: 48
    00> [00056288] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056289] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056289] <info> app: Send From Flash 69: Saved in Flash: 92
    00> [00056289] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056289] <info> app: Updated MQTT Send from Flash File Variable to Count: 69
    00> [00056289] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056289] <info> app: Sucessfully Read: 5084 Bytes from File: 69
    00> [00056289] <info> app: removed file name: 69
    00> [00056289] <info> app: LITTLEFS: ALLOCATED BLOCKS: 46
    00> [00056290] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056290] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056291] <info> app: Send From Flash 70: Saved in Flash: 92
    00> [00056291] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056291] <info> app: Updated MQTT Send from Flash File Variable to Count: 70
    00> [00056291] <info> app: Sucessfully Read: 5084 Bytes from File: 70
    00> [00056291] <info> app: removed file name: 70
    00> [00056291] <info> app: LITTLEFS: ALLOCATED BLOCKS: 44
    00> [00056291] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056292] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056292] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056292] <info> app: Send From Flash 71: Saved in Flash: 92
    00> [00056292] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056292] <info> app: Updated MQTT Send from Flash File Variable to Count: 71
    00> [00056292] <info> app: Sucessfully Read: 5084 Bytes from File: 71
    00> [00056292] <info> app: removed file name: 71
    00> [00056292] <info> app: LITTLEFS: ALLOCATED BLOCKS: 42
    00> [00056293] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056293] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056294] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056294] <info> app: Send From Flash 72: Saved in Flash: 92
    00> [00056294] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056294] <info> app: Updated MQTT Send from Flash File Variable to Count: 72
    00> [00056294] <info> app: Sucessfully Read: 5084 Bytes from File: 72
    00> [00056294] <info> app: removed file name: 72
    00> [00056294] <info> app: LITTLEFS: ALLOCATED BLOCKS: 40
    00> [00056294] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056295] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056295] <info> app: Send From Flash 73: Saved in Flash: 92
    00> [00056295] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056295] <info> app: Updated MQTT Send from Flash File Variable to Count: 73
    00> [00056295] <info> app: Sucessfully Read: 5084 Bytes from File: 73
    00> [00056295] <info> app: removed file name: 73
    00> [00056295] <info> app: LITTLEFS: ALLOCATED BLOCKS: 38
    00> [00056295] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056296] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056296] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056297] <info> app: Send From Flash 74: Saved in Flash: 92
    00> [00056297] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056297] <info> app: Updated MQTT Send from Flash File Variable to Count: 74
    00> [00056297] <info> app: Sucessfully Read: 5084 Bytes from File: 74
    00> [00056297] <info> app: removed file name: 74
    00> [00056297] <info> app: LITTLEFS: ALLOCATED BLOCKS: 36
    00> [00056297] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056298] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056298] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056298] <info> app: Send From Flash 75: Saved in Flash: 92
    00> [00056298] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056298] <info> app: Updated MQTT Send from Flash File Variable to Count: 75
    00> [00056298] <info> app: Sucessfully Read: 5084 Bytes from File: 75
    00> [00056298] <info> app: removed file name: 75
    00> [00056298] <info> app: LITTLEFS: ALLOCATED BLOCKS: 34
    00> [00056299] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056299] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056300] <info> app: Send From Flash 76: Saved in Flash: 92
    00> [00056300] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056300] <info> app: Updated MQTT Send from Flash File Variable to Count: 76
    00> [00056300] <info> app: Sucessfully Read: 5084 Bytes from File: 76
    00> [00056300] <info> app: removed file name: 76
    00> [00056300] <info> app: LITTLEFS: ALLOCATED BLOCKS: 32
    00> [00056300] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056300] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056301] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056301] <info> app: Send From Flash 77: Saved in Flash: 92
    00> [00056301] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056301] <info> app: Updated MQTT Send from Flash File Variable to Count: 77
    00> [00056301] <info> app: Sucessfully Read: 5084 Bytes from File: 77
    00> [00056301] <info> app: removed file name: 77
    00> [00056301] <info> app: LITTLEFS: ALLOCATED BLOCKS: 30
    00> [00056302] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056302] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056303] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056303] <info> app: Send From Flash 78: Saved in Flash: 92
    00> [00056303] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056303] <info> app: Updated MQTT Send from Flash File Variable to Count: 78
    00> [00056303] <info> app: Sucessfully Read: 5084 Bytes from File: 78
    00> [00056303] <info> app: removed file name: 78
    00> [00056303] <info> app: LITTLEFS: ALLOCATED BLOCKS: 28
    00> [00056303] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056304] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056304] <info> app: Send From Flash 79: Saved in Flash: 92
    00> [00056304] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056304] <info> app: Updated MQTT Send from Flash File Variable to Count: 79
    00> [00056304] <info> app: Sucessfully Read: 5084 Bytes from File: 79
    00> [00056304] <info> app: removed file name: 79
    00> [00056305] <info> app: LITTLEFS: ALLOCATED BLOCKS: 26
    00> [00056305] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056305] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056306] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056306] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056306] <info> app: Send From Flash 80: Saved in Flash: 92
    00> [00056306] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056306] <info> app: Updated MQTT Send from Flash File Variable to Count: 80
    00> [00056306] <info> app: Sucessfully Read: 5084 Bytes from File: 80
    00> [00056306] <info> app: removed file name: 80
    00> [00056306] <info> app: LITTLEFS: ALLOCATED BLOCKS: 24
    00> [00056307] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056307] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056308] <info> app: Send From Flash 81: Saved in Flash: 92
    00> [00056308] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056308] <info> app: Updated MQTT Send from Flash File Variable to Count: 81
    00> [00056308] <info> app: Sucessfully Read: 5084 Bytes from File: 81
    00> [00056308] <info> app: removed file name: 81
    00> [00056308] <info> app: LITTLEFS: ALLOCATED BLOCKS: 22
    00> [00056308] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056309] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056309] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056309] <info> app: Send From Flash 82: Saved in Flash: 92
    00> [00056309] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056309] <info> app: Updated MQTT Send from Flash File Variable to Count: 82
    00> [00056309] <info> app: Sucessfully Read: 5084 Bytes from File: 82
    00> [00056309] <info> app: removed file name: 82
    00> [00056309] <info> app: LITTLEFS: ALLOCATED BLOCKS: 20
    00> [00056310] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056310] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056311] <info> app: Send From Flash 83: Saved in Flash: 92
    00> [00056311] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056311] <info> app: Updated MQTT Send from Flash File Variable to Count: 83
    00> [00056311] <info> app: Sucessfully Read: 5084 Bytes from File: 83
    00> [00056311] <info> app: removed file name: 83
    00> [00056311] <info> app: LITTLEFS: ALLOCATED BLOCKS: 18
    00> [00056311] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056311] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056312] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056312] <info> app: Send From Flash 84: Saved in Flash: 92
    00> [00056312] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056312] <info> app: Updated MQTT Send from Flash File Variable to Count: 84
    00> [00056312] <info> app: Sucessfully Read: 5084 Bytes from File: 84
    00> [00056312] <info> app: removed file name: 84
    00> [00056312] <info> app: LITTLEFS: ALLOCATED BLOCKS: 16
    00> [00056312] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056313] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056314] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056314] <info> app: Send From Flash 85: Saved in Flash: 92
    00> [00056314] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056314] <info> app: Updated MQTT Send from Flash File Variable to Count: 85
    00> [00056314] <info> app: Sucessfully Read: 5084 Bytes from File: 85
    00> [00056314] <info> app: removed file name: 85
    00> [00056314] <info> app: LITTLEFS: ALLOCATED BLOCKS: 14
    00> [00056314] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056315] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056315] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056315] <info> app: Send From Flash 86: Saved in Flash: 92
    00> [00056315] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056315] <info> app: Updated MQTT Send from Flash File Variable to Count: 86
    00> [00056315] <info> app: Sucessfully Read: 5084 Bytes from File: 86
    00> [00056316] <info> app: removed file name: 86
    00> [00056316] <info> app: LITTLEFS: ALLOCATED BLOCKS: 12
    00> [00056316] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056317] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056317] <info> app: Send From Flash 87: Saved in Flash: 92
    00> [00056317] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056317] <info> app: Updated MQTT Send from Flash File Variable to Count: 87
    00> [00056317] <info> app: Sucessfully Read: 5084 Bytes from File: 87
    00> [00056317] <info> app: removed file name: 87
    00> [00056317] <info> app: LITTLEFS: ALLOCATED BLOCKS: 10
    00> [00056318] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056318] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056319] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056319] <info> app: Send From Flash 88: Saved in Flash: 92
    00> [00056319] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056319] <info> app: Updated MQTT Send from Flash File Variable to Count: 88
    00> [00056319] <info> app: Sucessfully Read: 5084 Bytes from File: 88
    00> [00056319] <info> app: removed file name: 88
    00> [00056319] <info> app: LITTLEFS: ALLOCATED BLOCKS: 8
    00> [00056319] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056320] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056320] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056320] <info> app: Send From Flash 89: Saved in Flash: 92
    00> [00056320] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056320] <info> app: Updated MQTT Send from Flash File Variable to Count: 89
    00> [00056320] <info> app: Sucessfully Read: 5084 Bytes from File: 89
    00> [00056320] <info> app: removed file name: 89
    00> [00056320] <info> app: LITTLEFS: ALLOCATED BLOCKS: 6
    00> [00056321] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056321] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056322] <info> app: Send From Flash 90: Saved in Flash: 92
    00> [00056322] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056322] <info> app: Updated MQTT Send from Flash File Variable to Count: 90
    00> [00056322] <info> app: Sucessfully Read: 5084 Bytes from File: 90
    00> [00056322] <info> app: removed file name: 90
    00> [00056322] <info> app: LITTLEFS: ALLOCATED BLOCKS: 4
    00> [00056322] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056322] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056323] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056323] <info> app: Send From Flash 91: Saved in Flash: 92
    00> [00056323] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056323] <info> app: Updated MQTT Send from Flash File Variable to Count: 91
    00> [00056323] <info> app: Sucessfully Read: 5084 Bytes from File: 91
    00> [00056323] <info> app: removed file name: 91
    00> [00056323] <info> app: LITTLEFS: ALLOCATED BLOCKS: 2
    00> [00056323] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056324] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056324] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056324] <info> app: Send From Flash 92: Saved in Flash: 92
    00> [00056324] <info> app: Updated MQTT Saved into Flash File Variable to Count: 92
    00> [00056324] <info> app: Updated MQTT Send from Flash File Variable to Count: 92
    00> [00056325] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056326] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056326] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056327] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056327] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056328] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056329] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056329] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056330] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056330] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056331] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056332] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056332] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056333] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056333] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056334] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056335] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056335] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056336] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056336] <info> app: trying to send direct!
    00> [00056336] <info> app: Paket: 5 - Start recording
    00> [00056336] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056337] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056338] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056338] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056339] <info> app: Send direct 1
    00> [00056339] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056339] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056340] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056340] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056341] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056342] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056342] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056343] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056344] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056344] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056345] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056345] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056346] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056347] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056347] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056348] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056348] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056349] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056350] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056350] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056351] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056351] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056352] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056353] <info> app: maximum observed queue utilization 6 - free space in the queue: 50
    00> [00056353] <info> app: maximum observed queue utilization 6 - free space in the queue: 49
    00> [00056354] <info> app: maximum observed queue utilization 6 - free space in the queue: 49

    Here's the device is doing pretty much everything that's required of it:

    Collecting data from multiple external sensors over i2c & spi, Streaming this data over BLE, communicating with a modem over UART, Reading&writing data to SPI NOR flash, Multiple timers running, etc.

    and still utilization doesn't go above six, and as you can see the events are being dealt with sucessfully.

    The closest i've come to recreating this error is by just putting putting nrf_delay_ms(7500) (somewhat arbitrary timeout) in code and shaking the device vigorously to generate motion interrupts.

    I also doubt it's one of the interrupts going crazy & scheduling countless events as i would expect the same location in code to be reported every time...

Children
  • Hi,

    It seems like the most likely reason for the queue getting full is that at some point it is no longer processed, typically because your main loop does not run. That is also what happens when you use nrf_delay_ms(7500). There is no generic way to find out what without a debugger attached though, which may be difficult if the issue is not easily reproducible. Perhaps you could try to add some instrumentation in form of logging or toggling different GPIOs upon entering and exiting event handlers etc. to try to narrow down that way.

  • I'm considering deploying a "field debugging solution". probably a raspberry pi which would be able to run gdb (i've had some moderate success with openocd and some usb debuggers). What would you suggest as a strategy in this case? unfortunately I don't have a debugger capable of ETM or profiling. Placing breakpoints all over the code would be ineffective since it would essentialy suspend exection and i should be able to have it running over an extended period of time (days). 

    considering a hypothetical situation where gdb is freely available but the bug cannot be recreated manually, what would the approach be to identify the piece of code that hangs?

    My strategy was to try to zero in on the issue with a watchdog timeout but so far the NO_MEM error persists where i would now expect a wdt timeout to trigger

  • Hi,

    nikolozka said:
    considering a hypothetical situation where gdb is freely available but the bug cannot be recreated manually, what would the approach be to identify the piece of code that hangs?

    The most naïve would be to pause execution and if most of the time is spent doing a particular task you have a good chance of getting lucky and pausing while the stack pointer is in the problematic region. (Perhaps there is a bad state that causes an eternal loop in a low priority interrupt, preventing the main loop from running so that the queue fills up, but higher priority interrupts still occur and fills up the queue. This is just a wild guess though.)

    nikolozka said:
    My strategy was to try to zero in on the issue with a watchdog timeout but so far the NO_MEM error persists where i would now expect a wdt timeout to trigger

    Apparently the device is in a bad state but you continue to feed the watchdog. How do you feed the watchdog? From where? And what is the criteria for feeding it or not? Should that be adjusted? And if you adjust it and then see the watchdog trigger, perhaps that would also give a clue about where there problem is?

  • The most naïve would be to pause execution and if most of the time is spent doing a particular task you have a good chance of getting lucky and pausing while the stack pointer is in the problematic region. (Perhaps there is a bad state that causes an eternal loop in a low priority interrupt, preventing the main loop from running so that the queue fills up, but higher priority interrupts still occur and fills up the queue. This is just a wild guess though.)

    This is quite close to what is happening. new events that are triggering the no_mem error originat in the timer module and gpiote interrupts. that's a start - to look for lower priority interrupt calls. I'll try that.

    Apparently the device is in a bad state but you continue to feed the watchdog. How do you feed the watchdog? From where? And what is the criteria for feeding it or not? Should that be adjusted? And if you adjust it and then see the watchdog trigger, perhaps that would also give a clue about where there problem is?

    This is also a good point I was under the impression that WDT only gets fed from the same main loop that calls app_sched_execute but seems like i was wrong (I've taken over the codebase a few months ago and it's never ceases to surprise me Upside down). I've found some other places where the watchdog gets fed - and those bits of code are gonna fall under scrutiny next.

    thanks for the debugger pausing suggestion too. I'll see if it yields any interesting results...

    Seems like I've got a lot of stuff to do... but i'll be back

    Thanks Einar

  • Looking at the priority system, I had this thought:

    Are there any downsides to implementing a timer that runs with elevated priority, say priority 3,

    that would occasionally fire and just call app_sched execute, to guarantee that events are cleared.

    obviosly nothing except for softdevice is running with higher priority. Gpiote has priority 3 at the moment (dubious) but surely even gpiote events would be cleared this way even if they are the one's responsible.

    everything else is running with priority 6. But my understanding is that main runs at an even lower priority...

    Is there anything inherently wrong with this approach? other than ofcourse it doesn't solve the underlying problem...

    also following your suggestion I tried pausing the debugger but under normal circumstances the PC  always points at  SEV which is what one would expect. This indicates to me that the offending piece of code doesn't normally take long to execute and only ends up in this state under specific conditions.

Related