Calls made to malloc/free will enable interrupts on return

[mhightower83]

Basic Infos

• This issue complies with the issue POLICY doc.
• I have read the documentation at readthedocs and the issue is not addressed there.
• I have tested that the issue is present in current master branch (aka latest git).
• I have searched the issue tracker for a similar issue.
• If there is a stack dump, I have decoded it.
• I have filled out all fields below.

Platform

• Hardware: ESP-12
• Core Version: 5a47cab
• Development Env: Arduino IDE
• Operating System: Ubuntu

Settings in IDE

• Module: Adafruit Feather HUZZAH ESP8266
• Flash Mode: qio
• Flash Size: 4MB
• lwip Variant: v2 Lower Memory
• Reset Method: nodemcu
• Flash Frequency: 40Mhz
• CPU Frequency: 80Mhz
• Upload Using: SERIAL
• Upload Speed: 115200 (serial upload only)

Problem Description

To simulate an IRQ handler calling malloc I used xt_rsil() to set INTLEVEL.
when malloc/free are called with an elevated INTLEVEL, INTLEVEL is set to 0 on return.

I noticed that ets_intr_lock() and ets_intr_unlock() are being used to handle critical section for umm_malloc. ets_intr_unlock() does not restore the previous INTLEVEL; it does an rsil a2, 0.
Ref: #2218 (comment) Thus causing the immediate problem.

MCVE Sketch

#include <ets_sys.h>
#include <interrupts.h>

#ifndef xt_rsr_ps
#define xt_rsr_ps()  (__extension__({uint32_t state2; __asm__ __volatile__("rsr.ps %0" : "=a" (state2)); state2;}))
#endif

/* 
 * A printf routine that can safely print with interrupts disabled
 * and does no "malloc lib" calls. 
 * 
 * The default printf will do a malloc call, spoiling the test.
 */
 
// ROM _putc1, ignores CRs and sends CR/LF for LF, newline.
// Always returns character sent.
extern "C" int constexpr (*_putc1)(int) = (int (*)(int))0x40001dcc;

extern "C" void uart_buff_switch(uint8_t);

int _sz_printf_P(const size_t buf_len, const char *fmt, ...) __attribute__((format(printf, 2, 3)));
int _sz_printf_P(const size_t buf_len, const char *fmt, ...) {
  
#ifdef DEBUG_ESP_PORT
#define VALUE(x) __STRINGIFY(x)
  // Preprocessor and compiler together will optimize away the if.
  if (strcmp("Serial1", VALUE(DEBUG_ESP_PORT)) == 0) {
    uart_buff_switch(1U);
  } else {
    uart_buff_switch(0U);
  }
#else
  uart_buff_switch(0U); // Side effect, clears RX FIFO
#endif

  char __aligned(4) ram_buf[buf_len];
  ets_memcpy(ram_buf, fmt, buf_len);
  va_list argPtr;
  va_start(argPtr, fmt);
  int result = ets_vprintf(_putc1, ram_buf, argPtr);
  va_end(argPtr);
  return result;
}

#define printf(fmt, ...) _sz_printf_P((sizeof(fmt) + 3) & ~0x03U, PSTR(fmt), ##__VA_ARGS__)



void setup() {
  Serial.begin(115200);
  delay(20);
  uint32_t beforePS, afterPS;

  printf("\n\n\nShow what happens to an elevated INTLEVEL after a \"malloc\" and \"free\"?\n");
  
  printf("\n  Preset INTLEVEL with \"xt_rsil(3);\"\n");
  xt_rsil(3);
  // Confirm that printf() is not spoiling our test.
  //   * A pass while the other tests fail is confirming.
  //   * A pass while the other tests pass tells nothing.
  beforePS = xt_rsr_ps();
  printf("  %s\n", "Indirectly confirm that printf() is not calling malloc and spoiling our test?");
  afterPS = xt_rsr_ps();
  printf("  PS register before/after \"printf();\":  0x%04X/0x%04X, %s\n", beforePS, afterPS, (beforePS ==  afterPS) ? "Pass" : "Fail!");

  printf("\n  Preset INTLEVEL with \"xt_rsil(4);\"\n");
  xt_rsil(4);
  beforePS = xt_rsr_ps();
  char *pc = (char *) malloc(3);
  afterPS = xt_rsr_ps();
  printf("  PS register before/after \"malloc(3);\": 0x%04X/0x%04X, %s\n", beforePS, afterPS, (beforePS ==  afterPS) ? "Pass" : "Fail!");

  *pc = '1'; // w/o this, malloc/free appears to be optimized away.
  
  printf("\n  Preset INTLEVEL with \"xt_rsil(5);\"\n");
  xt_rsil(5);
  beforePS = xt_rsr_ps();
  free(pc);
  afterPS = xt_rsr_ps();
  printf("  PS register before/after \"free(pc);\":  0x%04X/0x%04X, %s\n", beforePS, afterPS, (beforePS ==  afterPS) ? "Pass" : "Fail!");
  
  xt_rsil(0);
  printf("\n\n");
}

