Thermal runaway - monitor temperature variance

[zeleps]

There has been a number of reports on an issue (#20749) regarding temperature readings that get stuck while heaters remain on. I've noticed the same issue twice on my rig in the past, but I've moved on to a MAX31865 sensor and the issue has not appeared since.

It seems that the issue appears on SKR boards, and it might be related to interrupts being disabled at some point, which is the only obvious explanation to why thermistor values stop updating. Probably affects watchdog as well, since it never fires up. Since it hasn't occurred on my printer after I started using the MAX31865, it sounds like it has to do with the ISR (MAX31865 readings are independent of the ISR). This is a difficult bug to reproduce, and also a serious fire hazard, because heaters continue heating indefinitely.

I came up with this solution, after a request by @pillopaolo to implement a mechanism that would trigger a thermal runaway kill. The feature is built inside the thermal protection mechanism, and it's only active during the stable heating phase on all thermally protected heaters, which ensures that there will be a temperature fluctuation due to PID / bangbang. Also, it seemed ok to use the same detection window as TEMP_PERIOD, which is an acceptable time window for thermal runaway defined for each heater. Takes BOGUS_TEMPERATURE_GRACE_PERIOD under consideration, so _temp_error() persists until temperature starts varying or kill() occurs.

I've tested this with timed disablement of the temperature raw value updates (and it works fine), but I can't reproduce the original issue, so it remains to be seen if my solution will work when it occurs.

I strongly suggest that it is enabled by default, better safe than sorry.

Requirements

Thermal protection must be enabled.

Benefits

Detection of potential fire hazard. Will probably help to pinpoint the original issue, especially if some related state data is written to the serial prior to killing (I leave this to someone more engaged with the project).

Configurations

Any THERMAL_PROTECTION setting will do.

Related Issues

#20749

[pillopaolo]

Thanks John for quick response to this safety issue.
A) In temperature.cpp, lines 2586-2586 seem doing nothing, probably a leftover?
B) I did not spend much time in checking, however from a quick look I do not understand the purpose of lines 2574-2584: as soon as state=TRTempNotUpdating (line 2645), an error is triggered (line 2668), so I expect 2574-2584 is never used. Besides, lots of lines in 2574-2584 seem a repetition of code 2635-2652. Do not spend time is explaining, just want to be sure you did not leave lines 2574-2584 there by mistake.

[zeleps]

Hey @pillopaolo,

1. 2585-2586 is there to keep the code structure simple, since I didn't want to wrap 2590-2604 into another -optional- block, which would be harder to read. The empty block may also be used to insert debugging code to log information about the system state. Obviously open to suggestions on this one.

2. When BOGUS_TEMPERATURE_GRACE_PERIOD is used (see 1044-1059), _temp_error() will not kill the printer at first error. It will turn heaters off at first invocation (effectively saving the day), but the temperature updating issue most probably remains. And while it remains, invoking _temp_error() multiple times will eventually lead to depletion of BOGUS_TEMPERATURE_GRACE_PERIOD and an actual stop will occur. Note that this cannot be done from within the case statement, since the initial call to _temp_error() turns heaters off, so the next TR state will be TRInactive, effectively cancelling the variance check, stopping all error triggering, and leaving the machine cooling down but without proper temperature updating.

[zeleps]

I can't help but think that this issue is caused by a hardware bug. The only conditions that can effectively lead to the issue you (and others) are experiencing, is that:

