Deadlock with LittleFs

[mc-takashi-sato]

Hi
I am using Rp2040 with platformio.
I'm trying to write a file internally using LittleFs in a FreeRTOS environment, but a recent git pull has caused a deadlock at idleOtherCore().

 void idleOtherCore() {
     if (!_multicore) {
         return;
     }
     __holdUpPendSV = 1;
// diff : add from here----
     if (__isFreeRTOS) {
         vTaskPreemptionDisable(nullptr);
         vTaskSuspendAll();
     }
// diff : ---- add to here
     mutex_enter_blocking(&_idleMutex);
     __otherCoreIdled = false;
     multicore_fifo_push_blocking(_GOTOSLEEP);
     while (!__otherCoreIdled) { /* noop */ }
 }

It used to work fine in previous versions, but now it seems that both cores hang.
Old version that worked:
SHA-1: a58154b
(05/26/2022 07:13:25)

Originally, I think the purpose of this change was to suppress access from other threads while writing to Flash, but the call to vTaskSuspendAll(); seemed to be gone.

backtrase below

• Core0

#0  0x10020f44 in _MFIFO::idleOtherCore (this=<optimized out>) at C:\Users\{user}\.platformio\packages\framework-arduinopico\cores\rp2040/RP2040Support.h:102
#1  RP2040::idleOtherCore (this=<optimized out>) at C:\Users\{user}\.platformio\packages\framework-arduinopico\cores\rp2040/RP2040Support.h:299
#2  littlefs_impl::LittleFSImpl::lfs_flash_prog (c=<optimized out>, block=<optimized out>, off=<optimized out>, buffer=0x20008e28, size=256) at C:\Users\{user}\.platformio\packages\framework-arduinopico\libraries\LittleFS\src\LittleFS.cpp:186
#3  0x10024084 in lfs_bd_flush (lfs=lfs@entry=0x20007030, pcache=pcache@entry=0x20007040, rcache=rcache@entry=0x20007030, validate=<optimized out>) at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\littlefs\lib\littlefs/lfs.c:160
#4  0x100243e2 in lfs_bd_sync (lfs=lfs@entry=0x20007030, pcache=pcache@entry=0x20007040, rcache=rcache@entry=0x20007030, validate=validate@entry=false) at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\littlefs\lib\littlefs/lfs.c:194
#5  0x1002453c in lfs_dir_commitcrc (lfs=lfs@entry=0x20007030, commit=commit@entry=0x200087f0) at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\littlefs\lib\littlefs/lfs.c:1550
#6  0x10026580 in lfs_dir_relocatingcommit (lfs=lfs@entry=0x20007030, dir=dir@entry=0x20008874, pair=pair@entry=0x20008904, attrs=attrs@entry=0x200088fc, attrcount=attrcount@entry=1, pdir=pdir@entry=0x20008894) at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\littlefs\lib\littlefs/lfs.c:2093
#7  0x100267ce in lfs_dir_orphaningcommit (lfs=lfs@entry=0x20007030, dir=dir@entry=0x20008904, attrs=attrs@entry=0x200088fc, attrcount=attrcount@entry=1) at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\littlefs\lib\littlefs/lfs.c:2197
#8  0x10026d44 in lfs_dir_commit (lfs=lfs@entry=0x20007030, dir=dir@entry=0x20008904, attrs=attrs@entry=0x200088fc, attrcount=attrcount@entry=1) at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\littlefs\lib\littlefs/lfs.c:2369
#9  0x10027204 in lfs_commitattr (lfs=0x20007030, path=<optimized out>, type=<optimized out>, buffer=buffer@entry=0x20008988, size=size@entry=8) at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\littlefs\lib\littlefs/lfs.c:3880
#10 0x10027252 in lfs_rawsetattr (lfs=<optimized out>, path=<optimized out>, type=<optimized out>, buffer=buffer@entry=0x20008988, size=size@entry=8) at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\littlefs\lib\littlefs/lfs.c:3892
#11 0x10027ae4 in lfs_setattr (lfs=<optimized out>, path=<optimized out>, type=type@entry=116 't', buffer=buffer@entry=0x20008988, size=size@entry=8) at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\littlefs\lib\littlefs/lfs.c:5446
#12 0x10020b74 in littlefs_impl::LittleFSFileImpl::close (this=0x20011028) at c:\users\{user}\.platformio\packages\toolchain-rp2040-earlephilhower\arm-none-eabi\include\c++\10.3.0\bits/shared_ptr_base.h:1324
#13 0x1002d15a in fs::File::close (this=this@entry=0x200089dc) at C:\Users\{user}\.platformio\packages\framework-arduinopico\cores\rp2040\FS.cpp:127
#14 0x1000b960 in CommonClass::fs_fileAdd (this=<optimized out>, fName=..., Data=...) at src\common\common.cpp:139