void loop() {
  // Something to show we did not hang
  static size_t count = 0;
  delay(1000);
  printf(".");
  if (((++count) % 72) == 0)
    printf("\n");
}

Debug Messages

Show what happens to an elevated INTLEVEL after a "malloc" and "free"?

  Preset INTLEVEL with "xt_rsil(3);"
  Indirectly confirm that printf() is not calling malloc and spoiling our test?
  PS register before/after "printf();":  0x0023/0x0023, Pass

  Preset INTLEVEL with "xt_rsil(4);"
  PS register before/after "malloc(3);": 0x0024/0x0020, Fail!

  Preset INTLEVEL with "xt_rsil(5);"
  PS register before/after "free(pc);":  0x0025/0x0020, Fail!

Other Thoughts and Observations

The comments in the code indicate that the locking macros must be allowed to nest. In regards to the comment about _umm_malloc() having a call to _umm_free() I think the code may have been changed after that was written; however, there are calls to _umm_malloc() and _umm_free() from _umm_realloc() that would require nest support.

Arduino/cores/esp8266/umm_malloc/umm_malloc_cfg.h

Lines 103 to 114 in 5a47cab

	/*
	* A couple of macros to make it easier to protect the memory allocator
	* in a multitasking system. You should set these macros up to use whatever
	* your system uses for this purpose. You can disable interrupts entirely, or
	* just disable task switching - it's up to you
	*
	* NOTE WELL that these macros MUST be allowed to nest, because umm_free() is
	* called from within umm_malloc()
	*/
	#define UMM_CRITICAL_ENTRY() ets_intr_lock()
	#define UMM_CRITICAL_EXIT() ets_intr_unlock()

I have explored using XTOS_SET_MIN_INTLEVEL and XTOS_RESTORE_INTLEVEL from
ESP8266_RTOS_SDK/components/esp8266/include/xtensa/xtruntime.h for the UMM_CRITICAL_ macros. It has been working well for me. And there are comments in xtruntime.h about how it works, something I could never find for ets_intr_lock(). I like that you can specify an INTLEVEL to XTOS_SET_MIN_INTLEVEL and if the current level is higher it will keep it, instead of demoting it, as ets_intr_lock did.

An interesting side benefit from the broken nesting with the ets_intr_lock was that in one section of _umm_realloc() , after a _umm_malloc() call, interrupts were enabled before memcpy() was called. Curiously - this looks like it was safe. All variables referenced at this point were on the stack. I say benefit in the sense that a large block of data could be copied without exceeding the 10us max time for interrupts off.

Arduino/cores/esp8266/umm_malloc/umm_malloc.cpp

Lines 1641 to 1654 in 5a47cab

	/*
	* Now _umm_malloc() a new/ one, copy the old data to the new block, and
	* free up the old block, but only if the malloc was sucessful!
	*/
	if( (ptr = _umm_malloc( size )) ) {
	memcpy( ptr, oldptr, curSize );
	_umm_free( oldptr );
	}
	}
	/* Release the critical section... */
	UMM_CRITICAL_EXIT();

I have explored the idea of lightly refactoring _umm_realloc() to support locks off during copy/memmove to reduce the over 10us burdon. Of course, when called from an IRQ routine it has no effect, interrupts are off for the whole process. It seems to be working; however, I may not have a sketch that is demanding enough.

