Search This Blog

Showing posts with label exception. Show all posts
Showing posts with label exception. Show all posts

Monday, 20 August 2018

Using C++ std library with ESP8266 Ardiuino IDE - some "gotchas" solved

The hunting of the Snark

In the latter stages of testing the forthcoming release of Esparto v2, I was "stress" testing it by throwing everything including the kitchen sink at it to see how it coped.

Short story is : it didn't. Low workloads were absolutely fine, but once the rate got above a certain figure - and I couldn't work out exactly how big - it fell in a screaming heap, which is the one thing it is designed specifically NOT to do.

Very frequently it would crash with a stack dump and it was clear that heap exhaustion was the culprit. What slowed me down was that I had spent a lot of time building in heap protection. But no matter how careful and extensive my protection was, it was failing. I searched - literally - for days, stitching in almost as much diagnostic code as there was "real" code. On a couple of occasions, I created a "heisenbug" with my diagnostics: after putting them in, the bug went away. Take them back out, it reappeared. "Aha!" I thought that's a sure-fire sign of a timing problem.

Given that the whole thing is wrapped very tightly round a microsecond-indexed custom priority_queue on the main loop which has to co-operate with asynchronous events via a mutex, it was no surprise. And I had had problems with that core module in the past. And I had made a lot of changes to it -so it was no surprise to find that that's where a lot of my "wasted" days were spent...

Ironically, it's not actually a lot of code - about 500 lines of which about 30-odd percent or more is comment and/or vertical spacing for clarity so maybe only 3-400 lines of code, but its hellishly complex - for me at least.

For a start although I have been Cing and C++ing for many a year, I only looked st the standard library about 9 months ago, as It had rapidly become clear that "functional programming" was  the only way I could get a timer to call back to a class method which was a fundamental pre-requisite for an Arduino library. Once I had got my head around lambdas and function objects and the how-did-I-ever-do-without-it bind mechanism with placeholder parameters, I was cooking! I then delved into containers and I'm now sold sold sold and wouldn't ever dream of doing things any other way. I did have to spend a lot of time with my head in Stroustrup and whining on Stack Overflow, but I got there. Mostly.

Secondly, there is the very nature of the beast: that rare area that mostly only OS designers play with more than once: task synchronisation, critical sections, interlocked atomic access, volatiles, mutexes and a slew of buzz phrases most programmers never meet in a full career...luckily I'd had some previous experience - on mainframes in the mid 1970s...Oddly enough, it was a huge help when it all came back to me. The words may be different in ESP8266land, but the tune is the same.

Thirdly I was new-ish to the ESP8266 having got into the embedded scene (as many others) with AVR-based Arduinos.

All in all, a "random" timing bug under heavy loads was all I didn't need. After days of searching and not finding, I came reluctantly to the Sherlock Holmes conclusion:

"When you have eliminated the impossible, whatever is left - no matter how improbable - must be the truth"

The truth in this case was that the reason I couldn't find the bug in my code is because - it wasn't in my code! Therefore it must be in someone else's! The prospect of digging through profoundly complex library code written by geniuses - obviously for what would be days and daysdid not fill me with deep joyOnce I had finally tracked down and nailed the problem it turned out, it wasn't actually a bug but a combination of two things, both of them on the very limits of my knowledge comfort zone. But I'm jumping ahead.

The first big clue was my voluminous diagnostics revealing a sudden and huge drop in the available heap shortly before lights-out. Every time. At least that part had a pattern. I knew though bitter sweat and very very late nights to the sound of much swearing, I could account for every byte of memory I used, every pointer RAII'd until it bled, every heap fluctuation possible - I had the spreadsheets and graphs to prove it. Yet here was a sudden massive bite out of a very small cherry while I sat with my jaw clamped shut.

We all know the ESP8266 is heap-limited. There is a ton of other code on top of my core scheduler: a web server doing dynamic updates in real-time via web sockets, a real-time pin management library, auto WiFi / MQTT connection  management with AP fallback , yada yada yada all the way up to 410k plus. The app gets out of bed with less than 30k heap to play with. By the time it tells you MQTT is waiting to hear from you, there is only 27k left in the bank.

