Calibre 7.3/7.4 hangs during starting up

[kovidgoyal]

Also when it hangs what does task manager say?

Also can you run it as

calibre-debug -g

and reproduce and post whatever is output in the command prompt

[BetterRed]

Originally Posted by chaley

Do you have a view applied at startup?

Yes, all my libraries have a VM View applied.

The problem reproduces in Safe mode.

Some books in the two libraries that exhibit the problem have data folders, whereas none of the books in the libraries that don't have the problems have data folders. But it seems unlikely that data folders would be a problem in the cover grid view and not in the list view… where they have an icon.

I wonder if the OPs problem library has data folders?

Hmmm - if I delete %appdata%\calibre\Cache\gui-thumbnail-cache before starting calibre the problem does not manifest at startup, but it comes back again on a library switch - by which time the gui-thumbnail-cache has been created and had a some data added.

I've attached screen shots of my L&F-Cover grid settings, the Emblems tab is empty.

BR

[BetterRed]

Originally Posted by kovidgoyal

Does it reproduce with

calibre --ignore-plugins

Yes - but maybe less erratically…

[chaley]

@kovid: although I can't reproduce it, given what BR says I suspect it is related to setting the current index to row zero in init.finalize_layout(). It does it by setting a oneshot timer(0). This introduces a possible timing issue with ui.post_initialize_actions(). Which of the two goes first, and is the answer deterministic? You can see when the timers fire by when the selected book jumps, changing the book in book details. In BR's case the book jumps but book details isn't changed. The jump is caused by the timer. The selection for book details is inline, not in the timer method.

I tried moving the code to set the current row to zero from finalize_layout() to post_initialize_actions(). Nothing broke. Of course, nothing was fixed either.

Also, the view manager will "do its thing" at .initialization_complete(). which happens before the oneshots are processed. I don't know if that could confuse things, in particular the choosing of the currently selected row and the signals related to book details.

[chaley]

Hmmmm ... If it happens with switch library then the argument I made above is likely bogus. That code isn't run by switch_libary.

[kovidgoyal]

Originally Posted by chaley

Hmmmm ... If it happens with switch library then the argument I made above is likely bogus. That code isn't run by switch_libary.

Yes, I was considering only switch library since that eliminates a whole bunch of startup related complexity.

[BetterRed]

Originally Posted by kovidgoyal

Also when it hangs what does task manager say?

"calibre.exe is not responding"

Originally Posted by kovidgoyal

Also can you run it as

calibre-debug -g

and reproduce and post whatever is output in the command prompt

calibre 7.4  embedded-python: True
Windows-10-10.0.19045-SP0 Windows ('64bit', 'WindowsPE')
('Windows', '10', '10.0.19045')
Python 3.11.5
Windows: ('10', '10.0.19045', 'SP0', 'Multiprocessor Free')
Interface language: None
Successfully initialized third party plugins: BRMenu Menu (1, 2, 0) && Count Pages (1, 13, 4) && Drop Search Results (1, 0, 14) && Favourites Menu (1, 3, 0) && Job Spy (1, 0, 239) && Modify ePub (1, 8, 2) && Scroll Book Details (1, 0, 2) && View Manager (1, 10, 2)
QPA platform: windows
devicePixelRatio: 1.5
logicalDpi: 96.0 x 96.0
physicalDpi: 104.87741935483871 x 104.50285714285712
ApplicationPaletteChange event ignored
Using calibre Qt style: True
[0.00] Starting up...
[0.00] Initializing db...
[0.05] db initialized
[0.05] Constructing main UI...
qt.gui.imageio: libpng warning: iCCP: known incorrect sRGB profile
qt.gui.imageio: libpng warning: iCCP: cHRM chunk does not match sRGB
[0.98] GUI main window shown
Job Spy has begun initialization...
orig_option = prefs.get[option_key]:  True
Tweak Library Name:  Models
'read_file_metadata' global.py file prefs.set  FROM:  True  TO:  True
'read_file_metadata' global prefs[option_key] value changed FROM:  True  TO:  True
author_sort_copy_method >>> default tweaks.py method is:  invert
author_sort_copy_method changed FROM:  invert  TO:  copy
current  tweaks['title_series_sorting']:  library_order
--->>>apply_title_series_sorting_by_library:   libname is NOT tweaked; default value used for:    Models    is:  library_order
title_series_sorting changed FROM:  library_order  TO:  library_order
Calibre, and hence Job Spy, was gracefully shut down last time?  False
Last time daemon started:  never
Last time daemon failed:  never
Total daemon starts inception_to_date:  0
Total daemon failures inception-to-date:  0
qt.gui.imageio: libpng warning: iCCP: known incorrect sRGB profile
JS: ===>>> change_gui_alternating_row_colors()
Job Spy has finished initialization...
[1.48] main UI initialized...
[1.48] Started up in 1.48 seconds with 171 books

