Performance issues on long prints

[stimpy2318]

After around 4.5 hours of printing a fairly complex print while running Octoprint from a Raspberry Pi 4 with 4GB of RAM, the print started stuttering. I CPU and one of the octoprint processes was using approximately 120% of a single CPU core. When I looked in the octoprint.log I found a huge number of message chunks like the following. I had the InfluxDB update interval set to 1s throughout the first 4+ hours of the print without any issues but when I found this I started turning the update interval up but even with it set to 60s the print continued to stutter badly as if octoprint couldn't get gcode to the printer fast enough. I ended up removing my influxdb server from the plugin configuration and the print started running normally again a moment later.

2020-05-02 22:29:43,405 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,411 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,418 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,431 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,444 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,444 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,445 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,449 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,452 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,463 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,467 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,468 - octoprint.plugins.influxdb - INFO - Using existing database `rosie`
2020-05-02 22:29:43,474 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,489 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,470 - octoprint.plugins.influxdb - INFO - Using existing database `rosie`
2020-05-02 22:29:43,490 - octoprint.plugins.influxdb - INFO - Using existing database `rosie`
2020-05-02 22:29:43,493 - octoprint.plugins.influxdb - INFO - Using existing database `rosie`
2020-05-02 22:29:43,491 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,499 - octoprint.plugins.influxdb - INFO - Using existing database `rosie`
2020-05-02 22:29:43,500 - octoprint.plugins.influxdb - INFO - Using existing database `rosie`
2020-05-02 22:29:43,503 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,505 - octoprint.plugins.influxdb - INFO - Using existing database `rosie`
2020-05-02 22:29:43,516 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,520 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,523 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,539 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,541 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,547 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,551 - octoprint.plugins.influxdb - INFO - connecting: database='rosie', host='hassio.local', ssl=False, use_udp=False
2020-05-02 22:29:43,559 - octoprint.plugins.influxdb - INFO - Using existing database `rosie`

[stimpy2318]

Looking through the logs more it seems as though the issue might have started occurring when octoprint had a connection hiccup while attempting to communicate to the influxdb server.

[agrif]

I'll take a look -- it looks like some timer is accidentally entering a tight loop on unexpected disconnect. My apologies for the print issues!

[stimpy2318]

Thanks for taking a look and no worries on the print issues. Fortunately most of the prints that were affected were not too large since I am still working the kinks out of my printer after a long hiatus away from it. For now I have disabled the plugin since at the time I was mostly using it to track temperature variations on the hotend to troubleshoot an issue I was having. Turns out the thermistor wire was loose so that issue is now resolved and I don't currently have a huge need for long term temp recording for now.

[agrif]

So, I wasn't able to figure out how this happened, but I added a preventative measure so if it happens again it shouldn't hurt anything. From now on, if the plugin loses connection to the database, it will only try to reconnect once every 10 seconds, rather than hundreds of times per second.

If you want to give it a try, this change has been included in 1.3.0.