So who or what was stealing - out of nowhere - 16k or 60% of my available space? It would be OK when I was at 27, but if the heap-thief helped itself when I had 11k spare, guess what? Oblivion. Sadly, it did exactly that quite often.

Now the implementers of the std library on this platform are obviously well aware of the ESP8266's pint pot into which they had to shoehorn a barell-full of stdlib. Something had to give. Gone is any type info, gone is the ability to get the target of a function object...I could go on, suffice to say that while it is mostly functional for my humble needs it is a (necessarily) heavily-hacked offering.

The extensive stack back trace looked like an explosion in an alphabet soup factory in Moscow. I couldn't make head nor tail once it had got below the precious few of my own routines but I persevered and finally hit pay dirt as the second of the issues became apparent to me: my lack of experience in looking "under the hood" of stl.

It's a memory problem, I know that much. I also know I can't see the problem because its not in my code, so I'm going to have put diagnostics in - gasp - the stl code. After recovering from a near-faint at the thought, I vaguely recalled a little-if-ever used feature of the custom allocator. I had glossed over it as I knew I would never be needing it. Until now, of course! If I could write a custom allocator - yes, this is how desperate I was getting - I could sprinkle it with printfs and finally nail the problem.

By jingo, that's what I started to do. I found a skeleton malloc-based proof-of-concept template on't'web and blindly cut and pasted it it, as I sure as hell couldn't understand a word of it! So it was back to Bjarne and StackOverflow and I concentrated on how this foreign beast was meant to do it magic, I never even considered the when and why...

Blinkering my vision was the fact that because I "knew" I only had a few tasks in my queue, I was concentrating on numerous other potential culprits. What I hadn't seen was that a second (yes! how odd!) bug was causing me to double- and even triple-dip at stuffing tasks into the queue. The logic simply ignored the excess and/or duplicates, so it just wasn't apparent anywhere.

I think the exact Eureka! moment came as I delved deeper into the allocator's black box that I heard myself asking "Why is the last thing just after I have added one of my meagre handful of taks to the queue?" At this point, the experienced stl'ers amongst you will have probably already seen the problem, which could even be - by some standards - classed as a "schoolboy error". Those of you who use it on big machines with unlimited virtual memory may not yet have spotted it though, because what happens on an ESP8266 never happens in your big world.

Hiding complexity is one of stl's great strengths, but it has it's dark side too, as was the case here. I knew that these magic containers would stretch to fit. What I didn't know was a) when b) by how much. What I also couldn't see was that - albeit in error - I had filled up my small queue. How small? Who knew? Only the folk who implemented the stl on the '8266. Some arbitrary default initial size that would automatically stretch to fit as and when required.Without asking. Or telling. All that nasty implementation stuff is hidden from view, which - after all - is why we use the thing in the first place isn't it?

Drifting off into the new territory of dynamic resizing, I was trying to find the place in the allocator to put the printf with current heap size at the point where my queue was allocated, so I could see how much free heap there was and what else might be stealing it But I couldn't spot where an initial allocation was made and/or a resizing allocation was made. I didn't want to waste my efforts and put it anywhere near resizing code, because my queue was so small it would never need resizing! In an idle moment I mused on what might happen in that scenario: how much bigger would it grow and where in this mess would I even start to look for that?

"Because.." I thought, musing to myself to avoid having to solve this impossible bug, "...if  it did for some bizarre reason allocate a huge chunk...".

Then it hit me like a brick: I was looking for something under the hood that not only had the potential to, but was actually grabbing a huge chunk of memory without being asked, wasn't I? I'd got so many levels nested in the complexity that I'd forgotten my call return address. Once I unwound my own mental stack, I realised I was staring the problem right in the eyes: It wasn't something else stealing the memory, it was  the queue itself!

