Issue with Data Deletion and Garbage Collection in FDS

[lara_]

SDK: nRF5_SDK_17.1.0

I am currently encountering some difficulties regarding data deletion and garbage collection after recording in my Nordic application. I have followed the instructions provided by NRF closely, yet I seem to face persistent issues.

I have the impression that the code indicates that the deletion and garbage collection have been successfully completed, but when I examine the actual dirty records, they are not deleted. It seems that the garbage collection only works successfully during device initialization

Here's a snippet of the code I'm using:

void app_fds_delete_file(uint16_t my_file_id)
{
    ret_code_t rc;

    NRF_LOG_INFO("Deleting files...");
    rc = fds_file_delete(my_file_id);
    APP_ERROR_CHECK(rc);

    wait_for_del_file();

    app_fds_garbage_collection();
}

In the fds_evt_handler, m_fds_del_file is set to true in response to FDS_EVT_DEL_FILE.

static void app_fds_garbage_collection(void)
{
    ret_code_t rc;

    NRF_LOG_INFO("Trying to run garbage collection...");
    rc = fds_gc();
    APP_ERROR_CHECK(rc);

    wait_for_gc();
}

static void wait_for_del_file(void)
{
    while(!m_fds_del_file)
    {
        power_manage();
    }

    m_fds_del_file = false;
}

Here's an excerpt from the log showing the behavior during startup:

<info> app_timer: RTC: initialized.
<info> app: Initializing fds...
<info> app: Event: FDS_EVT_INIT received (NRF_SUCCESS)
<info> app: Reading flash usage statistics...
<info> app: Found 14 valid records.
<info> app: Found 10 dirty records (ready to be garbage collected).
<info> app: Found 16 pages_available.
<info> app: Found 0 open_records.
<info> app: Found 0 words_reserved.
<info> app: Found 1844 words_used.
<info> app: Found 2046 largest_contig.
<info> app: Event: FDS_EVT_GC received (NRF_SUCCESS)
<info> app: GC completed successfully.
<info> app: Sync file found.
<info> app: Sync storage round: 11
<info> app: Thu Jan 01 00:00:00 1970

At this point, querying the dirty records correctly returns 0, but if I save some data and try delete them the dirty records will never go back to 0.

I'm puzzled as to why this is happening. Could someone provide insights or suggestions on how to resolve this issue effectively?

Your assistance and expertise are greatly appreciated.

[Edvin]

Hello,

Can you please share the entire application so that I can try to replicate what you are seeing?

I didn't understand exactly what you were trying to say with the attached log. It doesn't say that there are any dirty records after the GC? How do you determine that there are still dirty records after the GC?

And what does your fds event handler look like?

Best regards,

Edvin

[lara_]

Hello Edvin ,

Thank you for your prompt response,

I'm afraid I can't provide the entire application, but I've implemented an API command to query the fds data.

Here's what I'm observing: Upon firmware initiation, if there are dirty records, querying the number of dirty records after garbage collection shows 0, indicating successful GC.

However, if I record data, delete it, and then perform GC, the number of dirty records doesn't reset to 0. Instead, it persists, necessitating FW restart to clear them.

Moreover, as I record and delete data without FW restarts, the available space for recording diminishes gradually. For instance, after FW restart, I can record 200 values. But after subsequent data deletion without restarts, the recording capacity decreases (e.g., to 180 values). I suspect this degradation results from ineffective deletion and garbage collection of dirty records, leading to flash space not being reclaimed properly.

Regarding the fds event handler, here's a snippet:

