fstorage hang at sd_app_evt_wait()

Nordic DevZone
Nordic DevZone

I try to using nrf_fstorage_write() to write data to fstorage and then waiting writting finish. But it hang at sd_app_evt_wait().fstorage.h

#include "app_timer.h"
#include "error.h"
#include "fds_flash.h"
#include "fstorage.h"
#include "nrf_delay.h"
#include "nrf_fstorage.h"
#include "nrf_fstorage_sd.h"
#include "nrf_fstorage_nvmc.h"
#include "nrf_log.h"
#include "nrf_soc.h"
#include "spi_flash.h"

#define FSTORAGE_PAGE_NUM    3
#define FSTORAGE_WAIT_CNT    1000



static bool _gFstorageInitialized = false;
static bool _gFstorageEraseDone   = true;
static bool _gFstorageWriteDone   = true;
static bool _gFstoragePageDirty   = true;

static void _fstorageEvtHandler(nrf_fstorage_evt_t * p_evt);

NRF_FSTORAGE_DEF(nrf_fstorage_t _gFstorage) =
{
    /* Set a handler for fstorage events. */
    .evt_handler = _fstorageEvtHandler,

    /* These below are the boundaries of the flash space assigned to this instance of fstorage.
     * You must set these manually, even at runtime, before nrf_fstorage_init() is called.
     * The function nrf5_flash_end_addr_get() can be used to retrieve the last address on the
     * last page of flash available to write data. */
    .start_addr = 0x7D000,
    .end_addr   = 0x80000,
};

static void _fstorageEvtHandler(nrf_fstorage_evt_t * pEvt) {
    NRF_LOG_DEBUG("Evt e\n");
    switch (pEvt->id) {
        case NRF_FSTORAGE_EVT_WRITE_RESULT:
        {
            NRF_LOG_DEBUG("Evt w\n");
            _gFstorageWriteDone = true;
            if (pEvt->result != NRF_SUCCESS) {
               NRF_LOG_WARNING("fstorage writing failed %d bytes at address 0x%x.",
                            pEvt->len, pEvt->addr);
            } else {
                NRF_LOG_DEBUG("NRF_FSTORAGE_EVT_WRITE_RESULT ok");
                _gFstoragePageDirty = true;
            }
        } break;

        case NRF_FSTORAGE_EVT_ERASE_RESULT:
        {
            NRF_LOG_DEBUG("Evt er\n");
            _gFstorageEraseDone = true;
            if (pEvt->result != NRF_SUCCESS) {
                NRF_LOG_WARNING("fstorage erased failed %d page from address 0x%x.",
                                 pEvt->len, pEvt->addr);
            } else {
                NRF_LOG_DEBUG("NRF_FSTORAGE_EVT_ERASE_RESULT ok");
                _gFstoragePageDirty = false;
            }
        } break;

        default:
            break;
    }
     NRF_LOG_DEBUG("Evt x\n");
}

static uint32_t _fstorageGetEndAddr(void) {
    const uint32_t bootloaderAddr = BOOTLOADER_ADDRESS;
    const uint32_t pageSz         = NRF_FICR->CODEPAGESIZE;
    const uint32_t codeSz         = NRF_FICR->CODESIZE;

    return (bootloaderAddr != 0xFFFFFFFF ?
            bootloaderAddr : (codeSz * pageSz));
}

static uint32_t _fstorageGetStartAddr(void) {
    const uint32_t eraseUnit = _gFstorage.p_flash_info->erase_unit;
    const uint32_t endAddr = _fstorageGetEndAddr();
    const uint32_t bootloaderAddr = BOOTLOADER_ADDRESS;
    uint32_t startAddr;
    if (bootloaderAddr == 0xFFFFFFFF) {
        startAddr = endAddr - FDS_VIRTUAL_PAGES * eraseUnit; 
    } else {
        startAddr = bootloaderAddr - FSTORAGE_PAGE_NUM * eraseUnit;
    }

    NRF_LOG_DEBUG("endAddr=0x%x", endAddr);
    NRF_LOG_DEBUG("startAddr=0x%x", startAddr);
    return startAddr;
}
static bool _fstorageIsEraseNeeded(void) {
    return _gFstoragePageDirty;
}    

static uint32_t _fstorageRoundUpU32(const uint32_t len) {
    if (len % sizeof(uint32_t)) {
        return (len + sizeof(uint32_t) - (len % sizeof(uint32_t)));
    }

    return len;
}

