Cura: [4.0] Slow startup

[Liger0]

Application Version
4.0

Platform
Windows 10 x64

Printer
It doesn't matter

Steps to Reproduce
Open Cura

Actual Results
It needs more than 1 minute before it even starts to open. For the first minute nothing appears after double clicking on the icon.

Expected results
It should load faster

[AlanWhereAreYou]

I get this as well.
Sometimes it starts quick, and sometimes it starts slow.

Basically if you watch the log files while it is launching, every single step takes 1-3 seconds to occur and there are hundreds of steps. Total launch time ~7 minutes.

If I switch my laptop into Airplane mode, disconnecting it from all networks, then the boot time is fast again with each step in the log taking much less than a second. Total launch time less than 1 minute.

Here are samples - network connected, this block takes 36 seconds:

2019-03-30 20:23:47,178 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin ConsoleLogger
2019-03-30 20:23:48,894 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin CuraDrive
2019-03-30 20:23:48,951 - INFO - [MainThread] CuraEngineBackend.CuraEngineBackend.__init__ [81]: Found CuraEngine at: C:\Program Files\Ultimaker Cura 4.0\CuraEngine.exe
2019-03-30 20:23:50,724 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin CuraEngineBackend
2019-03-30 20:23:52,499 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin CuraProfileReader
2019-03-30 20:23:54,244 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin CuraProfileWriter
2019-03-30 20:23:55,959 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin OBJReader
2019-03-30 20:23:57,679 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin OBJWriter
2019-03-30 20:23:59,491 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin STLReader
2019-03-30 20:24:01,234 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin STLWriter
2019-03-30 20:24:02,948 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin FileLogger
2019-03-30 20:24:04,684 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin FirmwareUpdateChecker
2019-03-30 20:24:06,409 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin FirmwareUpdater
2019-03-30 20:24:08,179 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin GCodeGzReader
2019-03-30 20:24:09,884 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin GCodeGzWriter
2019-03-30 20:24:11,628 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin GCodeProfileReader

Network disconnected, same block takes 2 seconds:

2019-03-30 20:27:29,383 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin ConsoleLogger
2019-03-30 20:27:29,561 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin CuraDrive
2019-03-30 20:27:29,701 - INFO - [MainThread] CuraEngineBackend.CuraEngineBackend.__init__ [81]: Found CuraEngine at: C:\Program Files\Ultimaker Cura 4.0\CuraEngine.exe
2019-03-30 20:27:29,754 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin CuraEngineBackend
2019-03-30 20:27:29,861 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin CuraProfileReader
2019-03-30 20:27:29,965 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin CuraProfileWriter
2019-03-30 20:27:30,079 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin OBJReader
2019-03-30 20:27:30,195 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin OBJWriter
2019-03-30 20:27:30,314 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin STLReader
2019-03-30 20:27:30,419 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin STLWriter
2019-03-30 20:27:30,511 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin FileLogger
2019-03-30 20:27:30,646 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin FirmwareUpdateChecker
2019-03-30 20:27:30,768 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin FirmwareUpdater
2019-03-30 20:27:30,884 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin GCodeGzReader
2019-03-30 20:27:31,001 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin GCodeGzWriter
2019-03-30 20:27:31,117 - INFO - [MainThread] UM.PluginRegistry.loadPlugin [436]: Loaded plugin GCodeProfileReader

[fieldOfView]

It would be helpful to see a full log of Cura starting up slow; then we can see when it starts to slow down.

[AlanWhereAreYou]

@fieldOfView attached are the stderr, stout, and cura logs.

Note that the launch is slow from the beginning: I launched the app at 10:49:36 and the first log message doesn't appear until 10:51:34ish. So 2 minutes just to get to the point where it wants to log.
cura.log
stderr.log
stdout.log

I feel like something is going weird with Python and it's trying to access disconnected drives. For example, process monitor shows this action:

Date & Time:    3/31/2019 10:49:47 AM
Event Class:    File System
Operation:  CreateFile
Result: BAD NETWORK PATH
Path:   \\DfsClient\;X:00000000001294a6\MyWorkDomain.net\Transfer\4.0\build\inst\lib\python3.5\site-packages\UM\Resources.py
TID:    25604
Duration:   1.1950705
Desired Access: Read Attributes, Synchronize
Disposition:    Open
Options:    Synchronous IO Non-Alert, Open Reparse Point
Attributes: N
ShareMode:  None
AllocationSize: n/a

Where MyWorkDomain.net is my work's domain, and \Transfer\ is a network folder I've recently accessed. Why Cura is trying to get Resources.py from that path is beyond me.

I can upload the entire Cura.exe process monitor if you'd like, but I have to annonomize it a bit.

I'll note that I did try launching Cura while connected to my work network, and it's fast. So there is something there that's messing up.

Let me know if I can help further.

[fieldOfView]

Ah, yes, that would explain things a bit. Due to reasons in the build-system, Cura sortof thinks it is running off a drive X:. It tries to access that drive for each file it opens. @Ghostkeeper, it is the frozen path issue again (that used to bother us even more when it was still trying to access D:).

As a workaround until this gets fixed, you could create a local, empty partition with drive letter X:. An ugly hack for sure, but it might solve your problem.

[Liger0]

Just for completion, this is a log I saved up. It hasn't been very slow this time though.
cura.zip

[fieldOfView]

@Liger0 have you tried disabling all network activity like @AlanWhereAreYou did?
Do you have an X drive? What sort of network/shared drives do you have?

[AlanWhereAreYou]

@fieldOfView thanks for the insight. I can just disconnect the drive, now that I know that's what's causing the problem (which I've tried, and can confirm the launch is fast again).

That also explains the intermittent nature of it - the share is only occasionally mapped.

[Liger0]

@Liger0 have you tried disabling all network activity like @AlanWhereAreYou did?
Do you have an X drive? What sort of network/shared drives do you have?

In that log I had ethernet and so I was connected to internet. I only have a C and D drive, where C is the OS and cura is installed on D.

[Ghostkeeper]

We've been getting a few reports here and there about being slow to start before the splash screen appears (during the loading of plug-ins, that is). This is the first hint of a direction we could search in. Thanks for the useful debugging, @AlanWhereAreYou!

[fieldOfView]

But note that Liger0 actually has no such X: drive, so there may be another mechanism at play.

[LipuFei]

JIRA ticket: CURA-6074

[LipuFei]

Turns out this problem is caused by Qt, see their bug report QTBUG-57832. We made a patch and this is fixed for the next release. https://github.com/Ultimaker/cura-build/pull/217

[AlanWhereAreYou]

@LipuFei I believe this issue has re-appeared in recent Cura releases. Not only is the launch slow when I have an inaccessible X: mapping, but the app itself becomes sluggish in use (lots of hangs while, presumably, X: drive operations time out). Currently doing it in 4.5.0, but I noticed it I think in the last two or three releases.