Cura: [master] - Question re checking per-object setting errors

[smartavionics]

Application version

Platform

Printer

Reproduction steps

Actual results

Expected results

Additional information

I've ignored the template because this isn't a bug report.

I'm trying to track down where a lot of time gets spent when starting a slice and I noticed that in StartSliceJob.py it calls _checkStackForErrors() for each scene node to check the per-object settings. But that method actually checks all of the properties in the stack(s) because it does this:
for key in stack.getAllKeys(): validation_state = stack.getProperty(key, "validationState") if validation_state in (ValidatorState.Exception, ValidatorState.MaximumError, ValidatorState.MinimumError, ValidatorState.Invalid): Logger.log("w", "Setting %s is not valid, but %s. Aborting slicing.", key, validation_state) return True Job.yieldThread()

Doesn't it only need to check the values defined in the first container? i.e. the per-object values rather than all the other values as well? If so, could it not look more like this (with some possible error checking in case getTop() returns None) ?

for key in stack.getTop().getAllKeys():

Thoughts ?

[nallath]

The following can be possible:
max_value of foo = bar / 2
The default value of bar is 20 and foo is 5, and the user sets the value of bar to be 2. At this point, the max_value error of foo should be triggered, even though it's value was not changed.

We could indeed be a bit smarter about this by checking the relations so we don't have to check all the settings.

[smartavionics]

Thanks for the reply. Yes, I can see that now. However, as most models probably don't have any model-specific settings applied, can't we still add the following early return into _checkStackForErrors() ?

````
if len(stack.getTop().getAllKeys()) == 0:
return False

````

i.e. if there are no per-model settings, there's no point in checking any of the other settings in the stack as they would already have been checked. If you agree, I'll put that into a PR.

[nallath]

Yeah, that makes total sense. Good find :) In my simple test it knocked off about 0.3 sec (1.3 without your change, 1 sec with) to send the slice message.

[smartavionics]

OK, I'll put that in a PR.

Now, the background to all this is that I noticed that on some low-powered platforms (PI4, Chromebook), the Python performance is distinctly sluggish. I did some python benchmark testing and found roughly the performance of those platforms compared to my "reference" box which is only a i3 running Linux at 2.3 GHz. The PI4 runs Python approx 2-3 times slower than the Linux box and the chromebook is about 50% slower than the PI4. So far so good but then when I look at the performance of Cura doing the per-object check I see a big disparity in performance between the platforms.

On a particular project, the per-object testing was taking 55 ! seconds on the chromebook, 25 seconds on the PI4, 10 seconds on the Linux box using the AppImage and about 1 second on the Linux box when just executing Cura not from the AppImage but out of an installed file tree (i.e. everything installed in /opt/cura).

What is very weird and I cannot find a reason for it is that on the same Linux platform, if I run Cura from a tree of files that has been created by cx_freeze (i.e. what would go inside the AppImage), the Python runs very much slower than executing exactly the same code from /opt/cura.

I think we're losing a lot of Python performance somewhere but I really can't see where at the moment.

[smartavionics]

Created https://github.com/Ultimaker/Cura/pull/6550.

[Ghostkeeper]

What is very weird and I cannot find a reason for it is that on the same Linux platform, if I run Cura from a tree of files that has been created by cx_freeze (i.e. what would go inside the AppImage), the Python runs very much slower than executing exactly the same code from /opt/cura.

I think we're losing a lot of Python performance somewhere but I really can't see where at the moment.

We are at the moment investigating this very issue. It seems that since 4.3 there has been something that makes all of the builds much slower but didn't influence running from source.

[smartavionics]

And what's even weirder is that the cura doesn't even need to be frozen for the slowdown to happen. You can execute the top level cura python script from the command line using the same python3 that would be used if you were running from source and it will still go slow if all the files are coming from the package tree.

[nallath]

@smartavionics I don't quite get what you mean by that. Isn't that what you do when running it from source?

[smartavionics]

I normally just install everything into /opt/cura and run from the command line a little shell script that looks like this:

````

!/bin/sh

this assumes that $0 is equal to $CURA_HOME/bin/cura.sh after symlinks have been resolved

CURA_BIN=$(dirname $(realpath $0))

CURA_HOME=$(realpath $CURA_BIN/..)

CURA_LIB=$CURA_HOME/lib

PATH=$CURA_BIN:$PATH

export PYTHONPATH=$CURA_LIB/python3/dist-packages:$CURA_LIB/cura
export LD_LIBRARY_PATH=$CURA_LIB
export QT_PLUGIN_PATH=$CURA_LIB/plugins
export QML2_IMPORT_PATH=$CURA_LIB/qml

$CURA_BIN/python3 $CURA_BIN/cura $@
````

Python performance is good.

But if I do a build in cura-build repo which takes the files in /opt/cura and combines some of those files with files from the build tree in cura-build/build and runs cx_freeze to create a package directory which is then bundled into an AppImage, something weird happens to the files in that package directory because now, even if I use the same python3 app to execute the Cura using the files in the package directory, it runs approx 2-3 times slower than executing with everything coming from /opt/cura.