• Core1

#0  0x10029c0c in vPortRecursiveLock (uxAcquire=1, pxSpinLock=0xd000013c, ulLockNum=1) at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\freertos\lib\freertos-kernel\portable\thirdparty\gcc\rp2040\include/portmacro.h:192
#1  vTaskSuspendAll () at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\freertos\lib\freertos-kernel/tasks.c:2944
#2  0x1002aeae in vTaskDelay (xTicksToDelay=xTicksToDelay@entry=10) at c:\users\{user}\.platformio\packages\framework-arduinopico\libraries\freertos\lib\freertos-kernel/tasks.c:1937
#3  0x1001c614 in ledClass::TaskMainLoop (this=this@entry=0x20003684 <AMR+892>) at src\mid\task1\task1.cpp:262

• Is it because both Core0 and Core1 call vTaskSuspendAll();?
  Multiple tasks are running on the Core1 side, but vTaskSuspendAll(); is reached when vTaskDelay(); is called.

• I think that the configuration expects recovery by interrupt processing, but when lfs_flash_prog() and lfs_flash_erase() are called on the Core0 side, noInterrupts(); is executed internally and then rp2040.idleOtherCore(); interrupt processing is also suppressed because of Is there anything wrong with my usage?

int LittleFSImpl::lfs_flash_prog(const struct lfs_config *c,
                                 lfs_block_t block, lfs_off_t off, const void *buffer, lfs_size_t size) {
    LittleFSImpl *me = reinterpret_cast<LittleFSImpl*>(c->context);
    uint8_t *addr = me->_start + (block * me->_blockSize) + off;
    noInterrupts();
    rp2040.idleOtherCore();
    //    Serial.printf("WRITE: %p, $d\n", (intptr_t)addr - (intptr_t)XIP_BASE, size);
    flash_range_program((intptr_t)addr - (intptr_t)XIP_BASE, (const uint8_t *)buffer, size);
    rp2040.resumeOtherCore();
    interrupts();
    return 0;
}

int LittleFSImpl::lfs_flash_erase(const struct lfs_config *c, lfs_block_t block) {
    LittleFSImpl *me = reinterpret_cast<LittleFSImpl*>(c->context);
    uint8_t *addr = me->_start + (block * me->_blockSize);
    //    Serial.printf("ERASE: %p, %d\n", (intptr_t)addr - (intptr_t)XIP_BASE, me->_blockSize);
    noInterrupts();
    rp2040.idleOtherCore();
    flash_range_erase((intptr_t)addr - (intptr_t)XIP_BASE, me->_blockSize);
    rp2040.resumeOtherCore();
    interrupts();
    return 0;
}

By the way, for idleOtherCore()

      if (__isFreeRTOS) {
          vTaskPreemptionDisable(nullptr);
          vTaskSuspendAll();
      }

It has been confirmed that the phenomenon does not occur if the is commented out.

[mc-takashi-sato]

#1352 (comment)

As written here, noInterrupts() is applied only to the calling core, so I think an interrupt should occur on the Core1 side...

[earlephilhower]

The ARM littlefs filesystem, and the Arduino wrapper library LittleFS, are NOT multicore or multhread safe. If you have 2 threads doing file IO, then you need to use a FreeRTOS mutex to ensure only one works at a time or else really bad things will happen. Only 1 task should use them.

The task-suspend-disable code you hilighted (which is actually pretty old) is absolutely necessary because without it the freezing task could be swapped out with the other core frozen causing the FreeRTOS task processing to break. If you check the git blame on those lines you'll find the PR and issue it references.

If you're not doing multiple thread access to LittleFS, could you make an MCVE (small, 1-screen long program) that causes the failure? That would let us take a look at it and see if there's some other race condition we haven't caught.

[mc-takashi-sato]

@earlephilhower
thank you for your reply.

Access to LittleFS is made single-threaded and mutex is used, but the problem does not seem to be improved.

I have created a sample minimum program, so would it be possible for you to take a look at it?

I will send the sample code by e-mail.

[mc-takashi-sato]

If you're not doing multiple thread access to LittleFS, could you make an MCVE (small, 1-screen long program) that causes the failure?

Sorry, the project is still there.
Sorry for the long source.
I'll see if I can reproduce it with a shorter source.
I would appreciate it if you could give me some advice if you have noticed anything.

[mc-takashi-sato]

@earlephilhower

I've created a small sample code where the deadlock reproduces.

• Starting one task to store logs inside LittleFS
• Publish the queue from the loop and pass it to the log task
• Log task outputs to Serial and saves the same content to a file

