Crazy nested stack in fds_record_write

[dare]

I have a test program that does a simple call to fds_record_write() to write a 4 byte value to an FDS file.  This is using the NVMC backend.  I happened to stop the debugger in my FDS event handler and discovered that the stack is 35 frames deep at the point the callback happens.  For some reason the code is recursively calling the FDS queue_process() function, despite the fact that this function has a while loop in it to process multiple events.

Can someone explain why I need 35 stack frames and over 1K of stack space just to write 4 bytes to flash?

gdb output follows.

--Jay

----------------

#0  on_write_complete () at ./main.c:127
#1  0x0000031e in fds_evt_handler (p_fds_evt=0x20000cc4 <ucHeap+804>) at ./main.c:141
#2  0x00002636 in event_send (p_evt=0x20000cc4 <ucHeap+804>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:109
#3  0x00003b0e in queue_process (result=7453)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1459
#4  0x00003b7a in fs_event_handler (p_evt=0x20000d00 <ucHeap+864>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1492
#5  0x0000441e in event_send (p_fs=0x2000023c <m_fs>, evt_id=NRF_FSTORAGE_EVT_WRITE_RESULT, p_src=0x200008b4 <m_queue_data+8>,
    addr=1036480, len=4, p_param=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage_nvmc.c:93
#6  0x000044da in write (p_fs=0x2000023c <m_fs>, dest=1036480, p_src=0x200008b4 <m_queue_data+8>, len=4, p_param=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage_nvmc.c:144
#7  0x000041b4 in nrf_fstorage_write (p_fs=0x2000023c <m_fs>, dest=1036480, p_src=0x200008b4 <m_queue_data+8>, len=4,
    p_context=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage.c:149
#8  0x00003170 in record_header_write_finalize (p_op=0x200008ac <m_queue_data>, p_addr=0xfd0bc)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:781
#9  0x000038f6 in write_execute (prev_ret=0, p_op=0x200008ac <m_queue_data>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1258
#10 0x00003aa8 in queue_process (result=0)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1420
#11 0x00003b7a in fs_event_handler (p_evt=0x20000df0 <ucHeap+1104>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1492
#12 0x0000441e in event_send (p_fs=0x2000023c <m_fs>, evt_id=NRF_FSTORAGE_EVT_WRITE_RESULT, p_src=0x20001100 <ucHeap+1888>,
    addr=1036488, len=4, p_param=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage_nvmc.c:93
#13 0x000044da in write (p_fs=0x2000023c <m_fs>, dest=1036488, p_src=0x20001100 <ucHeap+1888>, len=4, p_param=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage_nvmc.c:144
#14 0x000041b4 in nrf_fstorage_write (p_fs=0x2000023c <m_fs>, dest=1036488, p_src=0x20001100 <ucHeap+1888>, len=4,
    p_context=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage.c:149
#15 0x000032be in record_write_data (p_op=0x200008ac <m_queue_data>, p_addr=0xfd0bc)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:878
#16 0x000038ea in write_execute (prev_ret=0, p_op=0x200008ac <m_queue_data>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1254
#17 0x00003aa8 in queue_process (result=0)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1420
#18 0x00003b7a in fs_event_handler (p_evt=0x20000ee0 <ucHeap+1344>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1492
#19 0x0000441e in event_send (p_fs=0x2000023c <m_fs>, evt_id=NRF_FSTORAGE_EVT_WRITE_RESULT, p_src=0x200008b8 <m_queue_data+12>,
    addr=1036484, len=4, p_param=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage_nvmc.c:93
#20 0x000044da in write (p_fs=0x2000023c <m_fs>, dest=1036484, p_src=0x200008b8 <m_queue_data+12>, len=4, p_param=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage_nvmc.c:144
#21 0x000041b4 in nrf_fstorage_write (p_fs=0x2000023c <m_fs>, dest=1036484, p_src=0x200008b8 <m_queue_data+12>, len=4,
    p_context=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage.c:149
#22 0x00003120 in record_header_write_id (p_op=0x200008ac <m_queue_data>, p_addr=0xfd0bc)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:765
#23 0x000038de in write_execute (prev_ret=0, p_op=0x200008ac <m_queue_data>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1250
#24 0x00003aa8 in queue_process (result=0)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1420
#25 0x00003b7a in fs_event_handler (p_evt=0x20000fd0 <ucHeap+1584>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1492
#26 0x0000441e in event_send (p_fs=0x2000023c <m_fs>, evt_id=NRF_FSTORAGE_EVT_WRITE_RESULT, p_src=0x200008b0 <m_queue_data+4>,
    addr=1036476, len=4, p_param=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage_nvmc.c:93
