ginga Slow startup on Windows

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

Apr 10 '20 18:04 robertoabraham

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.

Apr 10 '20 18:04 pllim

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.

Apr 10 '20 18:04 robertoabraham

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?).

Apr 10 '20 19:04 robertoabraham

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

Apr 10 '20 19:04 pllim

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:

Apr 10 '20 19:04 robertoabraham

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'}

Apr 10 '20 19:04 pllim

And if those are not slow, what about this?

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

Apr 10 '20 19:04 pllim

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()

Apr 10 '20 19:04 robertoabraham

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

Apr 10 '20 19:04 pllim

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!

Apr 10 '20 19:04 robertoabraham

Your other font suggestion ran OK too

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

Apr 10 '20 20:04 ejeschke

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?

Apr 10 '20 20:04 ejeschke

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!

Apr 10 '20 20:04 robertoabraham

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. 🤷

Apr 10 '20 20:04 pllim

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).

Apr 10 '20 20:04 robertoabraham

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

Apr 10 '20 20:04 ejeschke

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?

Apr 10 '20 20:04 ejeschke

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?

Apr 10 '20 20:04 robertoabraham

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.

Apr 10 '20 20:04 ejeschke

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...

Apr 10 '20 20:04 robertoabraham

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...

Apr 10 '20 20:04 robertoabraham

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!

Apr 10 '20 20:04 ejeschke

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...

Apr 10 '20 20:04 ejeschke

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')

Apr 10 '20 21:04 robertoabraham

@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.

Apr 10 '20 21:04 ejeschke

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?

Apr 10 '20 21:04 ejeschke

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.

Apr 10 '20 21:04 robertoabraham

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...

Apr 10 '20 21:04 ejeschke

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.

Apr 10 '20 22:04 robertoabraham

: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.

Apr 10 '20 23:04 ejeschke

ginga ginga copied to clipboard

Slow startup on Windows

ginga
ginga copied to clipboard