static void power_manage(void)
{
#ifdef SOFTDEVICE_PRESENT
    (void) sd_app_evt_wait();
#else
    __WFE();
#endif
}

int _fstorageWait(const uint32_t timeOutCnt) {
#if 0
    NRF_LOG_DEBUG("timeOutCnt=%u\n", timeOutCnt);
    const uint32_t startCnt   = app_timer_cnt_get();
    NRF_LOG_DEBUG("startCnt=%u\n", startCnt);
    uint32_t endCnt;
    uint32_t diffCnt;

    do {
        endCnt           = app_timer_cnt_get();
        diffCnt          = app_timer_cnt_diff_compute(endCnt, startCnt);
        if (diffCnt >= timeOutCnt) {
            NRF_LOG_WARNING("_fstorage wait timeout\n");
            return ERROR_FSTORAGE_WAIT_TIMEOUT;
        }

        if (_gFstorageEraseDone && _gFstorageWriteDone) {
            break;
        }
    } while (true);

    NRF_LOG_DEBUG("endCnt=%u\n", endCnt);
#else
    while (nrf_fstorage_is_busy(&_gFstorage))
    {
        power_manage();
    }
#endif
		return 0;
    
}

int _fstorageRead(const uint32_t addr, const uint32_t len, uint8_t* data) {
    if (!_gFstorageInitialized) {
        return ERROR_FSTORAGE_UNINITIALIZED;
    }   

    const ret_code_t errCode = nrf_fstorage_read(&_gFstorage, addr, data, len);
    if (errCode != NRF_SUCCESS) {
        NRF_LOG_WARNING("nrf_fstorage_read() failed 0x%x\n", errCode);
        return ERROR_FSTORAGE_READ_FAIL;
    }

    return 0;
}

int _fstorageWrite(const uint32_t addr, const uint32_t len, void const* pData) {
    if (!_gFstorageInitialized) {
        return ERROR_FSTORAGE_UNINITIALIZED;
    }

    if (!_gFstorageEraseDone) {
        return ERROR_FSTORAGE_ERASE_ON_GOING;
    }

    if (!_gFstorageWriteDone) {
        return ERROR_FSTORAGE_WRITE_ON_GOING;
    }

    _gFstorageWriteDone = false;
    
    const uint32_t wlen = _fstorageRoundUpU32(len);
    const ret_code_t retCode = nrf_fstorage_write(&_gFstorage, addr, pData, wlen, NULL);
    if (retCode != NRF_SUCCESS) {
        NRF_LOG_WARNING("nrf_fstorage_write() failed 0x%x", retCode);
        return ERROR_FSTORAGE_WRITE_FAIL;
    }

    _fstorageWait(FSTORAGE_WAIT_CNT);

    return 0;
}


int fstorageInit(void) {
    _gFstorageInitialized = false;
    const ret_code_t errCode = nrf_fstorage_init(&_gFstorage, &nrf_fstorage_sd, NULL);
    if (errCode != NRF_SUCCESS) {
        NRF_LOG_WARNING("nrf_fstorage_init() failed 0x%x", errCode);
        return ERROR_FSTORAGE_INITIALIZE_FAIL;
    }

    _gFstorageInitialized = true;

    return 0;
}    

int fstorageErase(const uint32_t addr, const uint32_t pagesCnt) {
    if (!_gFstorageInitialized) {
        return ERROR_FSTORAGE_UNINITIALIZED;
    }

    if (!_gFstorageEraseDone) {
        return ERROR_FSTORAGE_ERASE_ON_GOING;
    }

    if (!_gFstorageWriteDone) {
        return ERROR_FSTORAGE_WRITE_ON_GOING;
    }    

    _gFstorageEraseDone = false;
    const ret_code_t errCode = nrf_fstorage_erase(&_gFstorage, addr, pagesCnt, NULL);
    if (errCode != NRF_SUCCESS) { 
        NRF_LOG_WARNING("nrf_fstorage_erase() failed 0x%x", errCode);
        return ERROR_FSTORAGE_ERASE_FAIL;
    }

    _fstorageWait(FSTORAGE_WAIT_CNT);
    
    return 0;
}