And it's wedged.

Here's another one with a library switch to my Creators library

calibre 7.4  embedded-python: True
Windows-10-10.0.19045-SP0 Windows ('64bit', 'WindowsPE')
('Windows', '10', '10.0.19045')
Python 3.11.5
Windows: ('10', '10.0.19045', 'SP0', 'Multiprocessor Free')
Interface language: None
Successfully initialized third party plugins: BRMenu Menu (1, 2, 0) && Count Pages (1, 13, 4) && Drop Search Results (1, 0, 14) && Favourites Menu (1, 3, 0) && Job Spy (1, 0, 239) && Modify ePub (1, 8, 2) && Scroll Book Details (1, 0, 2) && View Manager (1, 10, 2)
QPA platform: windows
devicePixelRatio: 1.5
logicalDpi: 96.0 x 96.0
physicalDpi: 104.87741935483871 x 104.50285714285712
ApplicationPaletteChange event ignored
Using calibre Qt style: True
[0.00] Starting up...
[0.02] Initializing db...
[0.19] db initialized
[0.19] Constructing main UI...
qt.gui.imageio: libpng warning: iCCP: known incorrect sRGB profile
qt.gui.imageio: libpng warning: iCCP: cHRM chunk does not match sRGB
[1.30] GUI main window shown
Job Spy has begun initialization...
orig_option = prefs.get[option_key]:  True
Tweak Library Name:  Books
'read_file_metadata' global.py file prefs.set  FROM:  True  TO:  True
'read_file_metadata' global prefs[option_key] value changed FROM:  True  TO:  True
author_sort_copy_method >>> default tweaks.py method is:  invert
current  tweaks['title_series_sorting']:  library_order
--->>>apply_title_series_sorting_by_library:   libname IS tweaked; new value for:  Books    is:  library_order
title_series_sorting changed FROM:  library_order  TO:  library_order
Calibre, and hence Job Spy, was gracefully shut down last time?  True
Last time daemon started:  never
Last time daemon failed:  never
Total daemon starts inception_to_date:  0
Total daemon failures inception-to-date:  0
qt.gui.imageio: libpng warning: iCCP: known incorrect sRGB profile
JS: ===>>> change_gui_alternating_row_colors()
Job Spy has finished initialization...
[1.69] main UI initialized...
[1.69] Started up in 1.69 seconds with 5 books
author_sort_copy_method >>> default tweaks.py method is:  invert
apply_author_sort_method_by_library:   libname is NOT tweaked; nothing changed:    Creators
orig_option = prefs.get[option_key]:  True
Tweak Library Name:  Creators
'read_file_metadata' global.py file prefs.set  FROM:  True  TO:  True
'read_file_metadata' global prefs[option_key] value changed FROM:  True  TO:  True
executing:  self.maingui._spare_pool.shutdown(wait_time=60.0)
Successful; forced the upcoming new pool to reload global preference 'read_file_metadata' just tweaked here per-Library...
current  tweaks['title_series_sorting']:  library_order
--->>>apply_title_series_sorting_by_library:   libname is NOT tweaked; default value used for:    Creators    is:  library_order
title_series_sorting changed FROM:  library_order  TO:  library_order

And it's wedged

BR

[BetterRed]

I'm going to do a backup, in case I break something, shouldn't take long - it's and incremental backup

BR

[kovidgoyal]

@BR: I meant is the CPU usage high? That is, is calibre.exe in some kind of loop or just stuck.