[devyte]

Thanks for the analysis. The core currently doesn't support masking a specific interrupt level. That doesn't mean it can't be implemented, only that at this time locking is implemented as all or nothing.

In any case, your investigation hints at a deeper underlying issue with very wide scope.

Dev Notes:

use case as follows:
disable interrupts
do stuff
malloc //ints get re-enabled
do more stuff //this code is not protected as is expected
enable interrupts //does nothing because ints were enabled above

Considerations:
interrupt lock must nest (stack?) x16 (all int levels)
umm must not be interruptible, ever
InterruptLock changes in interrupt. h
replace ets_enable|disable with something else for umm

[d-a-v]

Your sketch passes all three tests with:

#define UMM_CRITICAL_ENTRY() esp8266::InterruptLock lockMeHere
#define UMM_CRITICAL_EXIT()  do { (void)0; } while (0)

It's not simple as that because of definitions in Arduino.h included from everywhere, so I ended up copying the class into umm for testing because some include-and-definition-location rework is required - I can try to make a PR to prepare for that change if you need so)

Thanks

[mhightower83]

@d-a-v, thanks, but I am good. I have already worked through this issue for my needs. I saw this issue in the code while exploring how UMM_POISON worked. I ended out looking at how umm_malloc.cpp worked for a while and made a few other changes. For example, I monitored the min/max timings for the locks in, info/malloc/free/realloc when running my project. Now that I have my project working, I am making my way through different things I have changed and identifying the ones that are problems, that need to be reported/fixed. Writing does not come easy for me. It takes me quite a few drafts before hitting send.

Thanks to everyone for all that you do here. I don't know how you find the time to do so much.

[devyte]

@mhightower83 your writing was good enough and your analysis detailed enough to lead my thinking right to an unknown problem that could explain a lot of odd crashes. Please uphold your practice of reporting in that way!

[devyte]

@d-a-v os there anywhere in the umm code where:
a) more than one critical section exists in the same scope? I'm thinking of conflict due to multiple declarations of interruptLock
b) a critical section is entered in one scope but exited in another? I'm thinking of class destruction in the wrong place. Because these are defines, it should be possible to test this by adding a { before the entry and a } after the exit, which would force destruction on exit, but would fail to build if entry and exit are in different scopes.

[earlephilhower]

UMM's very simple, basically a single file of straight C. There are no object delete/creates, so (b) should not be an issue.

There is only 1 UMM_CRITICAL_ENTRY per function, so that's fine.

There is nested calls (realloc sets CRITICAL but then can call free() which also sets CRITICAL). However that's not a problem since only the first one will do anything.

[devyte]

@earlephilhower the nested case you mention seems to me like a variation of the use case I described above. I took a quick look at umm, and realloc is the worst case: it calls free and malloc from inside the critical section:

realloc()
  some code
  ENTRY (ints locked)
  some code
  jump to malloc()
    some code
    ENTRY (does nothing)
    some code
    EXIT (reenables ints)
    some code (point A)
    return from malloc()
  some code (point B)
  EXIT (does nothing)
  some code
  return from realloc

The code from point A to point B inclusive won't be protected as is expected, unless we implement nested locks.

[devyte]

Thinking further, nested locks are actually already supported via multiple instances of InterruptLock, where each instance represents one level of nesting (the instance saves the previous state, then restores it on destruction).
I think the scopes are ok, which means that @d-a-v 's solution is viable as proposed. Good thing we have umm building as C++ :)

However, @d-a-v 's solution only applies to code under our control. Is there any way to know if the ets_intr_blah() functions are called from anywhere else, e.g.: the closed libs?

[earlephilhower]

You can get a list of imports (undefined externals) easy enough for the .as we link in with nm, but realistically I think there's not much we can do about them.

[d-a-v]

@devyte
We can extract ets_intr_*lock() from firmware as we currently are doing for some other symbols.
We can then re-implement them properly.

@mhightower83
You found a nasty bug, and when there's a fixable one we usually try to address it asap.
Will you propose a fix soon enough ?
(that, because your finding, your credited commit)

This ets_intr_*lock() bug should be mentioned in the nonos-sdk repository.