Slow startup on Windows

robertoabraham commented 4 years ago

Hi, on my laptop it appears that ginga takes over 10x longer to start up in native Win32 mode than it does when running under the windows subsystem for Linux (WSL). On the same machine, running Anaconda python 3.7.3, ginga takes about 40 seconds to start up under win32, while on the exact same machine starting ginga in WSL takes just 3s.

I've run this multiple times on win32 to verify it isn't just a caching thing and did the tests at more-or-less the same time under identical loads.

Once ginga has started up as far as I can tell ginga is running fine in both Win32 and WSL modes.

I'm personally OK with using WSL for everything so this issue isn't biting me, but I'd like to start encouraging our undergrads to use ginga and many (in fact most) of them want to use Windows without having to deal with installing the Linux subsystem and an X11 server, so it would be great if the startup times under Windows Win32 and WSL were in the same ballpark.

All the best,

Bob Abraham

pllim commented 4 years ago

What's win32? I use 64-bit Windows 10 and I don't notice this startup lag time (at least not to the extend of 40s). Also, what is the graphics backend that Windows version of Ginga is using? I usually stick with Qt.

robertoabraham commented 4 years ago

Confusingly, Win32 is what you're running when you use 64-bit Windows 10... it's just Microsoft's standard name for the Windows API (yes, it's crazy, it also is what it's called under 64 bit windows).

I'm also running 64 bit Windows 10.

robertoabraham commented 4 years ago

Oh, and I just installed Ginga under windows using conda as follows:

conda install ginga -c conda-forge

I'm not sure which graphics backend it is using (probably Qt?).

pllim commented 4 years ago

If you run Ginga like this:

ginga --loglevel=20 --stderr

Do you see something like this?

2020-04-10 15:22:16,503 | I | main.py:378 (main) | Chosen toolkit (qt5) family is 'qt'

Ginga also runs the code in ~/.ginga/ginga_config.py (the path is obviously not Windows, so you have to find the Windows equivalent of ~/.ginga), so if you have one, maybe sure that .py file is not doing something computationally intensive on load.

Also, I am curious if you still have the same problem with the dev version of Ginga, which you can install into your conda environment with pip:

pip install git+https://github.com/ejeschke/ginga.git@master

robertoabraham commented 4 years ago

Hey, thanks, that was an incredibly useful suggestion! I see now I am running under Qt in both cases. The slow startup appears to be associated with trying to load a bundled font (roboto), which takes 28s under the Windows API vs. about 0.2s in WSL! Here's the output under both systems (using the standard version, but I also verified that the problem is still there after installing the development version).

Windows API