#27 0x000044da in write (p_fs=0x2000023c <m_fs>, dest=1036476, p_src=0x200008b0 <m_queue_data+4>, len=4, p_param=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage_nvmc.c:144
#28 0x000041b4 in nrf_fstorage_write (p_fs=0x2000023c <m_fs>, dest=1036476, p_src=0x200008b0 <m_queue_data+4>, len=4,
    p_context=0x0 <__isr_vector>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fstorage/nrf_fstorage.c:149
#29 0x000030d2 in record_header_write_begin (p_op=0x200008ac <m_queue_data>, p_addr=0xfd0bc)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:749
#30 0x000038d2 in write_execute (prev_ret=0, p_op=0x200008ac <m_queue_data>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1246
#31 0x00003aa8 in queue_process (result=0)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1420
#32 0x00003b60 in queue_start () at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1485
#33 0x00003d00 in write_enqueue (p_desc=0x0 <__isr_vector>, p_record=0x200010f4 <ucHeap+1876>, p_tok=0x0 <__isr_vector>,
    op_code=FDS_OP_WRITE) at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1603
#34 0x00003f3a in fds_record_write (p_desc=0x0 <__isr_vector>, p_record=0x200010f4 <ucHeap+1876>)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/components/libraries/fds/fds.c:1926
#35 0x00000472 in test_fds (pvParameter=0x0 <__isr_vector>) at ./main.c:197
#36 0x00005028 in pxPortInitialiseStack (pxTopOfStack=0x0 <__isr_vector>, pxCode=0xa5a5a5a5, pvParameters=0xa5a5a5a5)
    at ./projects/misc/nRF52840/nRF5_SDK_15.2.0_9412b96/external/freertos/portable/CMSIS/nrf52/port_cmsis.c:147

---------

(gdb) f 35
#35 0x00000472 in test_fds (pvParameter=0x0 <__isr_vector>) at ./main.c:197
197            ret = fds_record_write(NULL, &rec);
(gdb) p $sp
$1 = (void *) 0x200010e8 <ucHeap+1864>
(gdb) f 0
#0  on_write_complete () at ./main.c:127
127        fds_write_complete = 1;
(gdb) p $sp
$2 = (void *) 0x20000c8c <ucHeap+748>
(gdb) p 0x200010e8 - 0x20000c8c
$3 = 1116

[Håkon Alseth]

Hi,

 

That was quite a lot of stacking.

I tested this at my end, with the flash_fds example from SDK v15.2, and got approx. half of your stack usage.

Breakpoint 1, fds_evt_handler (p_evt=0x2003fd7c) at ../../../main.c:145
145                 if (p_evt->result == FDS_SUCCESS)
(gdb) bt
#0  fds_evt_handler (p_evt=0x2003fd7c) at ../../../main.c:145
#1  0x000026a0 in event_send (p_evt=<optimized out>) at ../../../../../../components/libraries/fds/fds.c:109
#2  queue_process (result=<optimized out>) at ../../../../../../components/libraries/fds/fds.c:1459
#3  0x00007854 in event_send (p_fs=0x200002cc <m_fs>, p_param=0x0 <nrf_log_default_backends_init>, len=4,
    addr=1040396, p_src=0x20000aec <m_queue_data+36>, evt_id=NRF_FSTORAGE_EVT_WRITE_RESULT)
    at ../../../../../../components/libraries/fstorage/nrf_fstorage_nvmc.c:93
#4  write (p_fs=0x200002cc <m_fs>, dest=1040396, p_src=0x20000aec <m_queue_data+36>, len=4,
    p_param=0x0 <nrf_log_default_backends_init>)
    at ../../../../../../components/libraries/fstorage/nrf_fstorage_nvmc.c:144
#5  0x00002a88 in record_header_write_finalize (p_addr=0xfe008, p_op=<optimized out>)
    at ../../../../../../components/libraries/fds/fds.c:781
#6  write_execute (p_op=<optimized out>, prev_ret=<optimized out>)
    at ../../../../../../components/libraries/fds/fds.c:1258
#7  queue_process (result=<optimized out>) at ../../../../../../components/libraries/fds/fds.c:1420
#8  0x00007854 in event_send (p_fs=0x200002cc <m_fs>, p_param=0x0 <nrf_log_default_backends_init>, len=24,
    addr=1040404, p_src=0x2000009c <m_dummy_cfg>, evt_id=NRF_FSTORAGE_EVT_WRITE_RESULT)
    at ../../../../../../components/libraries/fstorage/nrf_fstorage_nvmc.c:93
#9  write (p_fs=0x200002cc <m_fs>, dest=1040404, p_src=0x2000009c <m_dummy_cfg>, len=24,
    p_param=0x0 <nrf_log_default_backends_init>)
    at ../../../../../../components/libraries/fstorage/nrf_fstorage_nvmc.c:144