static void nus_data_handler(ble_nus_evt_t * p_evt)
{
    if(p_evt->type == BLE_NUS_EVT_RX_DATA)
    {
        uint32_t err_code;

        NRF_LOG_HEXDUMP_DEBUG(p_evt->params.rx_data.p_data, p_evt->params.rx_data.length);
        NRF_LOG_DEBUG("Received data from BLE NUS.");

        /* perform action according to command */
        
        else if((memcmp(p_evt->params.rx_data.p_data, "del!", 4) == 0))
        {
            if(can_query == true)
            {
                NRF_LOG_INFO("Delete Mode");

                /* delete all data files */
                delete_file = true;
                return;
            }
        }

This function is called from the main(), where there's a conditional check for delete_file being true. If it evaluates to true, the function app_fds_delete_file() is executed.

Hope this clarifies the situation. Let me know if further details are needed.

Best regards,
Lara

[Edvin]

Hello Lara,

I suspect that you attatched the wrong snippet. 

lara_ said:

However, if I record data, delete it, and then perform GC, the number of dirty records doesn't reset to 0. Instead, it persists

Are you saying that it doesn't decrease at all, or does it decrease, but never reach 0?

Can you please show the snippets where you delete the records and where you run GC, in addition to your fds evt_handler?

BR,

Edvin

[lara_]

Hello Edvin,

In the last snippet within the fds event handler, when I issue the API command "del!", it's supposed to delete the data. To achieve this, the delete_file flag is set to true within the fds handler. Then, in the main section, there's a conditional check for delete_file being true. If it evaluates to true, the function app_fds_delete_file() is executed. This function, in turn, calls the provided functions: fds_file_delete(), wait_for_del_file, and app_fds_garbage_collection(), all of which I've linked in my initial post.

What I mean is that the number of dirty records doesn't decrease at all when I run the garbage collection.

The 3 next snippets are: 1) some fds data before the deleting and garbage collection 2) Deleting and garbage collection 3) fds data after  deleting and garbage collection

<debug> app:  66 64 73 64 61 74 61 3F|fdsdata?
<debug> app: Received data from BLE NUS.
<info> app: valid_records: 74
<info> app: dirty_records: 10
<info> app: pages_available: 16
<info> app: open_records: 4
<info> app: words_reserved: 0
<info> app: words_used: 11813
<info> app: largest_contig: 2046
<info> app: freeable_words: 40
<info> app: corruption: false
<info> app: ble_send_data: 32
<info> app: Thu Jan 01 00:34:27 1970

<debug> app:  64 65 6C 21            |del!    
<debug> app: Received data from BLE NUS.
<info> app: Delete Mode
<info> app: Deleting files...
<info> app: Event: FDS_EVT_DEL_FILE received (NRF_SUCCESS)
<info> app: File ID:	0x0001
<info> app: Record KEY:	0x0000
<info> app: Record ID:	0x0000
<info> app: Trying to run garbage collection...
<info> app: Thu Jan 01 00:35:14 1970

<info> app: Thu Jan 01 00:35:15 1970

<info> app: Event: FDS_EVT_GC received (NRF_SUCCESS)
<info> app: GC completed successfully.
<info> app: Updating sync data.
<info> app: Sync storage round: 1
<info> app: Updating sync file...
<info> app: Event: FDS_EVT_UPDATE received (NRF_SUCCESS)
<info> app: File ID:	0x0000
<info> app: Record KEY:	0x0001
<info> app: Record ID:	0x2C04
<info> app: ble_send_text: Data deleted.
<info> app: Sent
<info> app: Thu Jan 01 00:35:16 1970

<debug> app:  66 64 73 64 61 74 61 3F|fdsdata?
<debug> app: Received data from BLE NUS.
<info> app: valid_records: 4
<info> app: dirty_records: 26
<info> app: pages_available: 16
<info> app: open_records: 4
<info> app: words_reserved: 0
<info> app: words_used: 2097
<info> app: largest_contig: 2046
<info> app: freeable_words: 2044
<info> app: corruption: false
<info> app: ble_send_data: 32
<info> app: Sent
<info> app: Thu Jan 01 00:36:25 1970

BR,

Lara

[Edvin]

Hello Lara,

It is a bit difficult to follow whats going on when I only have explanations on how things are implemented. I understand that you can't share your entire project, but is it possible to strip out everything but the fds parts, so that I can have a look? I still have not seen your fds_evt_handler(). I think I understand how you intend for it to work, but since something is not working as intended, it could be a bug in the implementation. 

lara_ said:

What I mean is that the number of dirty records doesn't decrease at all when I run the garbage collection.

I see that the number of dirty records went from 10 to 26, and this is after a GC. But it looks like you update at least one record after the garbage collection as well? This will result in at least one dirty record. Also, you go from 74 to 4 valid records, but the log only says that one record was deleted? I suspect there is a lot more going on than what the logs are saying.

If you can't share anything more, perhaps you can try to create a minimalistic application only reproducing the issue that you are seeing? 

Best regards,

Edvin