(base) § Blackbird2 {~\Desktop} ginga --loglevel=20 --stderr 2020-04-10 15:27:28,244 | I | main.py:374 (main) | Chosen toolkit (qt5) family is 'qt' 2020-04-10 15:27:29,998 | I | Control.py:170 (init) | trying to load bundled font 'roboto' 2020-04-10 15:27:57,746 | I | ModuleManager.py:71 (load_module) | Loading module 'Operations'... 2020-04-10 15:27:57,752 | I | PluginManager.py:67 (load_plugin) | Plugin 'Operations' loaded. 2020-04-10 15:27:57,753 | I | ModuleManager.py:71 (load_module) | Loading module 'Toolbar'... 2020-04-10 15:27:57,760 | I | PluginManager.py:67 (load_plugin) | Plugin 'Toolbar' loaded. 2020-04-10 15:27:57,761 | I | ModuleManager.py:71 (load_module) | Loading module 'Pan'... 2020-04-10 15:27:57,766 | I | PluginManager.py:67 (load_plugin) | Plugin 'Pan' loaded. 2020-04-10 15:27:57,766 | I | ModuleManager.py:71 (load_module) | Loading module 'Info'... 2020-04-10 15:27:57,770 | I | PluginManager.py:67 (load_plugin) | Plugin 'Info' loaded. 2020-04-10 15:27:57,771 | I | ModuleManager.py:71 (load_module) | Loading module 'Thumbs'... 2020-04-10 15:27:57,835 | I | PluginManager.py:67 (load_plugin) | Plugin 'Thumbs' loaded. 2020-04-10 15:27:57,836 | I | ModuleManager.py:71 (load_module) | Loading module 'Contents'... 2020-04-10 15:27:57,842 | I | PluginManager.py:67 (load_plugin) | Plugin 'Contents' loaded. 2020-04-10 15:27:57,842 | I | ModuleManager.py:71 (load_module) | Loading module 'Colorbar'... 2020-04-10 15:27:57,848 | I | PluginManager.py:67 (load_plugin) | Plugin 'Colorbar' loaded. 2020-04-10 15:27:57,849 | I | ModuleManager.py:71 (load_module) | Loading module 'Cursor'... 2020-04-10 15:27:57,858 | I | PluginManager.py:67 (load_plugin) | Plugin 'Cursor' loaded. 2020-04-10 15:27:57,862 | I | ModuleManager.py:71 (load_module) | Loading module 'Errors'... 2020-04-10 15:27:57,866 | I | PluginManager.py:67 (load_plugin) | Plugin 'Errors' loaded. 2020-04-10 15:27:57,867 | I | ModuleManager.py:71 (load_module) | Loading module 'Downloads'... 2020-04-10 15:27:57,870 | I | PluginManager.py:67 (load_plugin) | Plugin 'Downloads' loaded. 2020-04-10 15:27:57,872 | I | ModuleManager.py:71 (load_module) | Loading module 'Blink'... 2020-04-10 15:27:57,876 | I | PluginManager.py:67 (load_plugin) | Plugin 'Blink' loaded. 2020-04-10 15:27:57,876 | I | ModuleManager.py:67 (load_module) | Reloading module 'Blink'... 2020-04-10 15:27:57,879 | I | ModuleManager.py:71 (load_module) | Loading module 'Cuts'... 2020-04-10 15:27:57,883 | I | ModuleManager.py:71 (load_module) | Loading module 'LineProfile'... 2020-04-10 15:27:57,889 | I | ModuleManager.py:71 (load_module) | Loading module 'Histogram'... 2020-04-10 15:27:57,895 | I | ModuleManager.py:71 (load_module) | Loading module 'Overlays'... 2020-04-10 15:27:57,898 | I | ModuleManager.py:71 (load_module) | Loading module 'Pick'... 2020-04-10 15:28:00,286 | I | ModuleManager.py:71 (load_module) | Loading module 'PixTable'... 2020-04-10 15:28:00,290 | I | ModuleManager.py:71 (load_module) | Loading module 'TVMark'... 2020-04-10 15:28:00,292 | I | ModuleManager.py:71 (load_module) | Loading module 'TVMask'... 2020-04-10 15:28:00,297 | I | ModuleManager.py:71 (load_module) | Loading module 'WCSMatch'... 2020-04-10 15:28:00,300 | I | PluginManager.py:67 (load_plugin) | Plugin 'WCSMatch' loaded. 2020-04-10 15:28:00,301 | I | ModuleManager.py:71 (load_module) | Loading module 'Command'... 2020-04-10 15:28:00,700 | I | PluginManager.py:67 (load_plugin) | Plugin 'Command' loaded. 2020-04-10 15:28:00,701 | I | ModuleManager.py:71 (load_module) | Loading module 'Log'... 2020-04-10 15:28:00,704 | I | PluginManager.py:67 (load_plugin) | Plugin 'Log' loaded. 2020-04-10 15:28:00,704 | I | ModuleManager.py:71 (load_module) | Loading module 'MultiDim'... 2020-04-10 15:28:00,718 | I | ModuleManager.py:71 (load_module) | Loading module 'RC'... 2020-04-10 15:28:00,721 | I | PluginManager.py:67 (load_plugin) | Plugin 'RC' loaded. 2020-04-10 15:28:00,721 | I | ModuleManager.py:71 (load_module) | Loading module 'SAMP'... 2020-04-10 15:28:00,808 | I | PluginManager.py:67 (load_plugin) | Plugin 'SAMP' loaded. 2020-04-10 15:28:00,809 | I | ModuleManager.py:71 (load_module) | Loading module 'Compose'... 2020-04-10 15:28:00,813 | I | ModuleManager.py:71 (load_module) | Loading module 'ScreenShot'... 2020-04-10 15:28:00,816 | I | ModuleManager.py:71 (load_module) | Loading module 'ColorMapPicker'... 2020-04-10 15:28:00,955 | I | PluginManager.py:67 (load_plugin) | Plugin 'ColorMapPicker' loaded. 2020-04-10 15:28:00,956 | I | ModuleManager.py:71 (load_module) | Loading module 'PlotTable'... 2020-04-10 15:28:00,959 | I | ModuleManager.py:71 (load_module) | Loading module 'Catalogs'... 2020-04-10 15:28:00,962 | I | ModuleManager.py:71 (load_module) | Loading module 'Crosshair'... 2020-04-10 15:28:00,965 | I | ModuleManager.py:71 (load_module) | Loading module 'Drawing'... 2020-04-10 15:28:00,967 | I | ModuleManager.py:71 (load_module) | Loading module 'FBrowser'... 2020-04-10 15:28:00,970 | I | ModuleManager.py:71 (load_module) | Loading module 'ChangeHistory'... 2020-04-10 15:28:00,973 | I | PluginManager.py:67 (load_plugin) | Plugin 'ChangeHistory' loaded. 2020-04-10 15:28:00,974 | I | ModuleManager.py:71 (load_module) | Loading module 'Mosaic'... 2020-04-10 15:28:00,977 | I | ModuleManager.py:67 (load_module) | Reloading module 'FBrowser'... 2020-04-10 15:28:00,982 | I | PluginManager.py:67 (load_plugin) | Plugin 'FBrowser' loaded. 2020-04-10 15:28:00,983 | I | ModuleManager.py:71 (load_module) | Loading module 'Preferences'... 2020-04-10 15:28:00,985 | I | ModuleManager.py:71 (load_module) | Loading module 'Ruler'... 2020-04-10 15:28:00,989 | I | ModuleManager.py:71 (load_module) | Loading module 'SaveImage'... 2020-04-10 15:28:00,992 | I | PluginManager.py:67 (load_plugin) | Plugin 'SaveImage' loaded. 2020-04-10 15:28:00,994 | I | ModuleManager.py:71 (load_module) | Loading module 'WCSAxes'... 2020-04-10 15:28:00,996 | I | ModuleManager.py:71 (load_module) | Loading module 'WBrowser'... 2020-04-10 15:28:00,999 | I | PluginManager.py:67 (load_plugin) | Plugin 'WBrowser' loaded. 2020-04-10 15:28:00,999 | I | ModuleManager.py:71 (load_module) | Loading module 'Header'... 2020-04-10 15:28:01,002 | I | PluginManager.py:67 (load_plugin) | Plugin 'Header' loaded. 2020-04-10 15:28:01,002 | I | ModuleManager.py:71 (load_module) | Loading module 'Zoom'... 2020-04-10 15:28:01,005 | I | PluginManager.py:67 (load_plugin) | Plugin 'Zoom' loaded. 2020-04-10 15:28:01,023 | I | ColorBar.py:108 (resize_cb) | colorbar resized to 1103x36 2020-04-10 15:28:01,023 | I | ColorBar.py:108 (resize_cb) | colorbar resized to 1103x36 2020-04-10 15:28:01,480 | W | Control.py:1428 (add_channel) | no saved preferences found for channel 'Image': Error opening settings file (C:\Users\abrah.ginga\channel_Image.cfg): [Errno 2] No such file or directory: 'C:\Users\abrah\.ginga\channel_Image.cfg' 2020-04-10 15:28:01,538 | I | PluginManager.py:67 (load_plugin) | Plugin 'Blink' loaded. 2020-04-10 15:28:01,540 | I | PluginManager.py:67 (load_plugin) | Plugin 'Cuts' loaded. 2020-04-10 15:28:01,541 | I | PluginManager.py:67 (load_plugin) | Plugin 'LineProfile' loaded. 2020-04-10 15:28:01,542 | I | PluginManager.py:67 (load_plugin) | Plugin 'Histogram' loaded. 2020-04-10 15:28:01,543 | I | PluginManager.py:67 (load_plugin) | Plugin 'Overlays' loaded. 2020-04-10 15:28:01,545 | I | PluginManager.py:67 (load_plugin) | Plugin 'Pick' loaded. 2020-04-10 15:28:01,546 | I | PluginManager.py:67 (load_plugin) | Plugin 'PixTable' loaded. 2020-04-10 15:28:01,549 | I | PluginManager.py:67 (load_plugin) | Plugin 'TVMark' loaded. 2020-04-10 15:28:01,553 | I | PluginManager.py:67 (load_plugin) | Plugin 'TVMask' loaded. 2020-04-10 15:28:01,554 | I | PluginManager.py:67 (load_plugin) | Plugin 'MultiDim' loaded. 2020-04-10 15:28:01,562 | I | PluginManager.py:67 (load_plugin) | Plugin 'Compose' loaded. 2020-04-10 15:28:01,588 | I | PluginManager.py:67 (load_plugin) | Plugin 'ScreenShot' loaded. 2020-04-10 15:28:01,590 | I | PluginManager.py:67 (load_plugin) | Plugin 'PlotTable' loaded. 2020-04-10 15:28:01,595 | I | PluginManager.py:67 (load_plugin) | Plugin 'Catalogs' loaded. 2020-04-10 15:28:01,598 | I | PluginManager.py:67 (load_plugin) | Plugin 'Crosshair' loaded. 2020-04-10 15:28:01,604 | I | PluginManager.py:67 (load_plugin) | Plugin 'Drawing' loaded. 2020-04-10 15:28:01,607 | I | PluginManager.py:67 (load_plugin) | Plugin 'FBrowser' loaded. 2020-04-10 15:28:01,609 | I | PluginManager.py:67 (load_plugin) | Plugin 'Mosaic' loaded. 2020-04-10 15:28:01,610 | I | PluginManager.py:67 (load_plugin) | Plugin 'Preferences' loaded. 2020-04-10 15:28:01,611 | I | PluginManager.py:67 (load_plugin) | Plugin 'Ruler' loaded. 2020-04-10 15:28:01,613 | I | PluginManager.py:67 (load_plugin) | Plugin 'WCSAxes' loaded. 2020-04-10 15:28:01,800 | I | main.py:676 (main) | entering mainloop... 2020-04-10 15:28:06,934 | I | Control.py:2385 (quit) | Attempting to shut down the application... 2020-04-10 15:28:06,938 | I | Control.py:223 (stop) | shutting down Ginga... 2020-04-10 15:28:06,939 | I | main.py:683 (main) | Shutting down...

