Printer freezes or stutters when loading web interface, results in artefacts

[thedoble]

What were you doing?

Loading the OctoPrint web interface

What did you expect to happen?

The print to continue normally

What happened instead?

My printer stops for a few seconds, stutters ... and then keeps printing normally.

Branch & Commit or Version of OctoPrint

Version: 1.2.9 (master branch)

Printer model & used firmware incl. version

Rostock MAX V2, Repetier 0.91

Browser and Version of Browser, Operating System running Browser

Firefox 43.0.1, Windows 7 Pro x64
Problem also occurs when accessing from Safari on iPhone

Link to octoprint.log

https://dl.dropboxusercontent.com/u/908196/octoprint.log

Link to contents of terminal tab or serial.log

Excerpt from a stutter when loading the web interface:

Recv: ok 884
Send: N885 G1 X8.493 Y9.059 E152.8347_90
Recv: ok 885
Send: N886 G1 X-9.625 Y-9.059 E154.2554_95
Recv: wait
Send: N887 G1 X-10.190 Y-9.059 E154.2868_109
Recv: wait
Send: N888 M105_47
Recv: ok 886
Send: N889 G1 X7.928 Y9.059 E155.7075*94

Link to contents of Javascript console in the browser

http://pastebin.com/FmT6nzST

Screenshot(s) showing the problem:

This picture shows a print artifact (gap in print) which was caused due to a particularly long 'freeze' of the printer (around 5 seconds) - most of the time when the freeze occurs, a blob is left by the printer as the print head stops moving but plastic oozes out.

https://www.dropbox.com/s/o57mphukbpz9a98/Photo%2024-02-2016%2C%205%2043%2052%20PM.jpg?dl=0

I have read the FAQ.
I was directed here by the OctoPi team - guysoft/OctoPi#197

Thanks

[foosel]

I see it's trying (And weirdly enough failing) to delete time lapse data there in the log. Now, this is only a hunch but: did this also happen with 1.2.8? And if not (our you don't know) could you please try deleting/moving the existing time lapse files, so it doesn't have to fetch those from disk on a reload and see if it makes a difference in behaviour?

Easiest way on OctoPi would be to log in via ssh and do this:

sudo service octoprint stop
cd ~./octoprint
mv timelapse timelapse.bck
sudo service octoprint start

That will move the existing time lapse data top a new backup folder, so the data is safe but OctoPrint doesn't care about it. Then try to reproduce the issue and report back.

You can get your timelapse data back to the right location with

