PrusaSlicer does not finish generating gcode in timeframe expected for resources. G-code generator torture test

[DavidUnboxed]

Version

PrusaSlicer Version: 2.1.0-rc+win64 Build: PrusaSlicer-2.1.0-rc+win64-201909041321

Operating system type + version

Operating System: Windows System Architecture: 64 bit Windows Version: Windows 10 (build 18362), 64-bit edition See attached 'PrusaSlicer - System Information output: slicingmachine.txt

3D printer brand / version + firmware version (if known)

N/A. The issue occurs in PrusaSlicer as stock Original Prusa i3 MK3S MMU2S is powered off.

Behavior

Slicing the attached project consumes expected resources until 'Generating G-code..." appears. Then CPU usage drops to nominal usage and RAM consumption slowly increases. I observed this state for over 4 hours before aborting by merely closing the application (no error or warning about saving the slice or slicing in progress).

To reproduce via GUI:

1. load the attached project.
2. Slice.
3. wait for CPU load to fall off and observe to see if memory consumption continues while slicer falls to nominal CPU usage.

On my system, this happens 100% of the time. I will leave this running overnight to see if it completes in 8 hours or longer if requested. It might take a long time to run out of RAM on the box if it is runaway as the box has 64GB of ram and growth rate ~1G in several hours.

Expected Results: Slicing should continue to use available resources at the throttle limit set by default process priority and should thus ultimately complete well before the timeframe observed 4+ hours.

Actual Results: 'Generating G-code..." state does not appear to end and memory consumption slowly increases while CPU usage is nominal. I've observed PrusaSlicer at over 2GB of RAM consumption (for the process alone) after 4 hours. Green status bar reaches about 90% complete within the expected timeframe of a few minutes but remainder does not appear to progress even when allowed hours.

In this state, clicking the available 'Export G-code' button results in an offer to save the file as: "meadow-of-girasole_0.15mm_PLAMK3SMMU2S{print_time}".

This is not a new feature request.

Project File (.3MF) where problem occurs

I've uploaded here the 'meadow-of-girasole' project file, screen captures of the problem state, the config.ini in case it makes viewing settings easier, and a CPU-Z html output showing the full hardware. I have a memory dump of the process taken /w taskmgr's dump feature and can collect any additional diagnostics need if you give me details.

[DavidUnboxed]

I see I missed the project and CPU-Z output due to file type limitations. I've attached them here in a zip file. Project & CPU-Z output.zip

[neophyl]

try it with Avoid Crossing perimeters unticked. Traditionally that setting has been the biggest cause of slowdowns on slicing.

[DavidUnboxed]

Without 'Avoid crossing perimeters' checked: slicing completed in less than 6 min.

[DavidUnboxed]

Is there more data I can collect to help improve 'avoid crossing perimeters' function?

[Jebtrix]

It's a math optimization challenge but I'm sure the devs appreciate your tenacity to help. If math is your thing take a peek under the hood :)

[DavidUnboxed]

My math is better than my C++ but not adequate for any kind of 3D topology optimization.

As a test I started a fresh instance of PrusaSlicer at 9/10/2019 3:04:28 AM Central and immediately started slicing the same project. It is now past 16 hours of gcode generation. I decided to take a peek at this process with Process Monitor. Focusing on just the PID in use by PrusaSlicer.exe, in a 1/2 hour of watching it create and exite 10 threads, and write .28148.gcode.tmp twice: a length 4096 and a length 1515520. The first of those starting at offset 94,814,208.

If tmp file creation with the setting is similar to output size without the same, its at 102MB vs. 146MB anticipated. If so, it might finish in 8 hours more. So, about 24 hours of slicing. I'll check it again before I go to bed tonight, and when I awaken tomorrow.

Some oddity, threads created and exited that are not writing output, have this set of characteristics: High Resolution Date & Time: 9/10/2019 7:29:23.8751641 PM Event Class: Process Operation: Thread Exit Result: SUCCESS Path:
TID: 23556 Duration: 0.0000000 Thread ID: 23556 User Time: 0.0000000 Kernel Time: 0.0000000