WSL:

pllim commented 4 years ago

Huh... Do you have a lot of fonts installed? What if you fire up the Python interpreter and run the following? Any of these commands take 40s?

>>> from ginga.fonts import font_asst
>>> font_asst.get_loadable_fonts()
['roboto']
>>> font_asst.get_font_info('roboto')
{'name': 'roboto', 'font_path': 'd:\\...\\ginga\\fonts\\Roboto\\Roboto-Regular.ttf'}

pllim commented 4 years ago

And if those are not slow, what about this?

>>> from ginga.qtw import QtHelp
>>> QtHelp.load_font('roboto',  the_path_you_get)

robertoabraham commented 4 years ago

Nope! Those commands all run more-or-less instantly and seem to produce sensible outputs.

(base) § Blackbird2 {~\Desktop} python
Python 3.7.3 (default, Apr 24 2019, 15:29:51) [MSC v.1915 64 bit (AMD64)] :: Anaconda, Inc. on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> from ginga.fonts import font_asst
>>> font_asst.get_loadable_fonts()
['roboto']
>>> font_asst.get_font_info('roboto')
{'name': 'roboto', 'font_path': 'C:\\Users\\abrah\\Anaconda3\\lib\\site-packages\\ginga\\fonts\\Roboto\\Roboto-Regular.ttf'}
>>> quit()

