Match books infinite loop and then crash calibre

[Armin Geller]

Hello Kovid,
I got an infinite loop by matching books to library from a connected folder (ADE folder) with the calibre new release 5.13. I'll then run calibre then in debug mode with the same result. The book was imported before with calibre 5.12. The files within connected folder are mostly DRM protected.

What I did:
->connect to folder ->select device ->select a book in the list -> right click ->match book to library ->search

calibre 5.13 Windows x64bit
OS: Windows 10 x64 pro, Version 20H2, all updates included

I add a screenshot, the log file from debug mode and both, the database file from the main library and from the connected folder (.metadata.calibre and .driveinfo.calibre).

Best regards,
Armin

[Armin Geller (armingeller)]

I just recognize that it seems calibe is modifying the .metadata.calibre file in a way that destroy the entries for matching books in the library w/o that I had ask for it. The file size grows from former 8 MB to actual 25.77MB. I add the file too. Maybe you have an idea what is going on.

Best regards,
Armin

[Kovid Goyal (kovid)]

Does it happen if you run calibre as

calibre --ignore-plugins

[Kovid Goyal (kovid)]

Also if you remove the file c´t.pdf from the folder and delete the metadata.calibre file, does the problem stop?

[Kovid Goyal (kovid)]

And looking at your growing metadata.calibre it is growing because lots of custom column metadata is present in it, presumably because you ran the matching against a library with lots of custom column metadata. Are you running the matching against a different library from before?

[Kovid Goyal (kovid)]

Changing the component for this bug.

 assignee cbhaley
 status triaged

[Kovid Goyal (kovid)]

@Charles: You have any idea if user_metadata is stored in .metadata.calibre for a reason?

[Charles Haley (cbhaley)]

The original rationale was that all metadata should be there so that calibre could use it to re-import the book. However, that never happened. I don't know if any non-calibre app uses the data.

[Charles Haley (cbhaley)]

I can't make this fail. Steps I tried:
1) Copy the metadata.db file to a temp library.
2) Create a temp folder for the folder device.
3) Start calibre on the temp library.
4) Add an empty format to the book "Das Buch der Zukunft", the one mentioned in the image
5) Connect to the temp folder
6) Send "Das Buch der Zukunft" to the folder
7) Restart calibre
8) Connect to folder
9) In the device view, right click on "Das Buch der Zukunft" and select "Match book to library"
10) In the dialog, press Search. It finds the correct book.

I am also unable to make it fail on my normal test library.

I don't know where to go from here.

[Armin Geller (armingeller)]

Sorry for my delay, it took some time to test.

1. Does it happen if you run calibre as calibre --ignore-plugins?
--> Yes

2. Also if you remove the file c´t.pdf from the folder and delete the metadata.calibre file, does the problem stop?
--> 1. attempt: renaming metadata.calibre, wait for new building it and then match book "Das Buch der Zukunft" --> same problem, infinite loop
--> 2. attempt: renaming metadata.calibre, remove all c´t*.pdf files, wait for new building it and then match book "Das Buch der Zukunft" --> same problem, infinite loop

3. ...library with lots of custom column metadata. Are you running the matching against a different library from before?
--> Yes, the data are matched between two libraries named "Calibre Bibliothek" (have lots of custom column metadata) and "Calibre Magazine" (only a view custom column metadata). Both databases are used since years (start 2010/2011) with this setup. The documents a for "Calibre Bibliothek" books and documents and for "Calibre Magazine" magazine documents, means also that you have no documents in both libraries

4. --> More information:
I switch from 4.23 to 5.12 beginning this month and did today the update to 5.13 this month and updated all plugins as well to the actual versions. Worked w/o problems since this morning before updating, at least I didn't recognizing that there is/was a problem before today.

[Armin Geller (armingeller)]

Additional check:
1. Create a new library with all custom column from existing library
2. Connect to directory Digital Editions
3. Send file to new library
4. Match book -->work