"But why? It's tiny, look, this extra diag will show the size....!. Oh. Oh, that's a shock - where did all those tasks come from? Is there a bug in clearing the queue? Nope, checked that, works fine. is it a timing thing? Queue so busy that some underlying memory-freeing thingamajig an't get a look in?"

No, it's me accidentally busting the queue and the queue very obligingly and silently trying to expand to nicely accommodate me ...by not-so-nicely grabbing 60% of the little I have left. Bingo!

I rapidly found out how to set the capacity of the underlying vector container, hunted down the duh! bug that was tripling my queue, daringly removed (well commented out, I'm not that stupid) almost all the diagnostics, crossed my fingers, legs, arms and eyes and hit "run".

You know the rest: bug splatted. All the other code worked fine too and suddenly I'm almost ready to release. See the more recent posts here for a quick look-in - ignore the earlier posts from a few months back, it's changed a lot (because of this) since then.

On a big machine in the real world, I'd have never even noticed this. I'd have gone for release with an inefficient, heap-hungry monster. Such beasts don't live long in the mbeeded wrold, This particular one lived a lot longer than it should have, but - hey, we learn by our mistakes. Or by reading about others'!

The morals of this story are manifold:

  • Get to know a new technology in detail before playing with it in anger
  • Preallocate stl containers wherever possible
  • Where you can't preallocate, guard all accesses with heap checks
  • When you have eliminated the impossible...
  • Find the person who thinks 16k is a good size for reallocation on an '8266 and "have a word"

Anyone want to buy a brand-new completely unused custom stl memory allocator? It's an ideal self-teaching tool...

Wednesday, 1 November 2017

Beware of the (watch)dog!

Your house is full of smoke. The smoke alarm is beeping. Do you a) Turn of the smoke alarm and burn alive or b) find the source of the smoke and put out the fire?

I'm sure most folk would opt for b) but the most common problem I see when helping newbies in various esp8266 forums is the programmming equivalent of a). For reasons that are explained elsewhere on this blog LINK programming the ESP8266 isn't the same as programming  a "simple" AVR / Arduino etc and part of that difference frequently causes a "watchdog" timer reset - essentially a "crash" followed by a reboot.

These things generally only happen when the programmer doesn't fully grasp all the issues mentioned in the above LINK, but their first attempts to "fix the problem" usually involves "shooting the meesenger" and turning off the smoke alarm...

If you already know what a WDT is, how it works and why, then you will probably disagree with some aspects of my next statement...in which case, pop off somewhere else and let those who don't yet know those answers to allow this to sink in:

DO NOT TOUCH THE WATCHDOG TIMER. YOU DON'T NEED IT. FORGET IT EVEN EXSISTS! WHATEVER YOU THINK THE PROBLEM IS, IT IS ABSOLUTELY NOT THE WATCHDOG TIMER! DON'T FEED IT. DON'T DISABLE IT. 

D O N ' T   T O U C H  I T!!!

The “watchdog” timer (WDT) is the ESP8266’s smoke alarm. It goes off when there is a fundamental problem with your code. You need to find and fix that problem, not mess around with the WDT.

Embedded systems often don’t have the luxury of a screen and/or keyboard and are frequently fitted in difficult-to-access places where they are never seen by the human eye such as behind your living room wall or under the hood of your car - or in my case - 25feet up on a barn roof... When something fatal occurs, they have little option but to automatically reset themselves, thus many such devices have a WDT built into the hardware. This monitors the state of the system and if it freezes, locks / up or loops indefinitely for more than an “acceptable” amount of time, the WDT will reboot the device. After all, an occasionally faulty device is better than no device at all - especially if it controls your brakes.

I see many forum posts where the programmer says one of:
  •        “I need to understand how the WDT works”
  •        “There is something wrong with the WDT”
  •        “My code runs fine on xxxx , but when I run it on the ESP8266, I get a WDT reset”
  •      “Every time I run my code, I see: WDT reset, please help”.