pllim commented 4 years ago

Maybe @ejeschke knows where to poke at next. I can't reproduce this slowness on my Windows. Thanks for checking!

robertoabraham commented 4 years ago

Your other font suggestion ran OK too:

>>> from ginga.qtw import QtHelp
>>> QtHelp.load_font('roboto',   'C:\\Users\\abrah\\Anaconda3\\lib\\site-packages\\ginga\\fonts\\Roboto\\Roboto-Regular.ttf')

I'll wait to see if Eric can suggest anything, and thanks a million for helping diagnose this!

ejeschke commented 4 years ago

Your other font suggestion ran OK too

Hi Roberto. Is this from WSL though? or the Windows Command (DOS-type) shell?

ejeschke commented 4 years ago

Good guess on the fonts, @pllim! @robertoabraham, just to make sure it is not some other sort of legacy issue unrelated to fonts, can you temporarily rename any .ginga folders from the Home area and let Ginga recreate those? I don't quite remember what the root of that area is under Windows proper, but I suppose it would be the same as under WSL?

robertoabraham commented 4 years ago

Hi Eric,

I was running those commands (to check the font loading) from PowerShell (you can verify it from the windows-style file path for the fonts). The font takes a second or so to load (max).

I just zapped the .ginga file from my home directory and let ginga recreate it and then started up ginga a few times. I still get the same behavior I'm afraid. Here are the first three lines from the run log (from which it seems it takes about 35s to load the font).