When I run it, it deadlocks after saving a few times.
If don't use tasks and queues and save the log inside the loop, no deadlock will occur.

#include <Arduino.h>
#include <FreeRTOS.h>
#include <task.h>
#include <LittleFS.h>
#include <queue.h>
#include "hardware/watchdog.h"

int cnt;

#define DEF_LOGGERTASK_QUE_MAX 20
#define DEF_LOGGERTASK_MSG_LEN 64
#define DEF_LOGGERTASK_STKSIZE 2048

typedef struct tagLoggerMsg
{
    unsigned long       m_dwMessage;                        
    int                 m_nLength;                          
    char                m_chBuff[DEF_LOGGERTASK_MSG_LEN];   
} LoggerMsg;

#define DEF_LOGGERTASK_BUFFSIZE sizeof(LoggerMsg)
#define INTERNAL_LOG_SIZE_MAX   (1024 * 5) 
#define INTERNAL_LOG_FILE_MAX   10 

enum LoggerEventId{
  LoggerEvent_UNKNOWN = -1,
  LoggerEvent_WRITE = 0,           
  LoggerEvent_MAX                  
} ;

class LoggerTaskClass
{
public:
  TaskHandle_t _chkTaskHandleLoggerTask ;
  QueueHandle_t _xLoggerTaskQueue;
  void begin();
private:
  // static void createTask(void *pvParameters) ;
  static void LoggerTaskMainLoop(void *pvParameters) ;
};

LoggerTaskClass LOGGER ;


/******************************************************************************/
// logger main loop
/******************************************************************************/
void LoggerTaskClass::LoggerTaskMainLoop(void *pvParameters)
{
  int filesize = 0;
  LoggerMsg RcvMsg = {0};
  char *buffer;
  File _lfs;
  int ret = 0;

  LittleFS.begin();
  while(1)
  {
    if (xQueueReceive(LOGGER._xLoggerTaskQueue, &RcvMsg, portMAX_DELAY ) == pdTRUE)
    {
      
      switch(RcvMsg.m_dwMessage)
      {
        case LoggerEvent_WRITE:           
          buffer = RcvMsg.m_chBuff;
          Serial.printf(buffer);

          _lfs = LittleFS.open("/logfile.log", "a");
          if(_lfs){
            ret = _lfs.write(RcvMsg.m_chBuff,RcvMsg.m_nLength);
          }
          _lfs.close();
          break;
        default:
          break;
      }
    }
    
  }
}

/******************************************************************************/
// logger begin api
/******************************************************************************/
void LoggerTaskClass::begin(void)
{
  LOGGER._xLoggerTaskQueue = xQueueCreate(DEF_LOGGERTASK_QUE_MAX, DEF_LOGGERTASK_BUFFSIZE);

  _chkTaskHandleLoggerTask = NULL;
  xTaskCreate(LoggerTaskMainLoop, "LoggerTask", DEF_LOGGERTASK_STKSIZE, this, 3, &_chkTaskHandleLoggerTask);
  if (!_chkTaskHandleLoggerTask)
  {
    ;
  }
}

/******************************************************************************/
// log que send
/******************************************************************************/
void SaveLogFile(const char *buffer,int len)
{
  LoggerMsg SndMsg ={0};
  if(NULL == LOGGER._xLoggerTaskQueue){
    return;
  }
  
  SndMsg.m_dwMessage = LoggerEvent_WRITE;
  
  SndMsg.m_nLength = len;
  memcpy(SndMsg.m_chBuff, buffer, len);

  if(xQueueSend(LOGGER._xLoggerTaskQueue, &SndMsg, 0) == pdFALSE)
  {
    ;
  }
}

/******************************************************************************/
// main setup
/******************************************************************************/
void setup() {
  Serial.begin(115200, true);
  delay(500);

#if !defined(DEBUG)
  watchdog_enable(3000, 1);  
#endif

  cnt = 0;

  LOGGER.begin();
}

/******************************************************************************/
// main loop
/******************************************************************************/
void loop() {
  char buffer[64] = {0};
  File _lfs;
  delay(1000);
  
  cnt++;

  sprintf(buffer,"(%ld)loopCount[%d]\r\n",millis(),cnt);
  SaveLogFile(buffer,strlen(buffer));

#if !defined(DEBUG)
  watchdog_update();
#endif
}

[earlephilhower]

Got it. It'll be a few days before I can actually look at this, but I do thank you for making a concise example!

[mc-takashi-sato]

I tried using the latest release(Release 3.2.0) , but things seem to have gotten worse...
I'm sorry, but I will move the discussion to the issue.