My answers usually are:
  • Oh no you don't (see above)
  • Oh no there isn't
  • So what?
  • Read this blog
It really helps if you have already read the article on "Asynchronous programming". If you haven't, then you need to, because WDT problems are the tip of an iceberg and you need to understand the whole iceberg to get the best out of your ESP8266.

The usual cause of a WDT reset is that your code is “blocking” which means its stopping other processes or "threads" from running. This is often caused by taking too long to do what you think it needs to do. The most common causes I see are indiscriminate use of  delay() calls and/or waiting in a loop for an external resource e.g. a remote website. 

So how long is “too long” and what is an “acceptable” period of time, when your code already runs fine on an Arduino / stm32 / cray 1 / HP pocket calculator? Perhaps more importantly - why

ESP8266 is a WiFi capable device – that’s why you bought it, right? Connecting to, disconnecting from,  and – more importantly - maintaining a WiFi link os not magic - it takes processing time. There is only one CPU. The most important thing to grasp is that the code you write is not the only code running in the chip. About 200k+ of ESP code is loaded in before you even get to think about blinking an LED. And when does that code run? All the time. It runs “in the background” and you cannot easily see it or find out exactly what it’s doing and when. It just does its thing. Untill you interfere with it and stop it doing its thing. Then the WDT kicks in. It's really quite simple.

If your code stops the WiFi code from running for more than a very short period of time, the WDT says “oops! System has locked up, reboot!”. There is a reason why I have left you thinking "what does 'very short' mean? How long exactly is it?" and the reason is because if you write your programs correctly, you don't need to know. If you really want to, google it.

Yes, you can try to turn off  the WDT to “fix” the problem, but like the smoke alarm, it doesn’t remove the source of the fire, it just delays the inevitable. You can turn off the smoke alarm too, but if that is your preferred solution, I won’t be staying at your house, thank you. Even if you turn it off but still don't fix your code, the hardware WDT will probably kick in after a few seconds -and you can't turn that one off, so you are still going to crash - just several seconds later than if you hadn't turned off the software WDT.

Yes, there are ways you can "cheat" and "feed" the watchdog, but all you are doing is putting a blanket over the beeping smoke alarm to obscure the problem and hiding your bad code. Bad code generally finds a way to bite you in the ass no matter what you do, so it's best to find it and get rid of it, don't you think?

The only solution is to find the part of your code which blocks the background processing and then change it so that it doesn't. How to change it is a whole other (complex) story and for that, you definitely need to understand the link you haven't read yet...How do I know you haven't read it? Easy - because if you had, you wouldn't need to be reading this. Now go and read it.

The only way to absolutely guarantee no WDT resets is to write your code so that it can run asynchronously, co-operate fully with other processes and obey all the rules that multitasking requires. Unfortunately, that is a) a whole new way of thinking b) can be quite complex. With some basic rules, you can avoid most of the problems, but don't forget: we are talking about the tip of an iceberg here.

Until you get more experienced and fully understand the above paragraph, try to stick to the following:

1.       Never forget that yours is not the only code running.
2.       The problem is in your code. Messing with the WDT won’t fix that.
3.       Try to avoid delay() if at all possible. Only ever include delay() if it is absolutely needed and you truly understand why it is needed. If both of those aren't true, take it out.
4.       Never sit in a loop waiting for an external event to happen. Instead, set a volatile global, test and reset the global in the main loop. The same goes for callbacks and timer events. Or, write your code properly (see above link)
5.       Yield() in your main loop.
6.       If a library has a “run” or “handle” or “loop” method, always call it, it’s there for a reason!  This is usually the way library code does what your code also needs to do: co-operate with all other code running in the CPU. The best place is in your main loop.
7.       Never disable the WDT, it’s there for a reason!

Dont' Delay!

The following code looks like it will wait until pin 5 goes LOW until allowing the loop function to run:

void setup(){

  Serial.begin(74880);

  pinMode(5,INPUT_PULLUP);

  Serial.printf("T=%d Waiting\n",millis());

  while(digitalRead(5)==HIGH);

  Serial.printf("T=%d Ready\n",millis());

}