(base) § Blackbird2 {~} ginga --loglevel=20 --stderr
2020-04-10 16:22:34,848 | I | main.py:374 (main) | Chosen toolkit (qt5) family is 'qt'
2020-04-10 16:22:36,429 | I | Control.py:171 (__init__) | trying to load bundled font 'roboto'
2020-04-10 16:23:13,154 | I | ModuleManager.py:71 (load_module) | Loading module 'Operations'...

It's very weird!

pllim commented 4 years ago

I don't use PowerShell. I have Git Bash, which can see my Miniconda, and I run everything from Git Bash. I wonder if this is a problem it PowerShell rather than in Ginga. 🤷

robertoabraham commented 4 years ago

I don't think it's PowerShell. I just tried it using cmd.exe (the standard DOS prompt thing) and got the same behavior. I'm starting up python using the items in the Anaconda folder in the start menu. If you think it is worth a try I can uninstall Anaconda and reinstall (though it would be a hassle so I'd rather not unless you're out of ideas).

ejeschke commented 4 years ago

@robertoabraham, do you have a lot of fonts installed on your system?

ejeschke commented 4 years ago

How about running one of the Qt example programs from your git checkout:

python ginga/examples/qt/example2_qt.py  --loglevel=20 --stderr

starts up fast? Dragging a file into the window loads ok?

robertoabraham commented 4 years ago

Well, I'm not sure what counts as a lot of fonts these days! My C:\Windows\Fonts directory has 552 fonts in it. I guess that doesn't seem like a lot to me... but what do I know. Is it a lot?

ejeschke commented 4 years ago

No, that seems quite reasonable. Just asking, because some searches were suggesting that if there are thousands of fonts installed, Qt font management can sometimes get bogged down.

robertoabraham commented 4 years ago

The Qt example program ran pretty quickly. It took perhaps a couple of seconds to start.

(base) C:\Users\abrah\Temporary\ginga>python ginga/examples/qt/example2_qt.py  --loglevel=20 --stderr
2020-04-10 16:45:51,830 | W | ImageView.py:2151 (_scale_to) | Error in scaling: window size undefined
2020-04-10 16:45:51,831 | W | ImageView.py:2151 (_scale_to) | Error in scaling: window size undefined
2020-04-10 16:45:53,829 | I | example2_qt.py:264 (quit) | Attempting to shut down the application...