/*
int fstorageEraseFDS(void) {
    const uint32_t eraseUnit = _gFstorage.p_flash_info->erase_unit;
    const uint32_t endAddr = _fstorageGetEndAddr();
    const uint32_t bootloaderAddr = BOOTLOADER_ADDRESS;
    uint32_t addr;
    if (bootloaderAddr == 0xFFFFFFFF) {
        addr = endAddr - FDS_VIRTUAL_PAGES * eraseUnit; 
    } else {
        addr = bootloaderAddr - FDS_VIRTUAL_PAGES * eraseUnit;
    }
    
    const uint32_t pagesCnt  = FDS_VIRTUAL_PAGES;
    const ret_code_t errCode =  nrf_fstorage_erase(&_gFstorage, addr, pagesCnt, NULL);
    if (errCode != NRF_SUCCESS) { 
        NRF_LOG_WARNING("nrf_fstorage_erase() failed 0x%x\n", errCode);
        return ERROR_FSTORAGE_ERASE_FAIL;
    }

    return 0;
}
*/

int fstorageReadRecord(const uint32_t addr, record_t* pRecord) {
    uint8_t data[RECORD_LEN] = {0};
    if (_fstorageRead(addr, RECORD_LEN, data) != 0) {
        return ERROR_FDS_READ_FAIL;
    }

    data2Record(data, pRecord);

    return 0;
}    

int fstorageUpdateRecord(const record_data_type_t type, const record_t* pRecord) {
    const uint32_t addr = _fstorageGetStartAddr();
    NRF_LOG_DEBUG("type=%d, add=0x%x\n", type, addr);
    switch (type) {
        case RECORD_DATA_TYPE_START:
        {  
            NRF_LOG_DEBUG("RECORD_DATA_TYPE_START E\n");
            if (_fstorageIsEraseNeeded()) {
                NRF_LOG_DEBUG("fstorageErase() E\n");
                fstorageErase(addr, 1);
            }    
            NRF_LOG_DEBUG("fstorageWriteRecord() E\n");
            record_t record;
            record.offsetStart = 0;
            record.offsetEnd   = 0;
            fstorageWriteRecord(addr, &record);
            NRF_LOG_DEBUG("RECORD_DATA_TYPE_START x\n");
        }    
        break;

        case RECORD_DATA_TYPE_END:
        {
            NRF_LOG_DEBUG("RECORD_DATA_TYPE_END E\n");
            record_t record;
            NRF_LOG_DEBUG("fstorageReadRecord() E\n");
            if (fstorageReadRecord(addr, &record) != 0) {
                return ERROR_FSTORAGE_READ_FAIL;
            }
            NRF_LOG_DEBUG("fstorageReadRecord() x\n");
            NRF_LOG_DEBUG("record.offsetStart=0x%x", record.offsetStart);
            NRF_LOG_DEBUG("record.offsetEnd=0x%x",   record.offsetEnd);

            if (_fstorageIsEraseNeeded()) {
                NRF_LOG_DEBUG("fstorageErase() E\n");
                fstorageErase(addr, 1);
            }
            record.offsetEnd = pRecord->offsetEnd;
            NRF_LOG_DEBUG("record.offsetEnd=0x%x",   record.offsetEnd);
            NRF_LOG_DEBUG("fstorageWriteRecord() E\n");
            fstorageWriteRecord(addr, &record);
            NRF_LOG_DEBUG("RECORD_DATA_TYPE_END X");
        }   
        break;    
    }    

    return 0;
}

int fstorageWriteRecord(const uint32_t addr, record_t* pRecord) {
    uint8_t data[RECORD_LEN] = {0};
    record2Data(pRecord, data);
    if (_fstorageWrite(addr, RECORD_LEN, data) != 0) {
        return ERROR_FSTORAGE_WRITE_FAIL;
    }

    return 0;
}

int _fstorageWrite(const uint32_t addr, const uint32_t len, void const* pData) {
if (!_gFstorageInitialized) {
return ERROR_FSTORAGE_UNINITIALIZED;
}

if (!_gFstorageEraseDone) {
return ERROR_FSTORAGE_ERASE_ON_GOING;
}

if (!_gFstorageWriteDone) {
return ERROR_FSTORAGE_WRITE_ON_GOING;
}

_gFstorageWriteDone = false;

const uint32_t wlen = _fstorageRoundUpU32(len);
const ret_code_t retCode = nrf_fstorage_write(&_gFstorage, addr, pData, wlen, NULL);
if (retCode != NRF_SUCCESS) {
NRF_LOG_WARNING("nrf_fstorage_write() failed 0x%x", retCode);
return ERROR_FSTORAGE_WRITE_FAIL;
}

_fstorageWait(FSTORAGE_WAIT_CNT);

return 0;
}