The while loop is a technique used on other systems - and probably works - but here's what happens on an ESP8266:

T=5204 Waiting

Soft WDT reset

ctx: cont
sp: 3ffef240 end: 3ffef420 offset: 01b0

>>>stack>>>
3ffef3f0:  3fffdad0 00000000 3ffee3c8 40201c28
3ffef400:  feefeffe feefeffe 3ffee3ec 4020237c
3ffef410:  feefeffe feefeffe 3ffee400 40100718
<<<stack<<<

It just crashed. What happened was, your code is in a very tight loop, and while it is there, the WiFi code cannot run. The "watchdog timer" thinks the processor has "hung up" and so it restarts the system. This alone is one good reason is why programming the ESP8266 is different from programming e.g. an AVR with the Arduino IDE. If you replace the while statement with:

  while(digitalRead(5)==HIGH) delay(1); 

Then it works as you would have expected. The system sits doing nothing until pin 5 goes LOW. So it looks like "delay" is the solution. Before we added it your code was "doing nothing" - and it crashed. It doesn't take a rocket scientist to deduce then that delay cannot also be "doing nothing" therefore it must be doing something!

That something is allowing the WiFi code to run in the background, hence the WDT isn't worried.

Oddly, delay(0) would also have worked. As would the special function yield() which does pretty much the same as delay(0). delay is specifically designed to "yield" the CPU, i.e. "let go" of it for a short while, and in that short while, the WiFi code can use it.

"But Wait!" I hear you cry: "I haven't done anything with WiFi! I haven't even tried to connect to it!" - and that's true. But - look at the crash information: "T=5204" The system had been running for 5.2 seconds before it even got to the while loop. Did Serial.begin and pinMode really take 5 seconds?

If not, then what was the CPU doing for 5 seconds?

To answer that, I'd like to to actually try this experiment: don't just read it and take my word, actually do it. First - and this is vital: if you use a brand new chip or one you have used for "messing about with WiFi" then the following code might not work, You have to use a chip that you have already successfully connected to your WiFi, at least once before. When you have that, load the following sketch:

#include<ESP8266WiFi.h>

#define CSTR(x) x.c_str()
#define TXTIP(x) CSTR(x.toString())

WiFiEventHandler    gotIpEventHandler,disconnectedEventHandler;
              
void wifiEvent(WiFiEvent_t event) {
    switch(event) {
        case WIFI_EVENT_STAMODE_CONNECTED:
            Serial.printf("T=%d WiFi Connected SSID=%s\n",millis(),CSTR(WiFi.SSID()));
            break;
        case WIFI_EVENT_STAMODE_GOT_IP:
            Serial.printf("T=%d WiFi got IP %s\n",millis(),CSTR(WiFi.localIP().toString()));
            break;
        case WIFI_EVENT_STAMODE_DISCONNECTED:
            Serial.printf("T=%d WiFi lost connection\n",millis());
            break;        
        default:
            break;
    }
}

void wifiDisconnectHandler(const WiFiEventStationModeDisconnected& event){
  Serial.printf("T=%d Disconnected (reason=%d)\n",millis(),event.reason);
}

void wifiGotIPHandler(const WiFiEventStationModeGotIP& event){
  Serial.printf("T=%d Connected to %s (%s) as %s (ch: %d) hostname=%s\n",millis(),CSTR(WiFi.SSID()),TXTIP(WiFi.gatewayIP()),TXTIP(WiFi.localIP()),WiFi.channel(),CSTR(WiFi.hostname()));
}

void setup(){
  Serial.begin(74880);
  delay(1000);
  Serial.printf("T=%d Setup\n",millis());
  WiFi.onEvent(wifiEvent);
  gotIpEventHandler = WiFi.onStationModeGotIP(wifiGotIPHandler);
  disconnectedEventHandler = WiFi.onStationModeDisconnected(wifiDisconnectHandler);
  }