robertoabraham commented 4 years ago

Hmm... I just noticed that dragging a FITS file into the window of qt/example2_qt.py results in an error. However, loading the file by clicking the 'Open File' button works fine. Not sure if that's relevant or not...

ejeschke commented 4 years ago

Let's check whether this is a problem with just Roboto. Can you pick one of the monospaced fonts that you find in C:\Windows\Fonts (just note the path to the file), and now create a file ginga_config.py in your .ginga directory. It should have the following content:

def init_config(setup):
    from ginga.fonts import font_asst
    font_asst.remove_font('roboto')
    font_asst.add_font("/path/to/some/font/FontName.ttf", font_name='roboto')

Replace the font path with the one from your installation. Start up Ginga as before, and let us know the result. Tnx!

ejeschke commented 4 years ago

Hmm... I just noticed that dragging a FITS file into the window of qt/example2_qt.py results in an error. However, loading the file by clicking the 'Open File' button works fine. Not sure if that's relevant or not...

No, probably a bad assumption about paths in the example drag-drop handler. But we should open a separate ticket about that...

robertoabraham commented 4 years ago

I just tried replacing roboto with courier but I'm afraid it still took forever to load.

(base) C:\Users\abrah>dir .ginga
 Volume in drive C is Windows
 Volume Serial Number is AAC7-0521

 Directory of C:\Users\abrah\.ginga

2020-04-10  04:58 PM    <DIR>          .
2020-04-10  04:58 PM    <DIR>          ..
2020-04-10  04:21 PM               466 general.cfg
2020-04-10  04:58 PM               175 ginga_conf.py
2020-04-10  05:01 PM             4,303 layout
               3 File(s)          4,944 bytes
               2 Dir(s)  306,086,313,984 bytes free

(base) C:\Users\abrah>cd .ginga

(base) C:\Users\abrah\.ginga>type ginga_conf.py
def init_config(setup):
    from ginga.fonts import font_asst
    font_asst.remove_font('roboto')
    font_asst.add_font('C:\\WINDOWS\\FONTS\\COUR.TTF', font_name='roboto')

ejeschke commented 4 years ago

@robertoabraham, appreciate your patience! Could you try copying the fonts from ginga/fonts/Roboto into your Windows font directory? I wonder if installing them makes a difference.

ejeschke commented 4 years ago

I think this ginga_config.py will at least work around trying to load Roboto. On my system it does not show the logger line trying to load any fonts:

def init_config(setup):
    from ginga.fonts import font_asst
    font_asst.remove_font('roboto')
    font_asst.add_alias('fixed', 'Courier')

Does this speed up things?

robertoabraham commented 4 years ago

Hi Eric, I think we have been going down a rabbit hole! So I just edited my ginga_config.py file to not load any fonts as you suggested, and it still is taking a long time to load. Here are the first few lines of the log:

(base) C:\Users\abrah\.ginga>ginga --loglevel=20 --stderr
2020-04-10 17:32:05,308 | I | main.py:374 (main) | Chosen toolkit (qt5) family is 'qt'
2020-04-10 17:32:46,843 | I | ModuleManager.py:71 (load_module) | Loading module 'Operations'...
2020-04-10 17:32:46,850 | I | PluginManager.py:67 (load_plugin) | Plugin 'Operations' loaded.

The slowdown seems to be associated with something going on right after starting main.py, regardless of what that thing is. I smell a rat... maybe something like a virus checker is kicking in or something. I'm going to disable all virus checking temporarily to see if that makes a difference.

ejeschke commented 4 years ago

Hi Eric, I think we have been going down a rabbit hole! So I just edited my ginga_config.py file to not load any fonts as you suggested, and it still is taking a long time to load. Here are the first few lines of the log

Excellent. We'll have to narrow it down further. There was a similar issue posted earlier, for Ginga on Debian. Something about downloading documentation files or astropy files or something. We'll have to try searching the issues...

robertoabraham commented 4 years ago

Well, whatever is going on it's not my virus scanner... I disabled it and rebooted the machine to make sure it was really off, and then re-ran ginga and it still took over 30s to load.

