Maya takes a long time to start

Hey there,

Some users complained that Maya took longer time to launch when launching it via Shotgun Desktop.

After some tests, I have questions. Here are logs from dekstop.log:

00:53:39,471 [18324 INFO tk_desktop.communication_base] Connecting to gui pipe \\.\pipe\pyc-XXXXXXX
00:53:39,474 [13304 INFO tk_desktop.communication_base] Connecting to gui pipe \\.\pipe\pyc-YYYYYYY
00:54:38,799 [13304 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_1 "some/path"
00:55:10,904 [13304 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_2 "some/path"
00:55:21,688 [13304 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_3 "some/path"
00:55:32,447 [13304 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_4 "some/path"
00:55:43,214 [13304 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_5 "some/path"
00:55:53,980 [13304 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_6 "some/path"
00:56:04,746 [13304 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_7 "some/path"
00:56:15,532 [13304 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_8 "some/path"
00:56:26,292 [13304 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_9 "some/path"
00:56:37,061 [13304 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_10 "some/path"




01:29:13,647 [4148  INFO tk_desktop.communication_base] Connecting to gui pipe \\.\pipe\pyc-WWWWWWWWWWW
01:29:13,650 [15892 INFO tk_desktop.communication_base] Connecting to gui pipe \\.\pipe\pyc-ZZZZZZZZZZZ
01:31:05,382 [15892 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_1 "some/path"
01:31:06,009 [15892 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_2 "some/path"
01:31:06,217 [15892 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_3 "some/path"
01:31:06,407 [15892 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_4 "some/path"
01:31:06,615 [15892 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_5 "some/path"
01:31:06,825 [15892 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_6 "some/path"
01:31:07,013 [15892 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_7 "some/path"
01:31:07,221 [15892 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_8 "some/path"
01:31:07,430 [15892 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_9 "some/path"
01:31:07,618 [15892 INFO tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx SOME_ENV_VAR_10 "some/path"

:diamonds: What is ā€˜Connecting to gui pipeā€™ ? It seems this alone can take up to 1mn, is there a way to make this faster?

:diamonds: before_app_launch operations: I create env var (for instance needed to load maya plugins) with a python script that launch os.system(ā€˜setxā€¦ā€™). This Pythpon script is pretty fast when testing it alone and takes less than 5s to create all the env var, but it can takes up to 2mn! Are there other stuff happening in the background that the log donā€™t tell us about?

Thanks

3 Likes

I believe this only occurs when you select a project in Shotgun Desktop. Shotgun Desktop spawns off a separate python process for the project you are loading, and then creates a connection between the main SG Desktop process and the Project process. This should be pretty fast and followed by a message saying ā€œConnected to the proxy server.ā€ assuming all has gone well. You will need to have debug logging enabled in order to see the second message.

2020-01-22 10:32:36,152 [94531 INFO sgtk.ext.tkimpb08f1abfea4543efa875f07c759716d7.tk_desktop.communication_base] Connecting to gui pipe /var/folders/34/7f7f3d9d5bx50tx1b9g8tf3c0000gn/T/pymp-zfXYVY/listener-SNWaBH
2020-01-22 10:32:36,153 [94531 DEBUG sgtk.ext.tkimpb08f1abfea4543efa875f07c759716d7.tk_desktop.communication_base] Connected to the proxy server.

Again I think it would be important to see the debug logs here. One other thing you can do is add a log at the beginning and end of your hook to see how long it took.

Iā€™d also recomend checking out this guide on performance troubleshooting. Launching via Shotgun Desktop will take a little longer than launching without, as there is naturally more going on, but it shouldnā€™t be excessively longer. 2mins launch time seems too long. A common cause for slow launch covered in the doc, is folder creation.

2 Likes

Hi Philip,
Thanks for your quick answer.

Sorry about the log not containing debug, TK_DEBUG env var was appaently overriden during this test.
Here is a log from today. We can see the whole process is way faster than yesterday, while nothing chnaged in the config:

2020-01-22 11:52:51,448 [15892 DEBUG sgtk.core.log] Debug logging enabled. To permanently enable it, set the TK_DEBUG environment variable.
2020-01-22 11:52:51,450 [15892 DEBUG sgtk.core.log] Setting TK_DEBUG in the environment for this session. This ensures that subprocesses spawned from this process will inherit the global debug logging setting from this process.
2020-01-22 11:52:51,500 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Debug logging enabled. To permanently enable it, set the TK_DEBUG environment variable.
2020-01-22 11:52:51,502 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Setting TK_DEBUG in the environment for this session. This ensures that subprocesses spawned from this process will inherit the global debug logging setting from this process.
2020-01-22 11:53:02,950 [15892 DEBUG sgtk.env.site.tk-desktop.tk-framework-shotgunutils] User Settings Manager: Storing superprodartdev.shotgunstudio.com:project_recent_apps.190
2020-01-22 11:53:03,549 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Creating folders for Project 190. Defer keyword: 'tk-maya'
2020-01-22 11:53:04,466 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Path cache sync tracking marker in local sqlite db: 507281
2020-01-22 11:53:04,467 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Fetching create/delete folder event log entries >= id 507281 for project {'type': 'Project', 'id': 190}...
2020-01-22 11:53:04,653 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Got 1 event log entries
2020-01-22 11:53:04,654 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Event log contains 1 creations and 0 deletions
2020-01-22 11:53:04,654 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Path cache syncing not necessary - local folders already up to date!
2020-01-22 11:53:04,674 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Loading environment data from path: l:\_tech\sgtk_configs\config_deploy_calimero_trailer\env\project.yml
2020-01-22 11:53:04,946 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Loading SoftwareLauncher plugin 'C:\Users\userName\AppData\Roaming\Shotgun\bundle_cache\app_store\tk-maya\v0.9.10\startup.py' ...
2020-01-22 11:53:04,980 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Created SoftwareLauncher instance: <a7217bdd320146a88c31ae6b0179937a.MayaLauncher object at 0x0000000006953D30>
2020-01-22 11:53:04,982 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Created tk-maya engine launcher : <a7217bdd320146a88c31ae6b0179937a.MayaLauncher object at 0x0000000006953D30>
2020-01-22 11:53:04,983 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Preparing Maya Launch via Toolkit Classic methodology ...
2020-01-22 11:53:04,983 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Engine launcher prepared launch info:
  path : C:\Program Files\Autodesk\Maya2019\bin\maya.exe
  args : 
  env  : {dict of env var}
2020-01-22 11:53:04,984 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Running before app launch hook...
2020-01-22 11:53:04,986 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] <Sgtk App 0x03399278: tk-multi-launchapp, engine: <Sgtk Engine 0x03179128: tk-desktop, env: project>>: Resolved hook expression (associated with setting 'hook_before_app_launch'): '{config}/tk-multi-launchapp/before_app_launch.py' -> ['C:\\Program Files\\Shotgun\\Resources\\Python\\bundle_cache\\app_store\\tk-multi-launchapp\\v0.10.3\\hooks\\before_app_launch.py', 'l:\\_tech\\sgtk_configs\\config_deploy_calimero_trailer\\hooks\\tk-multi-launchapp\\before_app_launch.py']
2020-01-22 11:53:10,441 [15892 INFO sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx VAR "some/path"
2020-01-22 11:53:11,654 [15892 INFO sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx VAR "some/path"
2020-01-22 11:53:12,046 [15892 INFO sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx VAR "some/path"
2020-01-22 11:53:12,463 [15892 INFO sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx VAR "some/path"
2020-01-22 11:53:12,861 [15892 INFO sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx VAR "some/path"
2020-01-22 11:53:13,256 [15892 INFO sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx VAR "some/path"
2020-01-22 11:53:13,653 [15892 INFO sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx VAR "some/path"
2020-01-22 11:53:14,071 [15892 INFO sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx VAR "some/path"
2020-01-22 11:53:14,467 [15892 INFO sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx VAR "some/path"
2020-01-22 11:53:14,862 [15892 INFO sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] >>>> before_app_launch.py : setx VAR "some/path"
2020-01-22 11:53:14,864 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Launching executable 'C:\Program Files\Autodesk\Maya2019\bin\maya.exe' with args ''
2020-01-22 11:53:14,865 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] <Sgtk App 0x03399278: tk-multi-launchapp, engine: <Sgtk Engine 0x03179128: tk-desktop, env: project>>: Resolved hook expression (associated with setting 'hook_app_launch'): '{self}/app_launch.py' -> ['C:\\Program Files\\Shotgun\\Resources\\Python\\bundle_cache\\app_store\\tk-multi-launchapp\\v0.10.3\\hooks\\app_launch.py']
2020-01-22 11:53:14,875 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] Hook tried to launch 'start /B "App" "C:\Program Files\Autodesk\Maya2019\bin\maya.exe" '
2020-01-22 11:53:15,056 [15892 DEBUG sgtk.ext.tkimpeb4455471ee34fab8de689ac811dc2a9.tk_desktop.site_communication] [PROXY] create_event_log_entry: 0.172000s

It seems the time it takes to launch Maya from SGTK depends on the server and internet speed?

Iā€™ll check the log again next time a user tells me he has trouble launching Maya. In the meantime Iā€™ll also read the performance guide.

3 Likes

Is there a hook that would launch whenever a user load a project on SG Desktop, once Desktop has finished initialising?
Iā€™d like to test the time it would take to launch maya if I create env var once and not everytime we launch a DCC.

2 Likes

(bump)

Hi Ben

Sorry for not getting back to you sooner, Iā€™ve moved from support to engineering, so Iā€™m not looking on here as frequently.

The engine_init.py core hook should be run when the engine finishes starting up, so you could use that.

I donā€™t think that will likely have an impact on performance by removing the code from the app launch, but Iā€™d be interested to hear how you get on.

Cheers
Phil

2 Likes

Hey there Philip,

Good for you, thanks a lot for all the help you gave me those past few months! It was amazingly helpfull :slight_smile:


in engine_init.py:

if engine.name == "tk-desktop":
    if engine.context.project.get('id') == 190
         # do some stuff

This definitly works :slight_smile:

Iā€™ll have to check launch time at different hours of the day, but for now, since I moved env var definition here maya seems to launch in a matter of second, while it could take up to 5mn when I was using before_app_launch.py
SG Desktop launch and Project loading does not seem to be longer.

Thatā€™s definitly the way to go.

2 Likes