#10 0x00002a40 in record_write_data (p_addr=0xfe008, p_op=<optimized out>)
    at ../../../../../../components/libraries/fds/fds.c:878
#11 write_execute (p_op=<optimized out>, prev_ret=<optimized out>)
    at ../../../../../../components/libraries/fds/fds.c:1254
#12 queue_process (result=<optimized out>) at ../../../../../../components/libraries/fds/fds.c:1420
#13 0x00007854 in event_send (p_fs=0x200002cc <m_fs>, p_param=0x0 <nrf_log_default_backends_init>, len=4,
    addr=1040400, p_src=0x20000af0 <m_queue_data+40>, evt_id=NRF_FSTORAGE_EVT_WRITE_RESULT)
    at ../../../../../../components/libraries/fstorage/nrf_fstorage_nvmc.c:93
#14 write (p_fs=0x200002cc <m_fs>, dest=1040400, p_src=0x20000af0 <m_queue_data+40>, len=4,
---Type <return> to continue, or q <return> to quit---
    p_param=0x0 <nrf_log_default_backends_init>)
    at ../../../../../../components/libraries/fstorage/nrf_fstorage_nvmc.c:144
#15 0x00002aae in record_header_write_id (p_addr=0xfe008, p_op=<optimized out>)
    at ../../../../../../components/libraries/fds/fds.c:765
#16 write_execute (p_op=<optimized out>, prev_ret=<optimized out>)
    at ../../../../../../components/libraries/fds/fds.c:1250
#17 queue_process (result=<optimized out>) at ../../../../../../components/libraries/fds/fds.c:1420
#18 0x00007854 in event_send (p_fs=0x200002cc <m_fs>, p_param=0x0 <nrf_log_default_backends_init>, len=4,
    addr=1040392, p_src=0x20000ae8 <m_queue_data+32>, evt_id=NRF_FSTORAGE_EVT_WRITE_RESULT)
    at ../../../../../../components/libraries/fstorage/nrf_fstorage_nvmc.c:93
#19 write (p_fs=0x200002cc <m_fs>, dest=1040392, p_src=0x20000ae8 <m_queue_data+32>, len=4,
    p_param=0x0 <nrf_log_default_backends_init>)
    at ../../../../../../components/libraries/fstorage/nrf_fstorage_nvmc.c:144
#20 0x0000299a in record_header_write_begin (p_addr=0xfe008, p_op=<optimized out>)
    at ../../../../../../components/libraries/fds/fds.c:749
#21 write_execute (p_op=<optimized out>, prev_ret=<optimized out>)
    at ../../../../../../components/libraries/fds/fds.c:1246
#22 queue_process (result=<optimized out>) at ../../../../../../components/libraries/fds/fds.c:1420
#23 0x000032f4 in queue_start () at ../../../../../../components/libraries/fds/fds.c:1485
#24 write_enqueue (op_code=FDS_OP_WRITE, p_tok=0x0 <nrf_log_default_backends_init>, p_record=0xbd34 <m_dummy_record>,
    p_desc=0x2003ffc8) at ../../../../../../components/libraries/fds/fds.c:1603
#25 fds_record_write (p_desc=p_desc@entry=0x2003ffc8, p_record=p_record@entry=0xbd34 <m_dummy_record>)
    at ../../../../../../components/libraries/fds/fds.c:1926
#26 0x00009842 in main () at ../../../main.c:348

(gdb) p $sp
$1 = (void *) 0x2003fd58
(gdb) f 25
#25 fds_record_write (p_desc=p_desc@entry=0x2003ffc8, p_record=p_record@entry=0xbd34 <m_dummy_record>)
    at ../../../../../../components/libraries/fds/fds.c:1926
1926        return write_enqueue(p_desc, p_record, NULL, FDS_OP_WRITE);
(gdb) p $sp
$2 = (void *) 0x2003ff98
(gdb) p 0x2003ff98-0x2003fd58
$3 = 576

Do you have any logging enabled or similar in your example? This might eat memory.

 

Best regards,

Håkon

[dare]

Thank you for looking into this. I appreciate the help.

I note that your test has fewer stack frames than mine.  I strongly suspect the difference is due to compiler optimization (static function inlining, specifically), which I have turned off to aid debugging.   I will retest with a higher optimization.

That said, I still contend that 576 bytes of stack is excessive for the task at hand, and that this stems from the recursive nature of the code, which seems unnecessary and wasteful.

I can probably dig in and rework the code myself, but it seems like Nordic might want to spend some time making this better for everyone.

Thanks again.

--Jay

[Håkon Alseth]

I agree with you, close to 600 bytes of stack used seems excessive. I'll report this internally so that the developers are aware of this.

Cheers,

Håkon