It's a real puzzler. Whatever is going on it appears to happen after this line is logged:

2020-04-10 17:57:05,081 | I | main.py:374 (main) | Chosen toolkit (qt5) family is 'qt'

Anyway, I'm going to drink a beer so no more debugging from me today (but first I'm going to reactivate my virus scanning!). And of course I can always use ginga from WSL.

Thanks so much for looking into this stuff and hope you enjoy your holiday weekend!

Bob

P.S. Not to be a fanboy, but thanks again for Ginga. I really love it.

ejeschke commented 4 years ago

:beer: Cheers!

this is the issue I was thinking about. However, it looks like that was specific to the Debian version and was fixed. I think the next thing to try (whenever you get back to it) is to run the program with --loglevel=10. This is going to generate a lot of output, but what we are mainly interested in is the spot where it pauses for 30 sec.

I think you are right that the font stuff is a red herring. Just FWIW, it would also be useful to know the version of astropy you are using.

robertoabraham commented 4 years ago

Hi Eric,

I got a chance to look into this issue by starting up ginga with --loglevel=10 on my windows laptop again. I've attached a text file with the startup log. The slow bit now appears to be associated with a QT widget, which took 30s. Here's a snippet showing what's going on:

2020-04-22 18:17:16,963 | D | Task.py:1048 (startall) | startall done
2020-04-22 18:17:17,237 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.Splitter object at 0x0000027A464711D0>
2020-04-22 18:17:47,474 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.VBox object at 0x0000027A464AA7B8>
2020-04-22 18:17:47,547 | I | ModuleManager.py:71 (load_module) | Loading module 'Operations'...

Does this help to pin down the issue?

Thanks,

Bob

P.S. Can it be 12 days since I first posted this issue? Man the days blend together when one isn't supposed to leave the house because the coronavirus social distancing.

robertoabraham commented 4 years ago

Oops, I forgot to attach the log in my previous message. Here it is: GingaStartup.txt

ejeschke commented 4 years ago

I think the only thing of significance happening in those lines (in Desktop.py) is that the basic GUI is being constructed (without any plugins). On my Linux laptop the lines look like this:

2020-04-22 16:07:44,065 | D | Task.py:1048 (startall) | startall done
2020-04-22 16:07:44,098 | I | Control.py:168 (__init__) | trying to load bundled font 'roboto'
2020-04-22 16:07:44,108 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.Splitter object at 0x7f2108038090>
2020-04-22 16:07:44,122 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.VBox object at 0x7f20e80185d0>
2020-04-22 16:07:44,133 | I | ModuleManager.py:71 (load_module) | Loading module 'Operations'...

and on my Mac laptop it looks like this:

2020-04-22 16:19:34,445 | D | Task.py:1048 (startall) | startall done
2020-04-22 16:19:34,765 | I | Control.py:170 (__init__) | trying to load bundled font 'roboto'
2020-04-22 16:19:34,774 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.Splitter object at 0x10314f6390>
2020-04-22 16:19:34,958 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.VBox object at 0x10359a1b10>
2020-04-22 16:19:35,175 | I | ModuleManager.py:71 (load_module) | Loading module 'Operations'...

In both cases there is no significant delay in those lines.

@pllim, can you run it on your Windows laptop with --loglevel=10 and add your lines corresponding to the above?

ejeschke commented 4 years ago

I don't use PowerShell. I have Git Bash, which can see my Miniconda, and I run everything from Git Bash. I wonder if this is a problem it PowerShell rather than in Ginga.

I'm beginning to suspect @pllim is right that this has something to do with the environment set up by the shell. @robertoabraham, do you have any students who are seeing this same slow startup?

robertoabraham commented 4 years ago