void loop(){
  Serial.printf("T=%d LOOP: Do something\n",millis());
  delay(30000);
}

Now then, this is where it starts to look like a magic trick: Your WiFi SSID and password are not in that sketch and there is of course, nothing up my sleeve - I do not and could not possibly know them. Even if I did, there is no WiFi.begin anywhere in the sketch that would tell the ESP8266 to connect to your WiFi. But it will connect. Go on, if you don't believe me, try it. Surprised? I hope so. Note also that the connection occured after the loop had started running - certainly on my chip it did:

⸮T=6303 Setup
T=6303 LOOP: Do something
T=8126 WiFi got IP 192.168.1.113
T=8126 Connected to LaPique (192.168.1.1) as 192.168.1.113 (ch: 6) hostname=ESP_836EDC
T=36303 LOOP: Do something

What have we learned?
  1. The ESP8266 remembers the last successful WiFi connection and automatically re-connects to it - without you even asking!
  2. It can take quite a few seconds to connect.
  3. The ESP8266 is doing a lot of things "in the background" even when you think that nothing else is happening except your code.
That last one is the one you need to think very hard about. When "your" code crashes - it might not actually be your code causing the crash, it can often be your code causing some other code to crash, which can make it hard to pin down the true cause. The whole purpose of this article is to predict that - in a large percentage of cases - there will be a delay call just before the crash, so, for my next trick:

Insert a delay(1) before the Serial.printf in wifiGotIPHandler like so:

void wifiGotIPHandler(const WiFiEventStationModeGotIP& event){
  delay(1);
  Serial.printf("T=%d Connected to %s (%s) as %s (ch: %d) hostname=%s\n",millis(),CSTR(WiFi.SSID()),TXTIP(WiFi.gatewayIP()),TXTIP(WiFi.localIP()),WiFi.channel(),CSTR(WiFi.hostname()));
}

Here's what happens on mine:

T=6302 Setup
T=6302 LOOP: Do something
T=8124 WiFi got IP 192.168.1.113
T=8124 Connected to LaPique (192.168.1.1) as 192.168.1.113 (ch: 6) hostname=ESP_836EDC

Exception (9):
epc1=0x401050b9 epc2=0x00000000 epc3=0x00000000 excvaddr=0xffffffff depc=0x00000000

ctx: sys 
sp: 3ffffdb0 end: 3fffffb0 offset: 01a0

So now what have we learned?
  1. That time travel is apparently possible: the delay(1) before the Serial.printf caused the crash (trust me, it did) yet the Serial.printf still worked! Welcome to the wonderful world of asynchronous programming...
  2. That as little as a 1ms delay can cause a crash? No,we have learned that...
  3. delay is not - after all - such a wonderful solution: when used in the "wrong" place it is a nightmare.
I see a lot of code in example sketches, in question from "newbies" that is littered with delay calls, often with values that you just know have been made up on the spot, because there is often no need for delay to be there at all. A lot of people think it's the answer to a variety of problems, but I'm here to tell them - and you - that it's the indiscriminate use of it that is the cause of many.

delay can only be called - without problems - from the "main loop thread". If you call it from the "background thread", you've seen what happens. Some callbacks (especially timers) and all interrupt service routines (ISRs) do not run - by definition - on the main loop thread, so calling delay inside them will cause problems.

We are now in a "catch-22": The best way to write code for the ESP8266 is the event-driven style, but the same method makes other code break. The solution however, is easy: don't use that "other code". Don't use delay. If you need something to happen at a later date, use a Ticker, or the author's H4 library (which adds a lot of functionality to the Ticker class) github.com/philbowles/h4

Many of the ESP8266 libraries use callbacks. If you know - in every case - whether or not it's safe to call delay in the callback, feel free to ignore everything here. But if you don't, don't. Since you can't really do anything much more productive without those libraries other than flashing LEDs, the best starting point is:

D O   N O T   C A L L   D E L A Y

Unless, of course you understand all of this already and know exactly what you are doing.