sudo service octoprint stop
cd ~./octoprint
mv timelapse timelapse.new
mv timelapse.bck timelapse
mv timelapse.new/*.mpg timelapse 
rm -r timelapse.new
sudo service octoprint start

Or, if you didn't do time lapses during the test or don't need to keep them

sudo service octoprint stop
cd ~./octoprint
rm -r timelapse
mv timelapse.bck timelapse
sudo service octoprint start

[thedoble]

Thanks for your reply.

Yes this did happen with 1.2.8 as well.

I'll try moving the existing timelapse data as you say, I'm halfway through a print now so will do it tomorrow.

[thedoble]

I found that after moving the timelapse data, the printer did not stutter in my testing during the first 30 minutes of the print.

I have just tested again (8 hours into print) and the printer is back to stuttering when loading the interface :(

[ntoff]

Maybe your SD card is too slow so while it's trying to read the UI data and write the timelapse footage at the same time the card is getting bogged down? Try making an image of your SD card and duplicating it to another known to be good quality card.

[thedoble]

Hi

The SD card is a Sandisk Class 10 Ultra 16gb. The timelapse files are around 200kb and are only written every 30 seconds, I doubt this would cause the SD card to bog down?

I have loaded up iotop on the Raspi and will do some testing to confirm this.

[Loup911]

it happened to me the same thing.
During printing if I reload the web page of my print server I notice the processuce octoprint take 100% of the assigned CPU

I'am wits a raspberry pi 2B with 4 core

I think the solution might lie in separating the serial and web in 2 difent process. so they used a diferent process and could be assigned a diferent CPU.

I do not know if linux can assign priority level of the process. If so would require serial communication is in high priority over the web interface.

[markwal]

Since I don't have this difficulty with either RPi 2 nor 3 and the CPU is not heavily loaded in either case, I doubt it is CPU. It's either different add-on hardware (SD card, wi-fi dongle, etc.) or some other software installed or busy doing something that mine is not (like deleting old timelapses, searching through old gcode files updating analytics and stats).

[Loup911]

[Loup911]

printing job runing and updating the web page of octoprint server

may be some plugin!

[gddeen]

Hmmmm...

I stopped doing time lapses, and changed the port speed to 250K to the printer and keep my laptop connected and try to never watch a print.... (I waited for RPI3, but gave it away to daughter. Less stressful than watching prints.)

[markwal]

Huh. It is the CPU.

[Loup911]

I think to use a different application to manage the serial communication and the website could be an advantage.

Using one application that handles serial interface only, it would be easier to manage more than one printer with the same server.

What do you think?

[Loup911]

Currently I have three computer watching the video stream in real time and mjpg_streamer consumes 7 to 20% of the cpu, and it never Is the same cpu which is used by octoprint.

During assembly of the video file I have one of my cpu saturated at 100% and I print in the same time and have my video feed open on 1 computer. And the printing did not freezes

[gddeen]

I don't think that would fix it. (Random guess) If it's a bottleneck problem because of some locked resource, spreading it to two processes won't unlock the resource. It may complicate the discovery of a solution. I traced mine down to a timer and file io, then got rid of time-lapse. I replaced my SD card. I moved to a RPI2B (from dual core 64bit). I upgraded to a better video camera. I got rid of video camera. I shielded all cables and put ground planes beneath the boards. I added ferrite cores around wiring onto the board. I had a lot of fun... (I didn't really spend any time LOOKING for the problem...)

[ntoff]

I just tried on my pi2b and I got a spike of 27% for CPU usage though I don't have timelapse turned on. Once open though it settles down to about 1.6 - 5%

[theturtle32]

I have the same problem. I'm running OctoPrint 1.2.10 on a dedicated RasPi 2 Model B, connected with ethernet. Nothing connected except the 3d printer and the network cable. Nothing else installed and running. I have to be very careful not to load/reload the OctoPrint web interface after a print has started or it will ruin the print.

Every time the Web UI is loaded, it pegs one core at 100% for about 10-15 seconds, during which time the printer's buffer starves out. The flow of G-Code from the pi slows to a crawl, and the print head will be mostly stopped but will stutter a little bit here and there until the web UI finishes loading, at which point the print resumes full speed.

I don't have (and never did have) a webcam connected, and my timelapse directory is empty.
I do have 369MiB of data in the uploads folder, however. Does it scan through everything in that folder when serving the web UI?

[markwal]

@theturtle32 It will do a complete tree on the uploads folder in order to deliver the file list to the web UI. The operation should be on the order of the number of items in the folder not so much the size. It will also read a history yaml file containing information about the duration of the last print or whether it was successful or not.

[chaseacton]

+1

I am not using the time lapse feature, but I do have a camera attached. This is on a Pi 2.

[LunNova]

I'm having the same problem on a Pi 2. Time lapse is usually enabled with per-layer, but I tried turning it off and it still happens.

Are there any diagnostics or logs I can provide to help diagnose this?

[rincewind0803]

Im getting the same effect lately since the last update to 1.2.15.
But i never experienced this behavior before.
Steps to Reproduce:
-Start print Job ( with timelapse)
-Close Browser (Firefox/Archlinux)
-Open Octoprint in new Browser
Printer completely stops, Print interface unresponsive.
https://www.dropbox.com/s/9li39b11esgcf76/octoprint.log?dl=0
It does not happen if i leave the Browser open or do not reopen a new Window. I can watch printing progress with the octodroid app that does not make the printer stop.

[thedoble]

I thought I would post here again, I had stopped using Octoprint because of this issue causing blobs in my prints. I've recently started using it again, and have updated to v1.2.15

I have disconnected my USB cameras completely, so there is no longer any additional CPU use, and there is no timelapse being done.

As mentioned by @rincewind0803 the printer will stutter or freeze completely for 3-6 seconds when loading the web interface.

Thanks

[rincewind0803]

After further investigation it may rahter be a raspbian problem.
I switched to RepetierHost Sever for a print Job today and this one also stopped printing after reopening in Browser. SSH Connektion was alive and Pi was responsive but Repetier Server was killed.
I remember updating debian for the first time in months the same day I updated to 1.2.15.
I`ll post al list of packages updated if someone is interested.

[rincewind0803]

Things are getting misterious: I downloaded a new image no plugins and upgraded the hardware to a brand new Pi 3, only made the 1.2.15 update and getting trouble again.

[luke321]

I got the same problem with 100% CPU usage on 3 differernt Pi 2. I think it started with version 1.2.7.
The printer does not get enough Gcode lines an stutters or even stops in place for a few seconds.
Currently I use the telegram plugin to check the status of the printer.

[foosel]

Since I haven't seen this behaviour myself yet but it was already pointed out that OctoPrint will scan your upload folder when loading the file list via the API (which is part of what happens during a reload): how many files are people experiencing this have in there? And the same question for the timekeeper folder.

[luke321]

Actually my problem was caused by the history plugin. Probably because of the long list of prints loading each time.
I never had more than 4 files in the upload folder, no camera and no timelapse videos.
I will reinstall the history plugin and double check if the stuttering comes back and than post an issue in the plugin repo.

[LunNova]

Probably encountering the same issue here. I keep the uploaded files clean (currently 2 .gcodes there), but have hundreds of past jobs recorded by the history plugin.

edit: Yep, the request which takes longest on a page load when it freezes is to /history...

[foosel]

Yikes. That definitely looks like a likely culprit then. The login request probably takes so long because the server is blocked by the history request from just before it, that's just a wild guess right now.

Some proper caching headers on the history plugin's resource might already help tremendously here.

Meanwhile I'm also looking into some better cache handling on the API's of OctoPrint itself, to reduce overhead here.

[LunNova]

Is it possible to have a separate process for communicating with the printer? Doing it in its own thread should be fine, but python still has the damn global interpreter lock so that doesn't actually work.

I understand it's likely to involve a lot of work, but it's probably the only way to avoid occasional reports from users of serial pauses in the long run.

In terms of just fixing the history plugin: It should set caching headers, as you've pointed out. It could also time.sleep(0) in the large loops it's doing, which would yield and allow serial communication to happen in the middle of it. maybe?

[burner-]

I find one problem with MK4duo. If printer is connected via non native usb port it will do many kind stupid things. My freezing and shuttering problems went away when I move octopi communicate via native usb port.

[xaqaria]

I've noticed this off and on for some time. I am about to move from a Raspberry Pi 3B to 3B+ and thought I would try to resolve. Details are below, but as I was capturing the data I'm also noticing the UNDER VOLTAGE alert I don't remember seeing before.

Let me address the alert before you do any work with this feedback.

Video link wouldn't work in code section:
Video

#### What were you doing?
1.  Started a print
2.  Waited for print head to begin moving
3.  Logged on to the http://octopi page
4.  Printer started to stutter

#### What did you expect to happen?
Printer wouldn't stutter

#### What happened instead?
Printer stutters

#### Did the same happen when running OctoPrint in safe mode?
* occurred
* uninstalled disabled plugins and it occurred
* ran in safe mode and it occurred


#### Version of OctoPrint
1.3.11

#### Operating System running OctoPrint
Octopi 0.15.1 - octopi 4.14.34-v7+ #1110 SMP Mon Apr 16 15:18:51 BST 2018 armv7l GNU/Linux

#### Printer model & used firmware incl. version
Ultimaker 2+  fw 2.6.2


#### Browser and version of browser, operating system running browser
Windows 10 1903
Chrome 76.0.3809.100
Firefox 68.0.2 

#### Link to octoprint.log
https://gist.github.com/xaqaria/1c5f4eb163be8ed22a4f4ceee3ce3f87

#### Link to contents of terminal tab or serial.log
https://gist.github.com/xaqaria/678893c0cd7b63a7fdda38a9a9655f1e

#### Link to contents of Javascript console in the browser
Not available

#### Screenshot(s)/video(s) showing the problem:

[Video](https://photos.google.com/share/AF1QipNCj58Q4HmHu6N9idjc59pp8QTJdTGDiGqCMGVFePCHmrB9CnkYp1hKW5CQZK6q7Q/photo/AF1QipMu871lwm8h08kPmfw_9asQCGhqcP02isGJeIIq?key=TlJ2VnFBQ2pmUVVSTTBMVW9uT1VnWWVvbUJLX3NB)

update: addressing video link

[xaqaria]

I've addressed the Under Voltage and it didn't address the issue for me. From there I've tried the following to no avail:

• Timelapse disabled
• MJPG Streamer set to:
  • 1920x1080@30fps
  • 1280x720@30fps
  • 1280x720@15fps
• webcamdaemon disabled/camera unplugged

[thedoble]

Have you tried deleting your job history? Have you tried removing all other files from file list?

…

On Tue., 20 Aug. 2019, 1:54 pm Jason McSorley, ***@***.***> wrote: I've addressed the Under Voltage and it didn't address the issue for me. From there I've tried the following to no avail: - Timelapse disabled - MJPG Streamer set to: - ***@***.*** - ***@***.*** - ***@***.*** - webcamdaemon disabled/camera unplugged — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#1241>, or mute the thread <https://github.com/notifications/unsubscribe-auth/ADSB7AVSCHHEQJGZS4KSRPLQFNTITANCNFSM4B4FWWEA> .

[xaqaria]

@thedoble I think you may have hit on something. I need to turn everything else back on and re-test.

Adding a single browser does load a lot faster and it doesn't trigger the stutter. I could get it to stutter by quickly logging in two different browsers at the same time, but it was a lot shorter.

[justfalter]

I don't really understand why a hard browser refresh (Ctrl-Shift-R - leading to a request with Cache-Control: no-cache) should be tied to the OctoPrint service refreshing its caches. Typically, a request with Cache-Control: no-cache would cause intermediate proxies to invalidate their caches, but not the application server's caches. Why would OctoPrint ever need to invalidate its internal
caches outside of development?

In my opinion, the refreshing of OctoPrint's internal caches should not be tied to a browser refresh, perhaps it should be be a separate REST API endpoint?
At the very least, priority should always go to an in-progress print-job. Perhaps OctoPrint should refuse to do a refresh if a print is in progress?

[justfalter]

@foosel Do you have any thoughts on the above? It is trivial for a user to cause OctoPrint to refresh its caches with a hard-refresh of their browser. On raspberry pi hardware, this can lead to several seconds of CPU spikes that negatively affect an in-progress print.

[foosel]

Happy to accept the above PR if the backwards compatibility issue is solved (trivial change).

[RobeeeJay]

Hi! Love OP, thanks for all your work Foosel!

I am having random rare problems which are OP CPU related on my Prusa Mini, and after disabling various plugins, thinking this was all sorts of other reasons and eliminating them, I am now suspecting this is the same issue.

When this happens, on my Pi 3 B+, OctoPrint consumes 30% of the CPU, and it is not keeping up with providing Gcode to the printer. At it's worst it leaves all sorts of artifacts on the model I'm printing and can make a print which is due to finish in 10 minutes not finish for over an hour.

I think this might be related when I'm using Safari to monitor the print, and maybe it's quite aggressive at suspending tabs when I task switch.

Does this attached octoprint log look normal? When this happened I only had one browser open talking to OctoPrint, and only one tab. Webcam was off, Octolapse was off, Display Layer Progress was off.

octoprint.log

[Phil1988]

I am having the same issue since always :D

I never knew that this is not normal.
It's surprising to me, that this is actually preventable and I will do further research on this.

@foosel :
You mentioned that disableing the plugins by using safe mode might avoid that.
I will check this for sure in the next days and give you a feedback, but before that, I would like to see/get as much information as possible.
This way I want to make sure, that I identify my problem and give you (all) as much benefit from it as possible.
Hopefully this might help others to and get the source of the problem.
I read that the "history" plugin might be a good candidate for this issue.

To give you a short overview about my setup:
I am using this instance of Octopi for quite a long time with a lot of plugins installed.
I'm printing from octoprint directly (no SD card).
So I am having multiple files (really a lot) uploaded.
There might be a lot in the history as well ;)
I am also using basic auth. This is typically not used in a wide field of users.

How can I check the plugins load and time needed?
"top" is very limited and "hto"p also ony shows this after hitting F5:

@nallar : You have a nice graphic for that.
Can you or anyone else tell me how to get a great view like that?

EDIT:
CPU load during a fast (real 85mm/s) 3D print, with a round shape (=> many commands for the curves):

EDIT 2:
This is my timeline:

(For anyone interested, this is made by the google chrome development tools under network)

Needed 15.02s to finish the request.

EDIT 3:
reloaded with save mode:

13,29s (can be measuring inaccuracy)

EDIT 4:
after deleting all (2.08GB) if timelapses:

13,96s
still not really a change...

EDIT 5:
Ok! now we have something.
After deleting 498 uploaded .gcode-files:

4.43s

EDIT 6:
safe mode now turned off and sorted by response time:

7.16s is definetly an improvement.

I will test tomorrow if the stuttering appears again while printing and report back.

[foosel]

How can I check the plugins load and time needed?

You currently can't. There are now debugging tools or anything. You can use the web dev console as you already noticed, and you can use https://docs.octoprint.org/en/master/development/request-profiling.html but that's about it at the moment (as always, contributions welcome).

What I find weird here is that it loads the file list completely fresh. That is one of the most heavily cached endpoints precisely to avoid issues like this, so if it isn't properly caching here, the question is why. Will take a look.

[RobeeeJay]

Would it be difficult to add a simple timer whenever OctoPrint calls a plugin and if it takes over 100ms it logs the name of the plugin with warning? That might help locate the cause easier. I'm not sure how many places plugins are called regularly during printing, but if it's not that many I could try this.

if it was useful, it could also be extended to the UI alerting users that a plugin is consuming too many resources and give them the option to ignore the warning or disable the plugin.

[foosel]

Would it be difficult to add a simple timer whenever OctoPrint calls a plugin and if it takes over 100ms it logs the name of the plugin with warning?

Not difficult per se, but there's a ton of places where hooks and implementations are used, potentially even in other plugins, so that would become quite a lot of places that would need wrappers, some of which might even be tricky to pull off. I think it might be time to look into something like this however as it certainly would help debugging performance issues.

Meanwhile I've discovered an issue with the caching header evaluation that led to the cache for e.g. the files api endpoint not working as intended. The internal files cache still worked, but the response to the files request always had to be processed instead of just returning 304, which might explain some performance issues. Mind you, that only affects situations where you load the UI again in the same browser, not when you fire up a completely fresh browser with a clean history.

[foosel]

some of which might even be tricky to pull off

Strike this, I just had an idea, will see I can get that to work centrally in the plugin core.

[foosel]

So, OctoPrint 1.5.0 will ship with a new debug option, the plugintimings.log:

Enabling this will create a plugintimings.log in your log folder that contains stuff like this:

2020-09-30 13:50:23,434 - octoprint.plugins.action_command_prompt.ActionCommandPromptPlugin.on_event - 00.00ms
2020-09-30 13:50:23,442 - octoprint.plugins.announcements.AnnouncementPlugin.on_event - 00.00ms
2020-09-30 13:50:23,443 - octoprint_file_check.FileCheckPlugin.on_event - 00.00ms
2020-09-30 13:50:23,443 - octoprint_firmware_check.FirmwareCheckPlugin.on_event - 00.00ms
2020-09-30 13:50:23,443 - octoprint.plugins.pluginmanager.PluginManagerPlugin.on_event - 00.00ms
2020-09-30 13:50:23,443 - octoprint.plugins.softwareupdate.SoftwareUpdatePlugin.on_event - 00.00ms
2020-09-30 13:50:23,444 - octoprint.plugins.tracking.TrackingPlugin.on_event - 00.00ms
2020-09-30 13:50:23,444 - octoprint_firmwareupdater.FirmwareupdaterPlugin.on_event - 00.00ms
2020-09-30 13:50:23,444 - octoprint_z_probe_offset.Z_probe_offset_plugin.on_event - 00.00ms
2020-09-30 13:50:23,446 - octoprint.plugins.backup.BackupPlugin.socket_emit_hook - 00.00ms
2020-09-30 13:50:23,448 - octoprint.plugins.action_command_notification.ActionCommandNotificationPlugin.on_event - 00.00ms
2020-09-30 13:50:23,474 - octoprint.plugins.action_command_prompt.ActionCommandPromptPlugin.on_event - 00.00ms
2020-09-30 13:50:23,492 - octoprint.plugins.backup.BackupPlugin.socket_emit_hook - 00.00ms
2020-09-30 13:50:23,493 - octoprint.plugins.announcements.AnnouncementPlugin.on_event - 00.00ms
2020-09-30 13:50:23,533 - octoprint_file_check.FileCheckPlugin.on_event - 00.00ms
2020-09-30 13:50:23,534 - octoprint_firmware_check.FirmwareCheckPlugin.on_event - 00.00ms
2020-09-30 13:50:23,560 - octoprint.plugins.pluginmanager.PluginManagerPlugin.on_event - 00.00ms
2020-09-30 13:50:23,566 - octoprint.plugins.softwareupdate.SoftwareUpdatePlugin.on_event - 00.00ms
2020-09-30 13:50:23,567 - octoprint.plugins.tracking.TrackingPlugin.on_event - 00.00ms
2020-09-30 13:50:23,578 - octoprint_firmwareupdater.FirmwareupdaterPlugin.on_event - 00.00ms

It will also create a plugintimings.csv file at the same location:

2020-09-30 13:55:06,019;octoprint.plugins.tracking.TrackingPlugin.on_event;0.000000
2020-09-30 13:55:06,019;octoprint_firmwareupdater.FirmwareupdaterPlugin.on_event;0.000000
2020-09-30 13:55:06,019;octoprint_z_probe_offset.Z_probe_offset_plugin.on_event;0.000000
2020-09-30 13:55:07,485;octoprint.plugins.backup.BackupPlugin.socket_emit_hook;0.000000
2020-09-30 13:55:07,488;octoprint.plugins.backup.BackupPlugin.socket_emit_hook;0.000000
2020-09-30 13:55:07,489;octoprint.plugins.action_command_notification.ActionCommandNotificationPlugin.on_event;0.000000
2020-09-30 13:55:07,490;octoprint.plugins.action_command_prompt.ActionCommandPromptPlugin.on_event;0.000000
2020-09-30 13:55:07,490;octoprint.plugins.announcements.AnnouncementPlugin.on_event;0.000000
2020-09-30 13:55:07,491;octoprint_file_check.FileCheckPlugin.on_event;0.000000
2020-09-30 13:55:07,491;octoprint_firmware_check.FirmwareCheckPlugin.on_event;0.000000
2020-09-30 13:55:07,491;octoprint.plugins.pluginmanager.PluginManagerPlugin.on_event;0.000000
2020-09-30 13:55:07,491;octoprint.plugins.softwareupdate.SoftwareUpdatePlugin.on_event;0.000000
2020-09-30 13:55:07,491;octoprint.plugins.tracking.TrackingPlugin.on_event;0.000000
2020-09-30 13:55:07,491;octoprint_firmwareupdater.FirmwareupdaterPlugin.on_event;0.000000
2020-09-30 13:55:07,492;octoprint_z_probe_offset.Z_probe_offset_plugin.on_event;0.000000
2020-09-30 13:55:07,615;octoprint.plugins.backup.BackupPlugin.socket_emit_hook;0.000000
2020-09-30 13:55:07,615;octoprint.plugins.action_command_notification.ActionCommandNotificationPlugin.on_event;0.000000
2020-09-30 13:55:07,616;octoprint.plugins.action_command_prompt.ActionCommandPromptPlugin.on_event;0.000000
2020-09-30 13:55:07,616;octoprint.plugins.announcements.AnnouncementPlugin.on_event;0.000000

Both are rotated on server start. They log A LOT, so this should really only be enabled when actively hunting performance issues. Consequently there's also a navbar icon visible if it's enabled.

Should be available on the maintenance branch as of now.

[RobeeeJay]

Wow that was really quick! Thank you for this!!! You're the best!