Parents
  • The following log messages show that fatal error occur in sd_app_evt_wait(). Where "pm e" means entering sd_app_evt_wait() function and  "pm x" means leaving sd_app_evt_wait() function

    # SEGGER J-Link RTT Viewer V6.32i Terminal Log File
    # Compiled: 15:22:50 on Jul 24 2018
    # Logging started @ 24 Jun 2022 09:07:20
     0> <debug> nrf_ble_gatt: Requesting to update ATT MTU to 185 bytes on connection 0x0.
     0> <info> app: Connected.
     0> <debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 251 bytes.
     0> <debug> nrf_ble_gatt: Updating data length to 27 on connection 0x0.
     0> <debug> nrf_ble_gatt: Data length updated to 27 on connection 0x0.
     0> <debug> nrf_ble_gatt: max_rx_octets: 27
     0> <debug> nrf_ble_gatt: max_tx_octets: 27
     0> <debug> nrf_ble_gatt: max_rx_time: 2120
     0> <debug> nrf_ble_gatt: max_tx_time: 2120
     0> <debug> nrf_ble_gatt: Peer on connection 0x0 requested an ATT MTU of 527 bytes.
     0> <debug> nrf_ble_gatt: Updating ATT MTU to 185 bytes (desired: 185) on connection 0x0.
     0> <debug> nrf_ble_gatt: ATT MTU updated to 185 bytes on connection 0x0 (response).
     0> <info> app: Received data from BLE NUS. Writing data on UART.
     0> <debug> app:  4D                     |M       
     0> <info> app: M
     0> <debug> app: length=1
     0> <debug> app: data[0]=0x4D
     0> <debug> app: data[1]=0x0
     0> <debug> app: data[2]=0x0
     0> <debug> app: data[3]=0x0
     0> <debug> app: data[4]=0x0
     0> <debug> app: data[5]=0x0
     0> <debug> app: data[6]=0x0
     0> <info> app: 
     0> 
     0> <info> app: Received data from BLE NUS. Writing data on UART.
     0> <debug> app:  45                     |E       
     0> <info> app: E
     0> <debug> app: length=1
     0> <debug> app: data[0]=0x4D
     0> <debug> app: data[1]=0x45
     0> <debug> app: data[2]=0x0
     0> <debug> app: data[3]=0x0
     0> <debug> app: data[4]=0x0
     0> <debug> app: data[5]=0x0
     0> <debug> app: data[6]=0x0
     0> <info> app: 
     0> 
     0> <info> app: Received data from BLE NUS. Writing data on UART.
     0> <debug> app:  41                     |A       
     0> <info> app: A
     0> <debug> app: length=1
     0> <debug> app: data[0]=0x4D
     0> <debug> app: data[1]=0x45
     0> <debug> app: data[2]=0x41
     0> <debug> app: data[3]=0x0
     0> <debug> app: data[4]=0x0
     0> <debug> app: data[5]=0x0
     0> <debug> app: data[6]=0x0
     0> <info> app: 
     0> 
     0> <info> app: Received data from BLE NUS. Writing data on UART.
     0> <debug> app:  53                     |S       
     0> <info> app: S
     0> <debug> app: length=1
     0> <debug> app: data[0]=0x4D
     0> <debug> app: data[1]=0x45
     0> <debug> app: data[2]=0x41
     0> <debug> app: data[3]=0x53
     0> <debug> app: data[4]=0x0
     0> <debug> app: data[5]=0x0
     0> <debug> app: data[6]=0x0
     0> <info> app: 
     0> 
     0> <info> app: Received data from BLE NUS. Writing data on UART.
     0> <debug> app:  55                     |U       
     0> <info> app: U
     0> <debug> app: length=1
     0> <debug> app: data[0]=0x4D
     0> <debug> app: data[1]=0x45
     0> <debug> app: data[2]=0x41
     0> <debug> app: data[3]=0x53
     0> <debug> app: data[4]=0x55
     0> <debug> app: data[5]=0x0
     0> <debug> app: data[6]=0x0
     0> <info> app: 
     0> 
     0> <info> app: Received data from BLE NUS. Writing data on UART.
     0> <debug> app:  52                     |R       
     0> <info> app: R
     0> <debug> app: length=1
     0> <debug> app: data[0]=0x4D
     0> <debug> app: data[1]=0x45
     0> <debug> app: data[2]=0x41
     0> <debug> app: data[3]=0x53
     0> <debug> app: data[4]=0x55
     0> <debug> app: data[5]=0x52
     0> <debug> app: data[6]=0x0
     0> <info> app: 
     0> 
     0> <info> app: Received data from BLE NUS. Writing data on UART.
     0> <debug> app:  45                     |E       
     0> <info> app: E
     0> <debug> app: length=1
     0> <debug> app: data[0]=0x4D
     0> <debug> app: data[1]=0x45
     0> <debug> app: data[2]=0x41
     0> <debug> app: data[3]=0x53
     0> <debug> app: data[4]=0x55
     0> <debug> app: data[5]=0x52
     0> <debug> app: data[6]=0x45
     0> <info> app: 
     0> 
     0> <debug> app: endAddr=0x80000
     0> <debug> app: startAddr=0x7D000
     0> <debug> app: type=0, add=0x7D000
     0> 
     0> <debug> app: state=0
     0> 
     0> <debug> app: START E
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm x
     0> 
     0> <debug> app: pm e
     0> 
     0> <error> app: Fatal error
    
    .

    0> <debug> app: pm e
     0>
     0> <debug> app: pm x
     0>
     0> <debug> app: pm x
     0>
     0> <debug> app: pm e
     0>
     0> <error> app: Fatal error

  • Thanks for your reply! The following is error messages after defining define "DEBUG" and "DEBUG_NRF". But I can't find useful information.

     0> <debug> app: pm e
     0>
     0> <debug> app: pm x
     0>
     0> <debug> app: pm e
     0>
     0> <error> app: End of error report

  • You decide that where you call APP_SCHED_INIT(). For the As you ask the question, I wonder - do you use the app scheduler intentionally or is it by accident? There are good reasons to use it, but if you enabled it in the app_timer by accident and do not actually process the queue, then it will not work and this is expected. If the latter is the case, then you should modify your sdk_config.h to not use the scheduler by setting APP_TIMER_CONFIG_USE_SCHEDULER to 0.

  • If I setting APP_TIMER_CONFIG_USE_SCHEDULER to 0, _norDataHandler() is not called for handling fstorage read/write/erase.

    errCode = app_timer_create(&gNorDataTimerID, APP_TIMER_MODE_REPEATED, _norDataHandler);

    if (errCode != NRF_SUCCESS) {
            NRF_LOG_WARNING("app_timer_create(gNorDataTimerID) failed\n");
            return ERROR_TIMER_CREATE_FAIL;
    }

  • Hi,

    I do not have enough context to understand much from this. What is _norDataHandler()? Do you use the app scheduler in your firmware? (my comment about setting APP_TIMER_CONFIG_USE_SCHEDULER to 0 was just that if you don't use it and just accidentally set it to 1, that could also explain what you are seeing). But if you use the scheduler, the error you got initially is because the scheduler queue is full, either because it is not processed fast enough or that it is too small (or a combination).

  • Is it possible to increase scheduler queue?

    int norFlashWriteDataOC(void) {
        uint16_t len;
        static uint8_t buf[NOR_WRITE_BUF_SIZE];
        int error;

        len = _norBufferRead(NOR_WRITE_BUF_SIZE, buf);

        if (len > 0) {
            error = extFlashWriteDataOC(len, buf);
        }

        return error;
    }

    static void _norDataHandler(void* pContext) {
        const ble_nus_state_t bleNusState = BLE_UART_GetState();
        switch (bleNusState) {
            case BLE_NUS_STATE_READ:
            {   
            
            }    
            break;

            case BLE_NUS_STATE_MEASURE:
            {
                norFlashWriteDataOC();
            }    
            break;
        }    
    }

  • First: Can you clarify if you are using the scheduler? That would be very good to know in case we are far out Slight smile

    snowuyl said:
    Is it possible to increase scheduler queue?

    Yes, if you use the scheduler you have APP_SCHED_INIT() in your code somewhere. The first parameter there is the maximum scheduler element size, and the second parameter is the queue size (number of elements). The first needs to be large enough for any element that could be put in the queue (including by app_timer), and the second decides how many elements are held in the queue. Increase the latter to increase the queue size.

Reply
  • First: Can you clarify if you are using the scheduler? That would be very good to know in case we are far out Slight smile

    snowuyl said:
    Is it possible to increase scheduler queue?

    Yes, if you use the scheduler you have APP_SCHED_INIT() in your code somewhere. The first parameter there is the maximum scheduler element size, and the second parameter is the queue size (number of elements). The first needs to be large enough for any element that could be put in the queue (including by app_timer), and the second decides how many elements are held in the queue. Increase the latter to increase the queue size.

Children
Related