[smartavionics]

I have spent several days looking into this so far and have drawn a complete blank.

[nallath]

Well, I'm very happy that you got this far because we didn't find this out yet. It's a pretty good hint for us to continue the investigation.

[smartavionics]

Just a thought, has anyone tried reverting back to using Python 3.5.2 ?

[Ghostkeeper]

We didn't try that. However the 4.3 release was already using 3.5.7 and is performing normally, so I don't think that is causing it.

[smartavionics]

I found the cause of the big slowdown but I can't explain why it only seems to affect Cura when it has been processed by cx_freeze.

Here's the culprit, with my temporary hack to fix the problem, I leave it to you guys to come up with a proper solution...
````

Decorator that can be used to indicate a method has been deprecated

#

\param message The message to display when the method is called. Should include a suggestion about what to use.

\param since A version since when this method has been deprecated.

def deprecated(message, since = "Unknown"): #pylint: disable=bad-whitespace
def deprecated_decorator(function):
def deprecated_function(args, *kwargs):
#warning = "{0} is deprecated (since {1}): {2}".format(function, since, message)
#Logger.log("w_once", warning)
#warnings.warn(warning, DeprecationWarning, stacklevel=2)
return function(args, *kwargs)
return deprecated_function
return deprecated_decorator
````

Hell, I've wasted too much time finding this!

[smartavionics]

Would it be better if the deprecated decorator was a no-op for non-test builds?

[Ghostkeeper]

Our current suspicion is this patch we're doing on the CPython interpreter: https://github.com/Ultimaker/cura-build-environment/commit/cd32ee24c25626b4bc5a09700ed391c0ea103725

A build is being made to test without that patch. We've seen that creating our current source (master) using our build environment for 4.2 gives us a fast build with all our current features in, except those that needed new dependencies (e.g. OpenCTM, DAE...).

[smartavionics]

Hi @Ghostkeeper , did you see my comment above re the deprecated decorator? Zapping that, completely solved the problem for me.

[Ghostkeeper]

Yes I saw that. We're looking into a different direction though and also found a solution there. We've found that the upgrading of the packaging package was causing this. That is a proper solution.

It's weird though that commenting out just a log entry solved the problem. You've left the actual decorator itself in. The log entry is not being added all that often, maybe 10 times or so per run.

[smartavionics]

Yes, but the methods that have been decorated are probably being called thousands of times per run and so it's doing all the formatting, etc. in Logger.log() repeatedly.

[smartavionics]

OK, I'll close this issue now as it's no longer needed. I'm still bemused by the fact that you are unconcerned with the amount of CPU being wasted by the deprecated decorator.

[nallath]

But there isn't a whole lot of CPU being wasted. I've profiled Cura quite a few times and the amount of CPU used on the deprecated decorator is almost nothing compared to what the rest is doing.

[smartavionics]

Obviously, it depends on what functions have been decorated. Right now, in the master branch functions such as GlobalStack.extruders() are decorated and that is generating thousands of calls to the deprecated function which is over and over again needlessly formatting the message and then passing it to Logger.log() to fiddle with before it finally decides that it's not going to output anything because "w_once" has been specified. Perhaps on a fast computer you don't notice the wasted time but on less powerful platforms it's very noticeable.

[nallath]

The profiler that I'm using checks the percentage of time spent on doing it. Since the ratio will remain the same(ish) regardless of the system, it doesn't matter.

When I made the logging changes you suggested, i didn't get any speed improvements at all.

[smartavionics]

Now here's the odd thing, I only seem to get the really big slowdown when running cura from a packaged build, not when running from source. Even with the upstream recent reversion to packaging 18.0 I still get a very large slowdown when running Cura not from source. I wasted days trying to find what the difference was but the only thing that really helped was commenting out those lines in the deprecated decorator.

[nallath]

I did not profile it with the packaged version, so it could still be an issue.

[smartavionics]

So, to check I am not imagining this, just now, on the Pi4 platform, I did a test. Using a fairly recent set of master branches (just before the latest intent changes were merged but using the 0.8 version of packaging) the AppImage took around 2.2 seconds to do the per-object settings check in StartSliceJob when those lines in the deprecated decorator were commented out and around 20 seconds(!) when they were not commented out. i.e. it's taking around 10 times longer.

[smartavionics]

I see similar results on Windows and MacOS, also.

[Ghostkeeper]

I was also doing a test. During start-up of Cura (up until the "booting Cura took ... seconds") I get 24 calls of the deprecated_function function. The 24 times formatting takes a total time of 0.00018477439880371094 seconds.

I also measured the calls during the run() function of the StartSliceJob. This resulted in 66 calls to the deprecated_function function for a total of 0.00041675567626953125 seconds.

After packaging, it could be that some things are slower due to cx_freeze modifying stuff (as was apparent in the packaging module that we found). But even if it's 10 times longer that would save 4ms of time on starting a slice. That wouldn't be noticeable. So I'm thinking that something else must be different in that build system where you're seeing the difference.