I also see the process hitting repetitively a few Theme and Personalization keys in the registry:

7:52:52.8881344 PM prusa-slicer.exe 28148 RegQueryKey HKLM SUCCESS Query: HandleTags, HandleTags: 0x0 7:52:52.8881571 PM prusa-slicer.exe 28148 RegOpenKey HKLM\Software\Policies\Microsoft\Windows\Personalization NAME NOT FOUND Desired Access: Query Value 7:52:52.8885317 PM prusa-slicer.exe 28148 RegOpenKey HKCU SUCCESS Desired Access: Read 7:52:52.8885535 PM prusa-slicer.exe 28148 RegQueryKey HKCU SUCCESS Query: HandleTags, HandleTags: 0x0 7:52:52.8885703 PM prusa-slicer.exe 28148 RegOpenKey HKCU\SOFTWARE\Microsoft\Windows\CurrentVersion\Themes\Personalize SUCCESS Desired Access: Query Value 7:52:52.8885891 PM prusa-slicer.exe 28148 RegQueryValue HKCU\Software\Microsoft\Windows\CurrentVersion\Themes\Personalize\AppsUseLightTheme NAME NOT FOUND Length: 16 7:52:52.8886074 PM prusa-slicer.exe 28148 RegCloseKey HKCU\Software\Microsoft\Windows\CurrentVersion\Themes\Personalize SUCCESS 7:52:52.8886235 PM prusa-slicer.exe 28148 RegCloseKey HKCU SUCCESS

This fills my process monitor full-screen window over 106 times in two seconds.

[bubnikv]

This issue is likely a duplicate of https://github.com/prusa3d/PrusaSlicer/issues/2213 please see the comments at https://github.com/prusa3d/PrusaSlicer/issues/2213#issuecomment-524638411

[bubnikv]

This object is quite a torture test of various pieces of the slicing pipeline, thanks for that.

[DavidUnboxed]

FYI: this slice attempt is still running @ 36+ hours now. All checks of thread state for the process show: ThreadState : 5 ThreadWaitReason : 6

.28148.gcode.tmp is now at 140MB. I'm reviewing "This issue is likely a duplicate of #2213 please see the comments at #2213 (comment)"

[DavidUnboxed]

Testing slicing of this object with PrusaSlicer-2.1.0-rc2+Win64-201909111226.... I've got the original going along with it still. I cannot help but love the i7 8086K. :)

[DavidUnboxed]

The object from #2213 generated, with PrusaSlicer-2.1.0-rc2+Win64-201909111226, for me in just a few minutes. However, the one for this is still running now at well over 1 hr.

[DavidUnboxed]

The PrusaSlicer-2.0.0-rc+win64-201909041321 slice of the object uploaded for this problem has completed.

Slice Now: 9/10/2019 3:04:28 AM Slicing Complete: 9/11/2019 7:06:27 PM Just over 40 hours.

.28148.gcode size: 162MB.

The slicing with PrusaSlicer-2.1.0-rc2+win64=201909111226 is still ongoing at 3+hrs. Now at 77.4MB.

[DavidUnboxed]

The slicing with PrusaSlicer-2.1.0-rc2+win64=201909111226, Thursday, ‎September ‎12, ‎2019, ‏‎10:52:27 PM: ~30 hours. output was 162MB.

@bubnikv | That's a nice improvement. Seems it shaved about 10 hours of that between the builds.

[lukasmatena]

@DavidUnboxed While I admire your devotion, it is quite difficult to comprehend what was sliced in what version with what settings and in what time from your description. Summary in a small table with double checking of all data would help here (e.g. "PrusaSlicer-2.0.0-rc+win64-201909041321" was never released).

You seem to report that the bottleneck fix in avoid crossing perimeters mentioned in #2213 greatly improved performance between 2.1.0-rc and 2.1.0-rc2. That would be nice to hear, if the fix wasn't introduced in 2.1.0-beta2. There were no changes in this part of PrusaSlicer between rc and rc2 that I'm aware of.