Next:
1. Create a new library, copy metadata.db, metadata_db_prefs_backup.json and all books of Author from existing library to the new library
2. Connect to directory Digital Editions
3. Match book --> infinite loop

Next:
1. Create a new library, copy metadata.db, metadata_db_prefs_backup.json and all books of Author from existing library to the new library, then delete book "Das Buch der Zukunft"
2. Connect to directory Digital Editions
3. Send file to new library
3. Match book --> infinite loop

Remark, If not mentioned before, the book in folder "Digital Editions" have DRM and was send via known plugin. Opening this book in calibre viewer work.

This leave me to the question are you maybe try to open the book in folder "Digital Editions" before matching something (only a silly idea)

[Charles Haley (cbhaley)]

What is in Preferences / Searching / General tab / What to search by default? Is the "Limit search metadata" box checked? If so, what is in the dialog box "Columns that non-prefixed searches are limited to"?

If the "Limit Search metadata" is not checked, then what happens if you check it and set the "Column ..." box to "title, author, series, rating, publisher, tags"?

My concern is the custom column "Vitruelle Bibliothek". In the past we have seen problems with the "virtual_libraries()' function, and I am wondering if that is what we are seeing now. Changing the "Limit search..." checkbox will tell search not to look at that column.

[Armin Geller (armingeller)]

Is the "Limit search metadata" box checked?
   -->no. this checkbox wasn't checked

Next:
When I check it --> Match book works
    "title, authors, tags, series, publisher" is what is listed.

Next check:
When I check it, adding "#in_virtual_library" in addition, then
   --> Match book infinite loop
   --> In addition search in main GUI window also went into infinite loop

BTW, is it normal that I can't expand the list box for "title, authors, tags, series, publisher"? (See picture CalGuiGlitches3.PNG)

Your concern is correct, this seems to be the root of the problem. My conclusion for now: I will check restricted search for the future. At least as a workaround for this problem.
Thank you for pointing me to this once more. I remember now that we had some years ago a conversation about this function (that I use quite regular and is very helpful for me). But it seems it come with a cost impact. I wonder why this happen just now with the new release, maybe out of a pure case.

Now only one point is open, why was there a huge increase in .metadata.calibre? I had not updated those metadata. Looking in the file I see a lot of "Alice's Adventures in Wonderland - Lewis Carroll" Metadata linked to book files that I definitely had not updated since very long time (means for years)

While testing I found two additional little GUI glitches that is worth looking for some when in the future. It seems that some descriptions for text fields are restricted too much. I put three screenshots in a zip file.

[Charles Haley (cbhaley)]

@kovid, I think that when the LRU cache for searches is too small then things there is a knee; things work then immediately don't work. In this case there are 20 VLs and some 14 composite columns, which if I read the code correctly is 280 cache items per search (each column * number of libraries). The number of items in the cache is 50. Perhaps we are seeing cache churning.

I suspect that if @armingeller let it run (if possible) then it would eventually complete. That is what happened for me when I tried my VL DatabaseClosed plugin; it took nearly 30 minutes.

So the question: what do we do? I see four choices:
1) remove the virtual_libraries() function because it creates difficulties.
2) add a timer to *something* so that cache churning is detected. I don't know what "something" is.
3) add an explanation to the documentation saying that corner cases exist and otherwise change nothing.
4) increase the cache size to something a lot larger.

I don't know what is the best choice. Option 1 - remove the virtual-libraries() function: this isn't an unacceptable option because my "virtual libraries to column" plugins do the same computation on demand, but it would certainly break some working libraries. I have ho idea how many people that might affect. Option 2 - timer is a good choice if it can be made reliable. Option 3 is probably useless because most people don't read the docs. Option 4 would change the problem from churning to out-of-memory, which might be more understandable.

Or some other choice ...

What do you think?

[Kovid Goyal (kovid)]

