ESP8266 Cont stack keeps growing with simple Serial.printf (no recursion, no unused stack variables)

[vgahlaut]

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: [Rel 3.1.2]
• Development Env: [Arduino]
• Operating System: [Windows]

Settings in IDE

• Module: [Generic ESP8266 Module]
• Flash Mode: [dio]
• Flash Size: [4MB/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

This issue is somewhat related to following issue.
#5148
#9069
and following post
https://www.esp8266.com/viewtopic.php?p=87105

Reason for creating this as a new issue is that we have created simple reproducer where Cont stack keeps growing even if same function called in loop repeatedly. Since we are not using any ticker or similar kind of code where callbacks could affect sys stack so problem seems to be related to cont stack / Serial.printf implementation

We could understand higher watermark of cont stack when function is called for the first time with maximum array size of 500 to be printed but it keeps increasing (reducing free stack size) in repeated loop calls for same function though frequency of stack increase reduces with time.

It can be reproduced with Generic ESP8266 module/board. We used ESP-12F. Please see the logs running loop for 1000 times.

You can observer that before starting the loop available stack size was 3280 and after first function call free stack size is reduced to 3216. May be stack is freed and it just a watermark that stays to 3216.

However in logs, you can observe following
On Loop count 20, Available Cont stack size reduced to 3136
On Loop count 27, Available Cont stack size reduced to 2960
On Loop count 46, Available Cont stack size reduced to 2944
On Loop count 608, Available Cont stack size reduced to 2864

1. We are not clear if stack is growing or just watermark is growing. Need your help to understand
2. Even if it is watermark why it keeps growing when same function is called.
3. As there is no recursion, empty variable so there is no reason for stack/watermark to grow.
4. In our actual implementation with large code base (Issue ESP8266 Crashing During Prints randomly #9069) if we enable logs (Serial.printf) we are reaching to a point where we see free cont stack reduces to 0 just before system report stack smashing and reboots. So it is very important to understand, should it grown is this sample sketch, if yes, under what circumstances?
5. Is it a bug or expected behavior, if expected behavior, a reasonable explanation will be helpful because our system is expected to work for months with reboot/power cycle and we may need to enable prints to catch field issues and enabling prints is causing stack smashing.

MCVE Sketch

#include "Arduino.h"
#include <Esp.h>

#define MAX_UINT  4294967295

unsigned short len;
unsigned int loopcount = 0;

void irRawDataDump(unsigned short *buf, unsigned short len);

void setup() {
  Serial.begin(115200);
}

void loop() {

  Serial.printf("Looping Again... Count: %d\r\n", loopcount);

  if(loopcount == 0){
    // First time print maximum length
    len = 500;
  }else{
    // Print random length between 1 - 500
    len = random()%500;
    if(len == 0){
      len = 500;
    }
  }

  processData(len);

  loopcount++;

  if(loopcount == MAX_UINT){
    // Reset Loopcount 
    loopcount = 1;
  }

  delay (1000);

}

void processData(unsigned short len)
{
  unsigned short *data;

  data = (unsigned short *)malloc( sizeof(unsigned short) * len);

  memset(data, 0, sizeof(unsigned short) * len);

  Serial.printf("Cont Free stack Size Before Prints: %d\r\n" , ESP.getFreeContStack());

  printData(data, len);

  Serial.printf("Cont Free stack Size After Prints: %d\r\n" , ESP.getFreeContStack());

  free (data); 

}

void printData(unsigned short *buf, unsigned short len)
{
    Serial.printf("================ DATA =============\r\n");
    Serial.printf("Data Length: %d\r\n", len);
    for (int i = 0; i < len; i++)
    {
        Serial.printf("%d ", buf[i]);
    }
    Serial.printf("\r\n===============================\r\n");
}

Debug Messages

Please see the attached Log file. 
[putty.log](https://github.com/esp8266/Arduino/files/13931691/putty.log)

[ACE1046]

Only watermark is growing. You can repaint stack with ESP.resetFreeContStack();.

I've tested your sketch with stack repaint on every loop. getFreeContStack() changes a lot, by about 300 bytes at least. But always returns to start value after repaint.

At start:

Cont Free stack Size After Prints: 2928
Looping Again... Count: 19
Cont Free stack Size Before Prints: 3280

After some time:

Cont Free stack Size After Prints: 2944
Looping Again... Count: 4847
Cont Free stack Size Before Prints: 3280