[BetterRed]

Originally Posted by kovidgoyal

@BR: I meant is the CPU usage high? That is, is calibre.exe in some kind of loop or just stuck.

It's stuck, wedged in my vernacular

[chaley]

@kovid: it failed for me a few times. It is extremely timing dependent. Putting in print statements seems to often avoid the failures.

I was able to trace it to some sort of hang in the cover cache. The view was fully initialized after the library change and render_covers() was called. At that point things froze, by the looks of things deadlocked (no processor time). When it failed it seems not to render any covers.

Putting prints into the render thread "fixed" it. I never got a failure despite 30-40 attempts.

BTW: what is self.pixmap_staging[] used for in CoverCache. As far as I can tell covers are added to a list then never used. Is this some way to avoid garbage collecting covers?

[kovidgoyal]

Yeah, it prevents the QPixmap objects from being garbage collected in case they are removed from a non GUI thread. It might causes crashes if their destructors run on a non-GUI thread. Do you suspect the deadlock being there? Its a pretty simple class but you can try changing the Lock to an RLock.

[chaley]

Originally Posted by kovidgoyal

Yeah, it prevents the QPixmap objects from being garbage collected in case they are removed from a non GUI thread. It might causes crashes if their destructors run on a non-GUI thread. Do you suspect the deadlock being there? Its a pretty simple class but you can try changing the Lock to an RLock.

I think I found it. It doesn't involve RLock.

The method alternate_view.render_cover is called in the render thread, not the GUI thread. With this code (the print statements), when it fails I see only the first message. I have never seen a failure if the second message appears.

        ...
        print(f'render_cover has_cover: {has_cover}')
        if has_cover:
            p = QImage()
            p.loadFromData(cdata, CACHE_FORMAT if cdata is tcdata else 'JPEG')
            print(f'render_cover p.isNull: {p.isNull()}, cdata is tcdata:{cdata is tcdata}')
            p.setDevicePixelRatio(dpr)

What this tells me is that QImage.loadFromData() isn't thread-safe and can deadlock. This is consistent with some Qt posts that say that Qt data structures should be manipulated in the GUI thread, or at least in a QThread.

I see three possible fixes:

1. Build the data structures in the GUI thread before render_covers. This isn't practical because it would eliminate the advantage of the cache.
2. Use a cross-thread callback function to build the QImage in the GUI thread. This should work but might have performance problems because of signal overhead.
3. Use a QThread instead of a Thread. I have no idea if this would really work, and in any event is a bother to set up with queues.

I tried the second option. It seems to work, or better said it didn't hang in many (!) attempts. Performance seems acceptable, expecially given it is a one-time call per cover. I didn't look hard to see if there are any other Qt image/file operations outside the GUI thread.

A patch file is attached. I can do it as a PR if you would rather.

[kovidgoyal]

Qt in general is not thread safe, but QImage is supposed to be, see https://doc.qt.io/qt-6/threads-modules.html

That is in fact the reason the code uses QImage rather than QPixmap even though QPixmap is faster to render. That said, there could well be a regression in newer Qt that breaks the supposed thread safety of QImage. See for example: https://bugreports.qt.io/browse/QTBUG-90629

There are two QImage operations performed in the render thread, loading from data and resizing to create the thumbnail. If we don't trust QImage to be thread safe, probably best to move both into the GUI thread and just load the JPEG data into memory in the render thread. Or maybe have the render thread do resizing using PIL instead of Qt, that should cause the least loss of performance. PIL could output the thumbnail data in 32bpp format and it can be loaded into the QImage without copying using the QImage(uchar...) constructor. Or ditch QImage and use QPixmap (since we are now on the GUI thread) having PIL output in XPM or uncompressed PNG.

Needs some thought/experimentation.

Coming to your patch, its hard to know if it actually fixes the issue or just changes timing. If we have identified QImage not being thread safe as the culprit, then I would rather remove QImage completely from the render thread if that can be done performantly. I will look at it when I have some time, feel free to experiment further yourself if you want to, I will post here when I start working on it.

[JSWolf]

What changed between calibre 7.2.0 and the later versions that 7.2.0 doesn't hang while the newer versions do?