Some of your comments seem to indicate you are running the tests in parallel. If that's the case, the measured time does not really tell much.

[DavidUnboxed]

'PrusaSlicer-2.0.0-rc+win64-201909041321' was simply a typo, corrected it's: PrusaSlicer-2.1.0-rc+win64-201909041321. So for a short summary:

Slicing uploaded 'meadow' with PrusaSlicer-2.1.0-rc+win64-201909041321: ~40 hours. Slicing uploaded 'meadow' with PrusaSlicer-2.1.0-rc2+win64-201909111226: ~30 hours.

While it's true, running more than one instance, or anything else at all, may skew these a bit, total CPU never hit 100% after the first 10 minutes (during which it was largely pegged). After that, it always goes down to ~10% CPU per instance with no other baseline performance metric even remotely taxed; not even in the overlap except for 10 minutes when the 2nd process starts. Because they were executed in the order above, with the shorter executing run started after the longer run was hours into the run, it's unlikely to have caused any significant skew. If you really feel there is a need, I'd be happy to run a much shorter slice on both versions with system diagnostics collection for precision data. I just didn't feel it was necessary from my perspective given this run times. It's clear the change between versions was significant and excellent and very kudo worthy.

[lukasmatena]

If you really feel there is a need

I'm not saying there is a need to collect precise data of this sort. We are well aware of the fact that gcode export and avoid crossing perimeters in particular need major changes. I'm just saying the times can be misleading in some cases, that's all. Although I admit that it is interesting to see how bad it is.

It's clear the change between versions was significant and excellent and very kudo worthy.

It would be, but there is a problem. The change happened with 2.1.0-beta2. Not in between the versions that you tested (2.1.0-rc and 2.1.0-rc2).

[bubnikv]

The following "Quality" features are really detrimental to the slicing speed for this particular model:

"Extra perimeters if needed" and "Detect bridging perimeters" perform an operation of one island against the whole layer below, which has a quadratic complexity to the number of islands. That's why the perimeter calculation takes so long with your settings. Your model is a good torture test when trying to improve performance of the two features mentioned.

The "Avoid crossing perimeters" was always a bottle neck.

[DavidUnboxed]

No worries @lukasmatena; I simply misunderstood the timeline @bubnikv was relaying about the optimization made. I also recognize that this quite the monster job for those settings - even at such, I did not expect either attempt to take so long - especially given the status bar display being almost done and CPU consumption dropping to nominal after only 10 minutes. If this is a known issue with the code or design - just some more clarity in the interface about estimated time till completion would be a major improvement and probably result in far fewer people thinking it was was 'hung' while using these settings. Hence, the careful words I chose for the title of the issue.

I understand the goal of the settings but generally leave them all enabled because a little time upfront for better slices is better than when I forget and truly need settings. In this case, 'Avoid crossing parameters' seems to be the best option to reduce problems with stringing short of replacing the filament. I gave the nasty filament an appropriate name in the project file.

[bubnikv]

"Extra perimeters if needed" and "Detect bridging perimeters" perform an operation of one island against the whole layer below, which has a quadratic complexity to the number of islands.

These two features could be sped up with a relatively simple and straight forward optimization by doing pre-filtering using bounding boxes when doing an operation against the layer below. BTW I believe this is the approach of Cura as far as I remember when I was peeking into the code some two and half years ago.

[bubnikv]

"Avoid crossing perimeters" has been reworked with 5f456ebbe78f3b994ea7ecc7de23c119e4705b61 (see the branch lh_avoid_crossing_perimeters). The new algorithm will be available in PrusaSlicer-2.3.0-beta3. Please check the PrusaSlicer-2.3.0-beta3 change log for details.

The slicing finishes in a reasonable time on my recent 12 core Ryzen desktop. Please retest with the beta3, I am interested in your experience. As this particular model is a torture test of not only the "avoid crossing perimeters" feature, I am not sure whether to close this issue or not.