lbernstone
commented
1 year ago Put a delay in the internal while loop. Otherwise, you are blocking there. If this is really time sensitive, build a buffer of 4096, and write in chunks.
Open danieldecesaro opened 1 year ago
lbernstone
commented
1 year ago Put a delay in the internal while loop. Otherwise, you are blocking there. If this is really time sensitive, build a buffer of 4096, and write in chunks.
danieldecesaro
commented
1 year ago Hello @lbernstone,
Well, what happens is the following, I configured an interrupt that monitors a pulse sensor driven by a hydraulic pump, in parallel to this I have a thred that writes, every 250ms, the system log information to a file on flash. The problem happens when the log job is opening or creating a new log file and interruptions generated by the sensor occur, as these interruptions are not happening. I believe that something when creating or even updating files is momentarily "blocking" the interruptions. I performed a test using both I/O and timer interrupts and in both cases interrupts are lost. This is a bit worrying, as I believe that hardware interrupts such as I/O should not be "turned off" by a flash file writing routine.
Thank you for your help!
danieldecesaro
commented
1 year ago I built a code to simulate the problem. See below:
`
#include "FS.h"
#include "LITTLEFS.h"
#include <vector>
#define ES1a_PIN 34
#define ES1b_PIN 35
#define ES2a_PIN 32
#define ES2b_PIN 33
//#define FILE_SYSTEM SPIFFS
//#define FILE_SYSTEM LITTLEFS
#define FILE_SYSTEM LittleFS
#define FORMAT_SPIFFS_IF_FAILED true
#define SAMPLES_NUM 6
typedef struct {
fs::FS *loggerFS;
String directory = "/log";
String filename = "";
size_t maxSize = (30720 * 3);
size_t individualFileSize = 9216;
uint8_t maxFiles = 10;
} logger_t;
logger_t logger;
std::vector<String> temporaryLogList;
SemaphoreHandle_t vectorMutex = NULL;
SemaphoreHandle_t logLock = NULL;
hw_timer_t *timer2 = NULL;
portMUX_TYPE mux = portMUX_INITIALIZER_UNLOCKED;
portMUX_TYPE timer2Mux = portMUX_INITIALIZER_UNLOCKED;
volatile uint32_t count = 0;
volatile uint32_t pulse_duration = 0;
void setupIO() {
pinMode(ES1a_PIN, INPUT);
pinMode(ES1b_PIN, INPUT);
pinMode(ES2a_PIN, INPUT);
pinMode(ES2b_PIN, INPUT);
}
void startFileSystem() {
if (!FILE_SYSTEM.begin(FORMAT_SPIFFS_IF_FAILED)) {
Serial.println("SPIFFS Mount Failed");
delay(15000);
ESP.restart();
}
FILE_SYSTEM.format();
// fsPresent = true;
log_i("FLASH: %ukB - FIRMWARE: %u/%ukB - %.2f%% livre", (ESP.getFlashChipSize() / 1024),
(ESP.getSketchSize() / 1024), (ESP.getFreeSketchSpace() / 1024),
(100.00 - (float_t)((float_t) ESP.getSketchSize() / (float_t) ESP.getFreeSketchSpace()) * 100));
log_i("SPIFFS: %u/%ukB - %.2f%% livre", (FILE_SYSTEM.usedBytes() / 1024),
(FILE_SYSTEM.totalBytes() / 1024),
(100.00 - (float_t)((float_t)((float_t) FILE_SYSTEM.usedBytes() / (float_t) FILE_SYSTEM.totalBytes())) * 100));
}
void makeNewLogFile(logger_t *logger) {
String fileSufix;
uint8_t sufixPisition = logger->directory.length() + 5;
fileSufix = logger->filename.substring(sufixPisition);
fileSufix = String(fileSufix.toInt() + 1);
logger->filename.remove(sufixPisition);
logger->filename += fileSufix;
log_d("Novo arquivo de log: %s ", logger->filename.c_str());
}
void logFlush(void *pvParameters) {
File file;
size_t fileSize = 0;
while (1) {
file = logger.loggerFS->open(logger.filename, FILE_APPEND);
if (file) {
xSemaphoreTake(vectorMutex, portMAX_DELAY);
while (temporaryLogList.size() > 0) {
// ets_printf("%s", temporaryLogList.back().c_str());
// file.print(temporaryLogList.back().c_str());
temporaryLogList.pop_back();
}
xSemaphoreGive(vectorMutex);
}
// file.flush();
// fileSize = file.size();
file.close();
//
// if (fileSize > logger.individualFileSize) {
// makeNewLogFile(&logger);
// }
vTaskDelay(pdMS_TO_TICKS(250));
}
}
void bufferInsert(String str) {
xSemaphoreTake(logLock, portMAX_DELAY);
temporaryLogList.insert(temporaryLogList.begin(), str);
xSemaphoreGive(logLock);
}
void IRAM_ATTR ISR_Sensor2() {
static volatile unsigned long int widthOld = micros();
volatile unsigned long int width = micros();
portENTER_CRITICAL_ISR(&mux);
if (widthOld > width) {
pulse_duration = 0xFFFFFFFF - (width - widthOld);
}
else {
pulse_duration = width - widthOld;
}
widthOld = width;
count++;
portEXIT_CRITICAL_ISR(&mux);
}
void IRAM_ATTR onTimer2() {
portENTER_CRITICAL_ISR(&timer2Mux);
static volatile uint8_t internalSample = 0;
static volatile boolean oldState = false;
boolean state = digitalRead(ES2a_PIN);
if (state != oldState) {
internalSample = 0;
oldState = state;
}
if (internalSample < SAMPLES_NUM) {
if (++internalSample == SAMPLES_NUM) {
count++;
}
}
portEXIT_CRITICAL_ISR(&timer2Mux);
}
void loggerDeleteFiles(logger_t *logger) {
File logDir = logger->loggerFS->open(logger->directory, "r");
while (logDir) {
String fileName = "/";
fileName += logDir.name();
fileName += "/";
const char *file = logDir.openNextFile().name();
if (!file) {
break;
}
fileName += file;
if (!logger->loggerFS->remove(fileName)) {
log_e("Falha ao remover arquivo do log: %s", fileName.c_str());
} else {
log_d("Arquivo de log removido: %s", fileName.c_str());
}
}
logDir.close();
}
void loggerBegin(fs::LittleFSFS &fs, boolean deleteLogOnInit) {
logger.loggerFS = &fs;
logger.directory = "/log";
logger.maxFiles = 10;
vectorMutex = xSemaphoreCreateMutex();
logLock = xSemaphoreCreateMutex();
if (!logger.loggerFS->exists(logger.directory)) {
if (!logger.loggerFS->mkdir(logger.directory)) {
log_e("Falhou ao criar diretorio de log: %s", logger.directory);
} else {
log_d("Diretorio de log criado: %s", logger.directory);
}
}
if (deleteLogOnInit) {
loggerDeleteFiles(&logger);
log_d("Aquivos de log excluidos!");
}
logger.filename = "/log_1";
xTaskCreatePinnedToCore(logFlush, "LOGGER", 4000, NULL, 0, NULL, PRO_CPU_NUM);
log_v("Logger inicializado.");
}
void startCpu() {
attachInterrupt(ES2a_PIN, ISR_Sensor2, CHANGE);
//
// timer2 = timerBegin(1, 80, true);
// timerAttachInterrupt(timer2, &onTimer2, true);
// timerAlarmWrite(timer2, 125, true);
// timerAlarmEnable (timer2);
}
void setup() {
esp_log_level_set("*", ESP_LOG_VERBOSE);
setupIO();
Serial.begin(115200);
Serial.setDebugOutput(true);
Serial.print("\n");
startFileSystem();
loggerBegin(FILE_SYSTEM, true);
log_i("POWER ON...");
log_i("Reset Mode: %X", esp_reset_reason());
startCpu();
count = 0;
}
void loop() {
bufferInsert("Insert");
Serial.print("count: ");
Serial.print(count);
Serial.print(" - whith: ");
Serial.println(pulse_duration);
delay(100);
}`
The ISR_Sensor2 interrupt should occur every 5ms but in certain situations it takes more than 50ms to occur. This occurs when thred logFlush is active, but specifically when the lines that open and close the file are uncommented. If you comment on these lines, interruptions occur normally. Serial Debug: count: 8182 - whith: 4971 count: 8202 - whith: 4972 count: 8222 - whith: 4971 count: 8241 - whith: 43143 ---------- Here the interruption did not occur count: 8261 - whith: 4970 count: 8281 - whith: 4971 count: 8301 - whith: 4971
Am I doing something wrong, or is the file system blocking interrupts?
Grateful for the attention! Daniel!
lbernstone
commented
1 year ago Does it work if you remove the CRITICAL mutex in onTimer2? https://docs.espressif.com/projects/esp-idf/en/v4.4.6/esp32/api-guides/freertos-smp.html?highlight=enter_critical_isr#implementation
danieldecesaro
commented
1 year ago Does it work if you remove the CRITICAL mutex in onTimer2?
Hi @lbernstone, Thank you for your help!
In this test the timer is off, it is not causing interruptions!
danieldecesaro
commented
1 year ago When the lines:
file = logger.loggerFS->open(logger.filename, FILE_APPEND); It is file.close();
They are commented, interruptions occur normally, but 1M of them, without any error!
lbernstone
commented
1 year ago @danieldecesaro I would recommend you remove Arduino completely from this equation and try. The vfs/posix functions for open/close/write are so close to arduino it should not be difficult. Then, if the problem persists, you can ask the team that can actually do something about the issue.
danieldecesaro
commented
1 year ago @lbernstone, I did what you suggested, I replaced the code that opens and closes the file, but the error persists, here is the code I used: ` while (1) {
FILE *file = fopen("/littlefs/hello.txt", "w+");
//file = logger.loggerFS->open(logger.filename, FILE_APPEND);
if (file != NULL) {
xSemaphoreTake(vectorMutex, portMAX_DELAY);
while (temporaryLogList.size() > 0) {
// ets_printf("%s", temporaryLogList.back().c_str());
// file.print(temporaryLogList.back().c_str());
temporaryLogList.pop_back();
}
xSemaphoreGive(vectorMutex);
}
// file.flush();
// fileSize = file.size();
fclose(file);
// file.close();
//
// if (fileSize > logger.individualFileSize) {
// makeNewLogFile(&logger);
// }
vTaskDelay(pdMS_TO_TICKS(250));
}`
mrengineer7777
commented
1 year ago I suspect your interrupts are not being discarded. Instead, I suspect that writing to flash (triggered by fclose) pauses code execution on the processor. This is because with most embedded processors instructions run out of flash, so the processor can't execute another instruction while flash is being written. I read somewhere that ESP32 processors with PSRAM (where the code executes out of RAM instead of flash) can continue to run during a flash write, but will stall if any flash memory is accessed during that time. Hope that helps.
danieldecesaro
commented
12 months ago You must be right @mrengineer7777 ,
But shouldn't this part of the code be in IRAM? `
void IRAM_ATTR ISR_Sensor2() {
static volatile unsigned long int widthOld = micros();
volatile unsigned long int width = micros();
portENTER_CRITICAL_ISR(&mux);
if (widthOld > width) {
pulse_duration = 0xFFFFFFFF - (width - widthOld);
}
else {
pulse_duration = width - widthOld;
}
widthOld = width;
count++;
portEXIT_CRITICAL_ISR(&mux);
}`
Even though almost all of the code has been commented out, leaving only the counter active, counting failures still occur.
Could you help me more?
Att.
mrengineer7777
commented
12 months ago IRAM_ATTR ISR_Sensor2() should be in IRAM, but function calls from it may not be. I don't know if micros() is in IRAM.
me-no-dev
commented
12 months ago We are generally not running interrupts from IRAM anymore (since 2.0.0), in order to prevent easy shoot-in-the-foot situations.
danieldecesaro
commented
12 months ago Hey guys Thank you very much for your efforts in helping me. Well, to summarize the problem, I simplified the routines a little:
1 - The interrupt routine that is called when the state changes on a pin;
`
void ISR_Sensor2() {
count++;
}`
2 - This routine is configured like this:
`
attachInterrupt(ES2a_PIN, ISR_Sensor2, CHANGE);`
3 - Every 250ms a thred calls a routine that writes a log to a file in LittleFS:
`
void logFlush(void *pvParameters) {
while (1) {
FILE *file = fopen("/littlefs/hello.txt", "w+");
fprintf(file, "LOG TEST");
fclose(file);
vTaskDelay(pdMS_TO_TICKS(250));
}
}`
The problem occurs when this log routine comes into action and blocks the firing of interrupts, which occur every 5ms or so.
I have already tried to adjust the interrupt routine in several ways, configuring it to be positioned in IRAM or FLASH, but in neither case is the problem resolved.
I understand that when the ESP32 is blocking the SPI0 bus, the instructions are not being read and consequently executed, but if the routine is located in IRAM, shouldn't it be executed?
Thank you if you can help me!!!
ATT.
Board
esp32-wroom-32
Device Description
Custon hardware Develop
Hardware Configuration
GPIO 32 used as interrupt input
Version
v2.0.12
IDE Name
Sloeber
Operating System
Win11
Flash frequency
80MHz
PSRAM enabled
yes
Upload speed
115200
Description
Interrupts fail to create files with littlefs (esp32-wroom-32)
When updating to version 2.0.12 I started to notice strange behavior with I/O and timer interruptions. When I'm creating, or even updating, a file with LittleFS, some interrupts are lost, either in the timer (timerAlarmEnable(timer2)) or even in the I/O pins (attachInterrupt(ES2a_PIN, ISR_Sensor2, CHANGE)).
In both cases some interrupts fail and do not execute. I noticed that this occurs when a file is created or even updated, even allocating another CPU to the process.
Has anyone seen something similar? Do you know how to solve it?
Interrupt configuration code: ` attachInterrupt(ES2a_PIN, ISR_Sensor2, CHANGE);
`
File update code: ` void logFlush(void *pvParameters) { File file; size_t fileSize = 0;
`
Sketch
Debug Message
Other Steps to Reproduce
.
I have checked existing issues, online documentation and the Troubleshooting Guide