1) I was never a fan of virtual_libraries() but given that it exists and has been in use for a while, I think we cant remove it anymore.

2) Possible, you mean in __call__ in search.py?

3) This should possibly be done regardless if we are not doing (1)

4) I'm not really a fan of imposing a large memory cost on all users to facilitate the few that use virtual_libraries()
However, one thing that could be done is to move the LRUCache to the python builtin functools.lru_cache implementation, which might be a bit faster, no idea would need benchmarking.

[Kovid Goyal (kovid)]

Regarding caching, one could possibly parse the search expression to check if it uses virtual_libraries() and if it does temporarily increase cache size while evaluating the search expression.

[Charles Haley (cbhaley)]

Two thoughts:

1) In this case the virtual_libraries() problem could be a red herring. It might be the naked search & lots of metadata. But putting that aside ...

2) We can solve the virtual_libraries() problem by introducing another cache. The current implementation of the method db.cache.books_in_virtual_library() loops through all the VLs, depending on the search cache for performance. Instead we could build a cache {id: {vls_for_id}} then return the result from that. Building the cache wouldn't be slower than one pass through the existing method, and future calls would be *much* faster. The new cache would be cleared by db.cache.clear_caches(), and in particular by clear_search_caches(). This new cache would add memory only when virtual_libraries() is used.

Unless you object I will look at this later today.

[Armin Geller (armingeller)]

Good morning, just read your comments.

@Charls, I can confirm, it took 39 minutes to complete after I start it once more this morning. Need to admit that I didn't check if running the process will come to an result. The longest duration I had this run was about ~20 minutes and thought calibre stop working.

From a user view it also would help to giving the user an information/feedback that, if this function is involved in a search and this search took longer as usual (maybe if running longer than a half minute or what ever is a good duration). Maybe pointing out a notice that collecting results will take very long with an indication that the process is still running and nothing is broken during runtime. Then user know, this is not an error but expected behavior because I use this function. Something like that.

Thanks for spending your time finding a solution on this, it is very appreciated from me.

[Kovid Goyal (kovid)]

I'm OK with a dedicated cache for it.

[Charles Haley (cbhaley)]

Using @armingeller's database, the new cache improves the performance of the virtual_libraries() function by approximately 900 times. (!)

The numbers:
First cache loading: new=382,352 ms
First cache loading: old=368,381 ms (this is the first search)

Typical lookup: new= 185 ms
Typical lookup: old= 165,338 ms

The improvement on my test database that has many fewer VLs isn't as large, approximately 200 times.

First cache loading: new=7,846 ms
First cache loading: old=7,852 ms

Typical lookup: new= 1 ms (actually 800 ns)
Typical lookup: old= 195 ms

The actual times will be less because the print statement takes measurable time.

[Charles Haley (cbhaley)]

Sorry, I got the lookup time numbers wrong for the large lib. They are substantially better after I improved the cache lookup.

First: ms == microseconds, not milliseconds.

The right numbers:
Typical lookup: new= 1 ms
Typical lookup: old= 165,338 ms

The cache is 165,000 times faster.

[Kovid Goyal (kovid)]

Fixed in branch master. The fix will be in the next release. calibre is usually released every alternate Friday.

 status fixreleased

[Charles Haley (cbhaley)]

@rmingeller: see Preferences / Tweaks / "Edit metadata custom column label width and elision point (ID: metadata_edit_elide_labels)" to change the label length.

The dropdown problem in Preferences / Searching seems to be a regression that needs looking at.

[Armin Geller (armingeller)]

Charles and Kovid,
Thanks a lot for the fix. This sounds promising. I will report how it works for my library as soon as the new release is available.

Thanks for the hint with the tweaks setting. This one was new for me. Works fine too.

[Armin Geller (armingeller)]

Charles and Kovid,
this update turns out really good. Matching books is much faster now. Feels like searching in general is faster too. Thanks a lot.
Best regards, Armin