1. ISR has stopped working
2. Watchdog timer has also stopped working (or perhaps is being refreshed by some other process but I can't really figure that out).

That's why I asked what kind of sensor you're using, since only thermistor-based sensors are updated by the ISR. If you look at the first post in #20749 by @zenturacp, all temp sensors stop updating, not just the active hotend. This most probably means that update_raw_temperatures() (temperature.cpp@2943) is not being invoked anymore. I can't find a code path that may lead to this situation, unless the 2 conditions I mentioned above are true. Since hw serial communication seems to trigger the issue (Octoprint, TFTs), a hw interrupt problem sounds probable. Especially since all reports so far are about SKR boards.

[dkmaker]

Yeah sure - can be a hardware bug - the odd thing was mine was both as you mentioned..

The wierd thing was it was the exact same GCODE file every time..

Have never seen it since..

Now I'm running klipper and have never tried the issue on klipper not even the same GCODE file so something tells me it can be software or Klipper handling hardware different

[robbycandra]

What about using counter that always increase when Temperature::isr() called?

We will know if the Temp Timer stop by compare previous counter vs current counter.

[zeleps]

Yeah, an ISR counter (or even better, millis() since last invocation) is most probably an important debug info to log to the serial once we detect the problem. I don't want to assume what the cause is and what debug info would be useful to log, I'll leave that to @thinkyhead or someone more involved than I am.

[pillopaolo]

What if ISR is called, but not properly executed? Or the HW fails to report the temperature for some reasons (issue with temperature sensor, digital input, etc.).
I still think that the "freeze" test implemented by @zeleps is more robust and applicable to other situations too.

[dkmaker]

I did add an external monitor to that got a connection to Octoprint and monitored the divination on temperature if it is 0 in 1 or 2 minutes somthing is really not updated - no pid is 100% stable in that way my watchdog does not at all rely on anything..

[zeleps]

@zenturacp that's actually a nice idea for an Octoprint plugin, which would do firmware-independent and detailed cross-check of various vitals.

[pillopaolo]

BTW, the "freeze" test implemented by @zeleps would also cope with another fire issue I had in the past, for other reasons, as documented in #17327

[robbycandra]

What if ISR is called, but not properly executed? Or the HW fails to report the temperature for some reasons (issue with temperature sensor, digital input, etc.).

If the ISR is running but not executing properly, then the problem may be in analogRead().
It feels like a hardware error. And the trigger is probably in the process of reading the USB input. Just guessing.

[robbycandra]

Yeah, an ISR counter (or even better, millis() since last invocation) is most probably an important debug info to log to the serial once we detect the problem. I don't want to assume what the cause is and what debug info would be useful to log, I'll leave that to @thinkyhead or someone more involved than I am.

We can use both methods. Check temperature variance and isr counter at once.

[zeleps]

ISR is a time-sensitive routine, I'd rather leave this decision to @thinkyhead.

[pillopaolo]

My point is:

What if ISR is called, but not properly executed? Or the HW fails to report the temperature for some reasons (issue with temperature sensor, digital input, etc.).

If the ISR is running but not executing properly, then the problem may be in analogRead(). It feels like a hardware error. And the trigger is probably in the process of reading the USB input. Just guessing.

I am just trying to say that, no matter what the cause is (ISR, analogRead(), temperature capped by the thermistor table as in my previous incident #17327, etc.), the "freeze" test would reliably detect the issue. This is what I mean with being a ROBUST solution to this and other potential future issues.

[thinkyhead]

capped by the thermistor table

I believe it was originally intended for the thermistor tables to have "crazy" values at the start and end so that any readings outside the expected range would produce an obvious error. (See thermistor11.h) But not all thermistor tables are set up to do this.

[pillopaolo]

capped by the thermistor table

I believe it was originally intended for the thermistor tables to have "crazy" values at the start and end so that any readings outside the expected range would produce an obvious error. (See thermistor11.h) But not all thermistor tables are set up to do this.

As far as I remember, no matter how the table was made, temperature.cpp in past Marlin versions (e.g. Marlin 1.1.8 Jun-2018, as described in #17327) used to do an extrapolation above the max temperature value found in the table. Then in later versions (e.g. Marlin 2.0 Mar-2020) this extrapolation was removed and the temperature value capped = max temperature in table, very dangerous. Not sure how temperature.cpp is now, I did not check. In the past 2 years I simply modified thermistor1.h and added a "crazy" value as in thermistor11.h.
Anyway, with this new super VarianceDetection test we should be safe.
Thanks for being so fast in accepting @zeleps improvement, Safety First!

[zeleps]

@pillopaolo after your recent incident report, I felt unsafe too (you know, long, unattended prints...). Also, had some free time to kill. So yeah, it was a pretty selfish act ;)

Have a happy and prosperous new year, everyone!

[zeleps]

I understand that. Thank you for taking the time (and risk) to test it, let's hope it'll lead us somewhere.

[CBDesignS]

Dont know if I can add anything here but I have just jumped from 2.0.9.2 (that is working perfect) on an MKS Sgen-L v1 LPC1768 board up to the latest 2.0.9.3 and I get thermal errors every time I try to print. Pid tune on he0 & he1 both work as they should and I can set the bed to 80c and it will stay within 0.5c either side of the set temp for hour upon hour of testing, as soon as I ask the machine to print anything up to 1min into the print it errors out with
Error:Thermal Malfunction, system stopped! Heater_ID: bed
N149 M108*38
echo:TEMP MALFUNCTION

The only way to get this to stop is by uncommenting #define THERMAL_PROTECTION_VARIANCE_MONITOR or to bump up
#define WATCH_TEMP_PERIOD 40. #define THERMAL_PROTECTION_BED_PERIOD 40. #define WATCH_BED_TEMP_PERIOD 90

I have a few partial logs if they might be of any use to anyone
partial-logs.zip

with the logs you can see the temps are stable and moving a few .x degrees up and down so no readings seem to be stuck as per some of the above posts. and just as I type it`s gone and threw the error out mid print... back to 2.0.9.2 again.

[zeleps]

@CBDesignS your temperatures are exceptionally stable (that's amazing btw, what kind of bed / sensor are you using?). Either increase THERMAL_PROTECTION_PERIOD and THERMAL_PROTECTION_BED_PERIOD to 60 and 120 respectively (these are safe values, there is no way a bed can heat up dangerously in 120'', and 40'' seems to be too low for you). WATCH_*_TEMP_PERIOD has nothing to do with temperature malfunction. What type of sensor are you using btw?

[pillopaolo]

@zeleps I see a potential problem: if the T variation is < of the ADC resolution, the VARIANCE test might give a false positive. Especially with older boards (10 Bit = 1024 points).
Especially at higher temperatures, where the curve is steeper and therefore the resolution is lower, i.e. you have a wider temperature range within 2 ADC contiguous values.
Or am I wrong?

[zeleps]

@pillopaolo you can't auto-tune a PID system so well (as to have such temperature stability that remains invariant for a long time) on such a coarse temperature resolution. If you see @CBDesignS logs, you'll notice that the bed has a resolution of 0.04°C, which is quite high res (probably a 15bit ADC). The temperature seems extremely stable, but still there are minor fluctuations, it's just that there isn't any in a given 40'' window. I can't imagine how a hotbed can keep the temperature stable to within 0.04°C for 120''.

There should probably be some more details in the comments of THERMAL_PROTECTION_VARIANCE_MONITOR about it's working and tuning. @CBDesignS case is clearly a false positive, but I think it can work if periods are bumped up sufficiently (within a safe range, of course). Also, if the problem occurs even after setting higher values for the thermal protection periods, THERMAL_PROTECTION_VARIANCE_MONITOR can always be disabled.

[CBDesignS]

@zelps The heated bed is a standard 12v creality 310x310 bed & 4mm creality glass build plate and as far as I know its a 100k ntc thermistor set as ( 1 : 100kΩ EPCOS - Best choice for EPCOS thermistors). It is powered by its own 30A 12v psu & I removed the cheap ass creality foam insulation from the bottom and replaced it by a custom made "sheeps wool insulation pad" that holds the temperature . Up until this PR I have never had to change any thermal settings as the defaults worked out of the box and still do work in 2.0.9.2. I will make a couple of changes to THERMAL_PROTECTION_PERIOD 60 and THERMAL_PROTECTION_BED_PERIOD 120 as you suggested to see if that helps.

[zeleps]

Since this is a false positive issue, it proves an important point: nothing is obvious. Your case is a bit extreme (absolutely stable bed temp for 40''? give me a break...), but shows that this new feature should be pre-configured better if it's going to be turned on by default, otherwise it's destabilizing the system. I'll come up with something and return.

Just our of curiosity, did you try preheating hotend / bed (without a print) for a while? If yes, how come it didn't crash? Thermal protection is running regardless of printing, and just having heaters on for a while should have the same result.

[CBDesignS]

I never pre heated the bed or extruder as I was that use to just asking it to print and off it went. I could set a temperature on the bed and off it would go quite happy and get up to temp and sit there for hours. The longest pid tune of the bed I used was 9 cycles and it passed every time.
As I changed settings each time & flashed the firmware back I reset eeprom and pid tuned etc as you should (to rule out corrupt data in the eeprom). It only seemed to happen once the print was started, heat to bed & extruder with movement with extrusion.

Setting THERMAL_PROTECTION_PERIOD 60 and THERMAL_PROTECTION_BED_PERIOD 120 has let me slow print a benchy in 1hr 16mins with the bed at 80c and extruder at 230c.
I have a 15hr print planned but I still do not trust this as it stands so I will have to flash the old 2.0.9.2 build back for the print but once it is done and If there are any changes that need testing I can try them if needed.

I also aggree that this has to be stable if turned on by default because every tom dick and harry will start flooding git,fb,reddit etc screaming that marlin has broken their printer and want it fixed because they need to print this weeks random tiktok sponsored articulating toy.. (and to save elensp or tinkyhead having to close she loads of tickets)

Thank you Devs & knoledgable people for the help getting this going in the right direction because the more protection available the better.

[zeleps]

First of all you don't have to downgrade, just comment out THERMAL_PROTECTION_VARIANCE_MONITOR. But my opinion is that you won't be seeing the issue if you managed to print for more than an hour with 60/120''.

[CBDesignS]

@zeleps Your quote was "But my opinion is that you won't be seeing the issue if you managed to print for more than an hour with 60/120''. So since you were confident I would not have any more problems I though why not give it a try.
3 1/2 hours into the 9hr print and guess what just happened. Not the bed but the extruder this time. I never bothered with any logging either and all I have are the last few lines from Octoprint.
last-error.zip
.

[zeleps]

I'm sorry about your print, I know how frustrating it is. I'm thinking of some tweaks that would allow you to avoid disabling the feature completely, and I'll come back with a new PR for these, but for the moment it's probably best if you comment out THERMAL_PROTECTION_VARIANCE_MONITOR.

Please be aware that this covers a - rather rare - issue where temperatures stop updating but heaters remain powered. So far this issue has occurred in SKR1.4 boards afaik, so it probably doesn't affect you, and in any way you're not in a worse place than you were with 2.0.9.2. If you want to know more, please check the reports in issue #20749.

[CBDesignS]

@zeleps No worries. I know the risks and I had planned on staying beside the printer for the whole of the print today just incase anything did go wrong. todays print was a first print prototype part and printed in cheap ass nasty petg so nothing lost as I was doing some general tidying up work beside the printer. I have an skr 1.4 turbo board in another printer but I have never updated the firmware for years as it is rock solid. I ask it to print and off it goes.. The skr 1.4 uses an lpc1769 that is a very simmilar chip to the one on this mks Sgen L v1 that uses an lpc1768, could they share architecture and bugs between them ?

[zeleps]

I really don't know that. I don't want to assume things. We need more data on the issue, and hopefully this variance monitor will bring more cases to light.

[MakerMeik]

Hi @zeleps, as just discussed, the problem reappeared yesterday. I had already started and partially aborted prints several times. Thermal runway detections also occurred before, so I had to reset the printer manually.

However, this did not happen during a print, but only between two prints. By the way, Octoprint was running continuously, so I only reset the printer.

The actual undetected thermal runaway happened this time during the warm-up phase. So there was no print (yet).
This time the bed then became very hot, which I could fortunately detect from the smell. This time, however, the nozzle cooled down during the runaway.

Please find the attached log-files, as requested.

Octoprint-Marlin-Bug.zip

[InsanityAutomation]

Considering every log entry shows changes, it does appear to be getting a temperature update from that sensor, which is curious. Ive seen a poor connection cause similar results.

T:230.00 /230.00 B:63.02 /65.00 @:39 B@:127 W:?
2022-03-05 19:18:54,502 - Recv:  T:230.00 /230.00 B:63.15 /65.00 @:48 B@:127 W:?
2022-03-05 19:18:54,960 - Recv:  T:230.00 /230.00 B:63.10 /65.00 @:89 B@:127
2022-03-05 19:18:55,277 - Recv: echo:Thermal Runaway Running. Heater ID: 0 ; sizeof(running_temp):4 ;  State:2 ;  Timer:387820 ;  Temperature:230.00 ;  Target Temp:230.00
2022-03-05 19:18:55,463 - Recv: echo:busy: processing
2022-03-05 19:18:55,502 - Recv:  T:230.00 /230.00 B:63.19 /65.00 @:42 B@:127 W:?
2022-03-05 19:18:56,502 - Recv:  T:230.00 /230.00 B:63.27 /65.00 @:93 B@:127 W:?
2022-03-05 19:18:56,589 - Recv: Error:MAXTEMP triggered, system stopped! Heater_ID: bed

But then from here :
2022-03-05 19:25:41,582 - Recv: T:192.24 /0.00 B:62.86 /65.00 @:0 B@:127

to here :
2022-03-05 19:36:38,184 - Recv: T:192.24 /0.00 B:62.86 /65.00 @:0 B@:127 W:?

Almost 10 minutes without a change on the bed temp reading.

I see you have TMC drivers in UART mode. Im curious is the uart comms are taking priority from the temp isr as it can be a long running blocking operation. Anyone else reporting have UART or SPI stepper drivers?

[zeleps]

Ok, two things:

1. @MakerMeik It seems that you don't have THERMAL_PROTECTION_BED enabled, because I don't see any thermal runaway messages for the bed! If thermal protection is not enabled for bed, it's normal that variance detection did not halt your printer, because your heater was off when the issue occured, and variance detection only monitors active heaters. Please check to see if THERMAL_PROTECTION_BED is enabled, and if you think it is, PM me on discord later to check it out together. I'm pretty sure we'll at least manage to get the variance monitor working properly on your system, so you'll be safe from fire hazard.

2. These are the first logs we have in our hands that clearly show that no ADC values are refreshing. This is a strong hint towards ISR not working. I've prepared this commit with the latest bugfix sources, which creates three int counters, two for temp::isr() (one on each invocation and one on bed measurement state) and one for watchdog refresh. @MakerMeik, it would be great if you could flash this commit, which will clearly show what's working and what not once the issue occurs. This will also show if there are any noticeable delays in the ISR.

@InsanityAutomation, this is interesting, I'm using a UART configuration and had this issue a long time ago, but it hasn't occurred for months. The commit I'm posting here will clearly show if there are any delays in the ISR, since the counter values will be correlated to log timestamps, so let's wait and see what comes up.

[zeleps]

We had a fruitful session with @MakerMeik last night, where the problem manifested itself in all its glory. Here are the serial logs, which show temperatures stuck at 2022-03-07 21:29:18,861, without any heating taking place. Please note that the version running is this, which displays some debug info every couple of seconds.

Findings:

1. In his previous comment, @MakerMeik posted some logs that appear to bypass bed thermal protection. After examining his config files I found out he was using bang bang for bed power control. He changed this to PID and that seems to have corrected the issue. I'm not sure if it was the rarity of bed logs (once every 5sec) during bang bang which made them to not appear in the log file (to avoid flooding the serial and delaying the machine, I was only printing one out of 300 logs), or the fact that thermal protection did not work at all, since he had a temp malfunction for 10 minutes that went undetected. This needs further examination, as it might indicate an issue with thermal protection when bang bang is configured.

2. Once he flashed the new firmware, and after some initial homing etc., he tried to run M303, which failed because temperature readings had already stopped updating. This is where the issue begins:

2022-03-07 21:29:18,861 - Recv:  T:24.00 /0.00 B:24.38 /0.00 @:0 B@:0

No heaters were on at the time, so this went undetected. But this time, I had some int32 incremental counters added at 3 different points, one at the beginning of the temp ISR, one after bed ADC measuring and one at every watchdog refresh. All three counters continued increasing normally while the temperatures remained stuck, so the only possible explanation is that ADC was returning the same values for each sensor. I'm not familiar with LPC1769's ADC reading mechanism, I'll look into it later, but this is strong evidence towards a HAL issue, which might well explain why the issue occurs only on SKR boards so far.

3. The only peculiarity I found in his configuration is that he's using a dual drive Z axis, with motor driver status and sensorless homing, all these over the UART connection of the TMC2209 drivers. This may be related to what @InsanityAutomation described in the comment above. I'll create a timing graph from the collected data to see if there were any noticeable delays in the ISR.

4. All values coming from the ADC stop refreshing (not just one), so this might help improving the temperature variance monitor by checking variance globally over all ADC sensors and not on each one individually, effectively reducing (if not eliminating) false positives.

If someone's more experienced with LPC1769, it would be a great help if they could provide some insight, now that we have more data on what's working and whatnot (and we know it's not the ISR), as well as towards what to debug next. I'm pretty positive that we're close to identifying and fixing this long-standing issue.

[zeleps]

I made a graph of the first derivative of the counters over time, and this is the result:

(I scaled the values to have the graphs separated vertically)

As you can see, the ISR (blue) and bed measuring (orange) occur at very stable intervals and have some minor periodic fluctuations, while watchdog refreshes (gray) are more irregular (expected). The watchdog spike is where homing is issued (also normal). The big spike is the restart.

[zeleps]

Some new findings came up today. I gave @MakerMeik a version that prints out the whole LPC1768 ADC block, and this is what came up:

Normal operation:

ADCR: 21FF06 ADGDR: C2000C90 ADINTEN: 0 ADSTAT: 0F00 ADTRIM: 0 ADC0-7: 0, C0000C90, C000CBC0, 0, 0, 0, 0, 0

Readings get stuck:

ADCR: 21FF06 ADGDR: 0100CBB0 ADINTEN: 0 ADSTAT: 0F00 ADTRIM: 0 ADC0-7: 0, CC0, CBB0, 0, 0, 0, 0, 0

As you can see, channels 1 and 2 are 'on' (Pins 0.24, 0.25), and there is no change to the ADCR register. ADC1 and 2 contain a normal reading, but the DONE flag is not set, and they don't update anymore from that point on. Thermal malfunction occurred normally after 35''.

Here are the full logs, issue occurred at 18:05:35.

This seems to be an ADC issue. Whether it's a hardware malfunction that occurs randomly or it's triggered by something else, I can't really tell. If there's someone more experienced with LCP MCUs, it would be interesting to share their opinion on the issue.

Also, please note that the Arduino LPC library does not check "doneness" of the values on , so the fact that DONE bit (31) is 0 goes undetected by Marlin. IMHO this should be changed, and the fact that values are not ready to read for a long time should be a hard error.

Thoughts?