@ejeschke term just ended so I can't easily check with undergrads (all my grad students and postdocs are using Macs or Linux boxes), but I think what I'll do is find some old Windows machines and install AstroConda on them to see what happens (or maybe I will just nuke my current laptop's setup from orbit and reinstall everything) and see if this goes away. Might take a few days, but it'll happen and I'll report back!

pllim commented 4 years ago

Here's my log. The cursor blinked 4 times and then Ginga loaded.

2020-04-23 10:46:25,589 | D | Task.py:918 (taskloop) | Starting worker thread loop.
2020-04-23 10:46:25,910 | I | Control.py:170 (__init__) | trying to load bundled font 'roboto'
2020-04-23 10:46:25,916 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.Splitter object at 0x0000015A35446DD8>
2020-04-23 10:46:31,561 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.VBox object at 0x0000015A3CB10588>
2020-04-23 10:46:31,590 | I | ModuleManager.py:71 (load_module) | Loading module 'Operations'...

ejeschke commented 4 years ago

That is interesting. Even from @pllim's shell we are seeing a 4-5 second lag during the building of the GUI, whereas on Mac and Linux it's a couple hundred milliseconds at most. @pllim, how about on your work Linux desktop with the same log lines?

ejeschke commented 4 years ago

@robertoabraham, can you post the same lines when launching from WSL?

robertoabraham commented 4 years ago

@ejeschke Sure! Here's the corresponding output when starting ginga from WSL:

ginga_wsl.txt

pllim commented 4 years ago

Definitely a bit faster on RHEL 7:

2020-04-23 15:54:59,360 | D | Task.py:1048 (startall) | startall done
2020-04-23 15:54:59,571 | I | Control.py:170 (__init__) | trying to load bundled font 'roboto'
2020-04-23 15:54:59,649 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.Splitter object at 0x7fa53e33e748>
2020-04-23 15:54:59,658 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.VBox object at 0x7fa53e360fd0>
2020-04-23 15:54:59,697 | I | ModuleManager.py:71 (load_module) | Loading module 'Operations'...

Disclaimer: They are not exactly the same dev versions on both OS, but I don't think that matters that much?

pllim commented 4 years ago

Hmm.. is the startall vs taskloop in the log a significant clue?

pllim commented 4 years ago

Sorry, I was on a PR branch. This is the log from latest master on Windows 10:

2020-04-23 16:02:36,341 | D | Task.py:1048 (startall) | startall done
2020-04-23 16:02:36,341 | D | Task.py:918 (taskloop) | Starting worker thread loop.
2020-04-23 16:02:36,709 | I | Control.py:170 (__init__) | trying to load bundled font 'roboto'
2020-04-23 16:02:36,715 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.Splitter object at 0x00000179858FAEB8>
2020-04-23 16:02:43,334 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.VBox object at 0x000001798CE30550>
2020-04-23 16:02:43,360 | I | ModuleManager.py:71 (load_module) | Loading module 'Operations'...

ejeschke commented 4 years ago

Here's @robertoabraham's extract from the WSL startup:

2020-04-23 15:49:30,762 | D | Task.py:1048 (startall) | startall done
QStandardPaths: XDG_RUNTIME_DIR not set, defaulting to '/tmp/runtime-abraham'
2020-04-23 15:49:30,799 | I | Control.py:171 (__init__) | trying to load bundled font 'roboto'
2020-04-23 15:49:30,819 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.Splitter object at 0x7fb180081160>
2020-04-23 15:49:30,826 | D | Desktop.py:264 (switch_page_cb) | page switch: <ginga.qtw.Widgets.VBox object at 0x7fb1800b01d0>
2020-04-23 15:49:30,891 | I | ModuleManager.py:71 (load_module) | Loading module 'Operations'...

So a HUGE difference, about 10 milliseconds between the two Desktop.py calls...

ejeschke commented 4 years ago

Hmm.. is the startall vs taskloop in the log a significant clue?

I don't think so. The lag comes in Desktop.py which is the module that builds the "desktop" (outer shell) of the GUI, without any plugins. My guess is that somehow there is a lag associated with instantiating the particular combination of Qt widgets when invoked from the non-WSL Windows environment. On the other platforms, and from WSL, the time lag is negligible.

ejeschke / ginga

Slow startup on Windows #832