ets_printf may not be safe for ISR debug printing

mhightower83 commented 5 years ago

Basic Infos

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

Platform

Hardware: [ESP8285 device]
Core Version: [f2de9e130c66b00cc9e9d8b4e9144b0f5621607d]
Development Env: [Arduino IDE]
Operating System: [Ubuntu]

Settings in IDE

Module: [Generic ESP8285 Module]
Flash Mode: [dout]
Flash Size: [1MB]
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

I have seen in several places where ets_printf() is the recommended function call for debug printing from an ISR; however, from what I see in the current master I don't think this is true anymore.

ets_printf() uses the character print function installed by ets_install_putc1(). At the start of setup() the print function address resides in IRAM. Once Serial.begin() is called that print function address resides in flash. The MCVE below shows the function address under various situations and the resulting output across Serial and Serial1.

It looks to me that of these options, the safest ISR debug print solution is to use ets_uart_printf() and/or ets_putc(). Both of these functions reside in ROM and neither uses the print function installed by ets_install_putc1(). They use an internal ROM function for printing, which requires a prior call to uart_buff_switch() to select a UART.

MCVE Sketch

#include <ESP8266WiFi.h>
#include <ets_sys.h>
#include <osapi.h>

// Boot ROM print functions
extern "C" int ets_uart_printf(const char *format, ...)  __attribute__ ((format (printf, 1, 2)));
extern "C" void ets_write_char(char c);
extern "C" void uart_buff_switch(uint8_t);
typedef void (*fn_putc1_t)(char);

// Boot ROM data area reference
// Location where ets_install_putc1 saves function address
#define installed_putc1 ((fn_putc1_t)(*(void **)0x3fffdd48))

void print_test() {
  char c;
  size_t i;
  os_printf("  os_print()\n");
  os_printf_plus("  os_print_plus()\n");
  ets_printf("  ets_printf()\n");
  for (i=0; (c="  installed_putc1()\n"[i]); i++) installed_putc1(c);
  for (i=0; (c="  ets_write_char()\n"[i]); i++) ets_write_char(c);

  ets_uart_printf("  ets_uart_printf()\n");
  for (i=0; (c="  ets_putc()\n"[i]); i++) ets_putc(c);
}

void setup() {
  fn_putc1_t original_putc1 = installed_putc1; 
  WiFi.mode(WIFI_OFF);

  Serial.begin (115200);
  Serial1.begin(115200);

  Serial.printf ("\nOriginal value at setup()     putc1 = %p\n", original_putc1);
  Serial1.printf("\nOriginal value at setup()     putc1 = %p\n", original_putc1);

  Serial.printf ("\nAfter Serial.begin(115200)    putc1 = %p\n", installed_putc1);
  Serial1.printf("\nAfter Serial.begin(115200)    putc1 = %p\n", installed_putc1);
  print_test();

  Serial.setDebugOutput(true);
  Serial.printf ("\nSerial.setDebugOutput(true)   putc1 = %p\n", installed_putc1);
  Serial1.printf("\nSerial.setDebugOutput(true)   putc1 = %p\n", installed_putc1);
  print_test();

  Serial1.setDebugOutput(true);
  Serial1.printf("\nSerial1.setDebugOutput(true)  putc1 = %p\n", installed_putc1);
  Serial.printf ("\nSerial1.setDebugOutput(true)  putc1 = %p\n", installed_putc1);
  print_test();

  Serial1.setDebugOutput(false);
  Serial.printf ("\nSerial1.setDebugOutput(false) putc1 = %p\n", installed_putc1);
  Serial1.printf("\nSerial1.setDebugOutput(false) putc1 = %p\n", installed_putc1);
  print_test();

  uart_buff_switch(0);
  Serial.printf ("\nuart_buff_switch(0)           putc1 = %p\n", installed_putc1);
  Serial1.printf("\nuart_buff_switch(0)           putc1 = %p\n", installed_putc1);
  print_test();

  uart_buff_switch(1);
  Serial.printf ("\nuart_buff_switch(1)           putc1 = %p\n", installed_putc1);
  Serial1.printf("\nuart_buff_switch(1)           putc1 = %p\n", installed_putc1);
  print_test();

  uart_buff_switch(0);
  Serial.printf ("\nuart_buff_switch(0)           putc1 = %p\n", installed_putc1);
  Serial1.printf("\nuart_buff_switch(0)           putc1 = %p\n", installed_putc1);
  print_test();

}

void loop() {}

Debug Messages

From Serial

Original value at setup()     putc1 = 0x401049e0

After Serial.begin(115200)    putc1 = 0x40203d40
  ets_uart_printf()
  ets_putc()

Serial.setDebugOutput(true)   putc1 = 0x40203024
  os_print()
  os_print_plus()
  ets_printf()
  installed_putc1()
  ets_write_char()
  ets_uart_printf()
  ets_putc()

Serial1.setDebugOutput(true)  putc1 = 0x40202fe8
  ets_uart_printf()
  ets_putc()

Serial1.setDebugOutput(false) putc1 = 0x40203d40
  ets_uart_printf()
  ets_putc()

uart_buff_switch(0)           putc1 = 0x40203d40
  ets_uart_printf()
  ets_putc()

uart_buff_switch(1)           putc1 = 0x40203d40

uart_buff_switch(0)           putc1 = 0x40203d40
  ets_uart_printf()
  ets_putc()

From Serial1

Original value at setup()     putc1 = 0x401049e0

After Serial.begin(115200)    putc1 = 0x40203d40

Serial.setDebugOutput(true)   putc1 = 0x40203024

Serial1.setDebugOutput(true)  putc1 = 0x40202fe8
  os_print()
  os_print_plus()
  ets_printf()
  installed_putc1()
  ets_write_char()

Serial1.setDebugOutput(false) putc1 = 0x40203d40

uart_buff_switch(0)           putc1 = 0x40203d40

uart_buff_switch(1)           putc1 = 0x40203d40
  ets_uart_printf()
  ets_putc()

uart_buff_switch(0)           putc1 = 0x40203d40

earlephilhower commented 5 years ago

@mhightower83, what do you suggest to resolve this? A documentation addition? I don't think any of the core routines themselves (other than maybe your cool new umm stuff when called by an evil IRQ to allocate memory) try and print stuff in an ISR...

devyte commented 5 years ago

@mhightower83 I'm not sure I understand the use case either. Are there ISRs somewhere in our core or in the sdk that are printing out with unsafe functions? Or do you mean for a general guideline, e. g. :"mr user, if youre in an ISR, don't use these print functions, use those instead"?

mhightower83 commented 5 years ago

@devyte the later.

What I noticed when I searched for a safe printf function to use for debugging from an ISR (or rsil(15)), was ets_printf() was often suggested. And, I believe using the bare NONOS SDK it is safe (the installed putc1 function is in IRAM); however, with the current Arduino ESP8266 Core, once you run Serial.begin() or Serial1.begin() the installed putc1 function is in flash. Thus a group of print functions, that ~use~ rely on the results of the ets_installed_putc1 function, are not safe for ISR use even if they are in ROM.

Also worth noting is that os_printf_plus is in IRAM and the putc1 function also started out in IRAM before Serial.begin(). On this point, I am left wondering if the Blob would ever call os_printf_plus from an ISR like state.

In the printout, I was trying to show the changes in the putc1 function and the print functions that it affected and how.

So my conclusion was that for debugging purposes ets_putc, ets_uart_printf, and uart_buff_switch are the functions to use for printing from an ISR.

Update: Improved wording

esp8266 / Arduino