Calibre Companion Very Long Syncs with 2 Devices

[JimmXinu]

Hi,

I've been using Calibre Companion for a while to sync my two Android devices (Nexis 7 & Droid RAZR Max) as wireless devices. It's always taken a while connect and sync up, but lately it's become unacceptably long.

The progress bar dialog:
Syncing with calibre...
Receiving metadata from calibre

...used to step through my 2700+ books by 10s and take a few minutes, which was inconvenient but acceptable. Now it's taking a bit less than 1 sec per book raising the total time to about 30 minutes.

That's fine as a one time thing, which it seems to be if I connect the same device again. Connecting the same device again sees a very short sync time--which is a great improvement.

But when I connect the other device, it does the full 30+ minute update again.

Is there anything I could do in my setup to address this issue?

Otherwise, I speculate that the new feature added in Version 3.2.1 to avoid sending metadata every time doesn't take multiple devices into account.

I'd appreciate any help you can give me, thanks.

[chaley]

It should not matter if more than one device is used. The cache should be the union, in that the second connect of either will be faster. Unfortunately, you are saying that this isn't the case.

Could you post a calibre debug log showing connects from each device in sequence? That will establish (I hope) which one is clearing the cache. If you are willing to take the time, an pair of connects from each one would be better (device 1, 1, 2, 2).

[JimmXinu]

Originally Posted by chaley

Could you post a calibre debug log showing connects from each device in sequence? That will establish (I hope) which one is clearing the cache. If you are willing to take the time, an pair of connects from each one would be better (device 1, 1, 2, 2).

Attached is log of attaching the Nexus 7 twice, then the Droid twice, then the Droid again after restarting calibre. The Droid had been the last connected device before I started.

I annotated a couple things and removed the majority of the "sync_booklists sending metadata for book" lines because I didn't think they'd be relevant.

Interesting, it's sending data for 2775 books, but my library is 2834, 2833 of which should be synced on both devices.

It may be unrelated, but the CC on Nexus reports it has 3305 books and the Droid 2834. A quick perusal of list in CC the Nexus finds duplicates where both "The Title.epub" and "Title, The.epub" are included. But they are aren't reported as duplicates in calibre when attached as a Wireless Device.

I'm happy to run more test cases as needed or provide 'unabridged' debug logs if you think it would help.

[chaley]

Thanks for the logs. I think I understand what is happening. I am traveling so I can't look at the code to verify my theory.

From what I see in the logs, calibre's cache is (mostly) up to date for both devices. CC is sending very little metadata up to calibre in all of the connections. However, calibre is sending metadata back to device B if you had just connected device A. What that:book2: means is that the last modified date for the books changed when you changed devices. My theory: reading list is doing something to a custom column when it syncs with a device that causes the lastmod dates of ask the books in the list to change such as altering a custom column, perhaps to itself. The second time you sync, reading list doesn't have any work to do so no dates get changed. When you connect a different device, reading list processes the new device again changing the last mod dates. Metadata is sent because the last mod dates have changed since the last send.

The easy test is to disable reading list and see if the problem goes away. Alternatively you could look for something that is changing last mod dates, such as changing the template for a composite custom column. Alternatively squared, look at the last mod date to see if it changed after a connect of a different device.

[JimmXinu]

The last_modified timestamp shows more updated today than I would have expected, but only 50 odd, not 2700+.

Since you pointed to the calibre side of the connection, I added additional debug output to _metadata_already_on_device in smart_device_app/driver.py. What it indicates is that the vast majority of updates are due to the thumbnail size being different. Going from Nexus 7 to Droid, it's (usually) 320 vs 160 and then going from Droid to Nexus 7, 160 vs 320.

Looking at my devices, the Nexus was configured to use Large and Normal thumbnails and the Droid Normal and Small for different things. Changing all the cover size settings to 'Medium' in both Droid and Nexus as a compromise (Cover size in books details doesn't offer 'Normal'?) solves the problem.

So it appears the root cause is that in calibre the thumbnail is saved in the same place for all smart devices while different devices can require different sizes?

[chaley]

Good! I wasn't totally happy with my theory, correctly so as it turns out.

IIRC since version 3 CC has stored 320 pixel thumbnails for all devices, dynamically resizing them as needed for displaying. The 160 px thumbs setting came from previous installations. Changing the displayed thumb size in any way would change the stored size to 320. Now that you have changed the size on the droid it will store 320 px thumbs, so you can now change the two devices to use whatever size you want without "breaking" metadata syncing.

I will look at what it will take to cache per device. I haven't wanted to use the device UUID, for what are probably silly reasons.

[K8HW]

Originally Posted by chaley

Thanks for the logs. I think I understand what is happening. I am traveling so I can't look at the code to verify my theory.

From what I see in the logs, calibre's cache is (mostly) up to date for both devices. CC is sending very little metadata up to calibre in all of the connections. However, calibre is sending metadata back to device B if you had just connected device A. What that means is that the last modified date for the books changed when you changed devices. My theory: reading list is doing something to a custom column when it syncs with a device that causes the lastmod dates of ask the books in the list to change such as altering a custom column, perhaps to itself. The second time you sync, reading list doesn't have any work to do so no dates get changed. When you connect a different device, reading list processes the new device again changing the last mod dates. Metadata is sent because the last mod dates have changed since the last send.

The easy test is to disable reading list and see if the problem goes away. Alternatively you could look for something that is changing last mod dates, such as changing the template for a composite custom column. Alternatively squared, look at the last mod date to see if it changed after a connect of a different device.

Hi Chaley. I was having trouble since the last upgrade of CC and Calibre. It was taking a VERY long time to sync with my Nexus and I ended up with over 100 duplicate books in the process.

After reading this post, I tried to disable "Reading List" but Calibre won't let me. I removed the plugin and it looks like it solved my problems. The reading list only had 27 books and I don't know why I was getting all the duplicates. I discovered the duplicates could be corrected by using the menu item look for books without files. Too bad about the plugin as I really used "Reading List" a lot!

Thanks once again for a great app and excellent support!

~Dave

[chaley]

@JimmXinu and @K8HW: I have found a problem with the caching stuff that might explain some of what you are seeing.

I am using the book's UUID (unique ID) and the extension of the format file to determine whether a book is in the cache. Unfortunately that will fail if the same format of the same book is on the device more than once, which can happen if you are naming books in the normal calibre fashion. Example: "Tempest, The.epub" and "The Tempest.epub" could both be on the device. As it is today, the cache will contain one of these and both books from the device will match that book. You would not see duplicates, and I think that the metadata for one of the books will not be updated.

Could this behavior explain anything you saw or are seeing?

[K8HW]

Originally Posted by chaley

@JimmXinu and @K8HW: I have found a problem with the caching stuff that might explain some of what you are seeing.

I am using the book's UUID (unique ID) and the extension of the format file to determine whether a book is in the cache. Unfortunately that will fail if the same format of the same book is on the device more than once, which can happen if you are naming books in the normal calibre fashion. Example: "Tempest, The.epub" and "The Tempest.epub" could both be on the device. As it is today, the cache will contain one of these and both books from the device will match that book. You would not see duplicates, and I think that the metadata for one of the books will not be updated.

Could this behavior explain anything you saw or are seeing?

I guess that behavior seems to make sense. What would be the solution?

From what I am experiencing now, I will only be using my Nexus with Calibre Companion for now. After removing the "Reading List" plugin, everything seemed to OK. This afternoon I had Calibre Companion sync with my NookColor and it took almost an hour! I tried it again and all is well. Well, I must be a masochist because I just synced with the Nexus and it took about 18 minutes and I ended up with 98 books with missing files.

Do you think it would fix it if I erased ALL the books from both devices and started from scratch? Or would I have to change the way the books are named?

[JimmXinu]

Originally Posted by chaley

I am using the book's UUID (unique ID) and the extension of the format file to determine whether a book is in the cache. Unfortunately that will fail if the same format of the same book is on the device more than once, which can happen if you are naming books in the normal calibre fashion. Example: "Tempest, The.epub" and "The Tempest.epub" could both be on the device. As it is today, the cache will contain one of these and both books from the device will match that book. You would not see duplicates, and I think that the metadata for one of the books will not be updated.

I have seen that behavior, but it's not the main problem I was having.

I did see duplicate books on my devices of the form "Tempest, The.epub" and "The Tempest.epub". Deleting all the books without files cleared most or all of them, however. I think I have a 1 book discrepancy on one device now.

The main problem I was having was very clearly to do with the thumbnail size. I added _debug calls to _metadata_already_on_device in calibre/devices/smart_device_app/driver.py and it was clear: One device wanted thumbnails 320px high and the other 160px high and the thumbnail in calibre was which ever was called for last.

Spoiler:

    def _metadata_already_on_device(self, book):
        try:
            v = self.known_metadata.get(book.lpath, None)
            if v is not None:
                if v.get('uuid', None) != book.get('uuid', None):
                    self._debug("uuid(v:%s book:%s"%(v.get('uuid', None),book.get('uuid', None)))
                if v.get('last_modified', None) != book.get('last_modified', None):
                    self._debug("last_modified(v:%s book:%s"%(v.get('last_modified', None),book.get('last_modified', None)))
                # Metadata is the same if the uuids match, if the last_modified dates
                # match, and if the height of the thumbnails is the same. The last
                # is there to allow a device to demand a different thumbnail size
                if (v.get('uuid', None) == book.get('uuid', None) and
                        v.get('last_modified', None) == book.get('last_modified', None)):
                    v_thumb = v.get('thumbnail', None)
                    b_thumb = book.get('thumbnail', None)
                    if bool(v_thumb) != bool(b_thumb):
                        self._debug("thumbnail(v:%s book:%s"%(bool(v.get('thumbnail', None)),bool(book.get('thumbnail', None))))
                        return False
                    if v_thumb==None or v_thumb[1] != b_thumb[1]:
                        self._debug("thumbnail(v:%s v[1]:%s book[1]:%s"%(bool(v_thumb), v_thumb[1], b_thumb[1]))
                    return not v_thumb or v_thumb[1] == b_thumb[1]
            else:
                self._debug("v:None")
        except:
            traceback.print_exc()
        return False

Output:

SMART_DEV (  81.61:  0.000) _metadata_already_on_device thumbnail(v:True v[1]:320 book[1]:160
SMART_DEV (  81.63:  0.000) _metadata_already_on_device thumbnail(v:True v[1]:320 book[1]:160
SMART_DEV (  81.64:  0.000) _metadata_already_on_device thumbnail(v:True v[1]:320 book[1]:160
... (repeat many times) ...
... then when connecting other device ...
SMART_DEV ( 350.12:  0.269) _metadata_already_on_device thumbnail(v:True v[1]:160 book[1]:320
SMART_DEV ( 350.14:  0.000) _metadata_already_on_device thumbnail(v:True v[1]:160 book[1]:320
SMART_DEV ( 350.15:  0.000) _metadata_already_on_device thumbnail(v:True v[1]:160 book[1]:320
... (repeat many times) ...

Changing the thumbnail size to 'Medium' for all uses on both devices works around it for now.

[chaley]

Originally Posted by JimmXinu

The main problem I was having was very clearly to do with the thumbnail size. I added _debug calls to _metadata_already_on_device in calibre/devices/smart_device_app/driver.py and it was clear: One device wanted thumbnails 320px high and the other 160px high and the thumbnail in calibre was which ever was called for last.

Fixing this is one reason I am going to change caching to be per device. Another reason is to not have mod time changes on one device not affect other devices. Unfortunately I won't be able to get to this for a week, which means that the changes won't be available for two weeks (at best).

[chaley]

Originally Posted by K8HW

I guess that behavior seems to make sense. What would be the solution?

From what I am experiencing now, I will only be using my Nexus with Calibre Companion for now. After removing the "Reading List" plugin, everything seemed to OK. This afternoon I had Calibre Companion sync with my NookColor and it took almost an hour! I tried it again and all is well. Well, I must be a masochist because I just synced with the Nexus and it took about 18 minutes and I ended up with 98 books with missing files.

Do you think it would fix it if I erased ALL the books from both devices and started from scratch? Or would I have to change the way the books are named?

There are at least two issues here.

The first is the same problem that JimmXinu debugged, that using two devices with different thumbnail sizes will force a full metadata refresh every time you switch devices. The only workaround is the one he used: change both devices to use the same cover image size. I have no idea if doing this will cause problems on the nook color because it is so memory constrained.

The second problem, one I just isolated, is related to multiple formats of the same book on your device (e.g., mobi and epub). In this case the cache gets confused and ignores all but one of them, not updating metadata and not reporting that the ignored formats are on the device. I can't find a way that this problem would result in missing book files, but that doesn't mean there isn't one. I have submitted a fix for this, but because of my timing the fix won't be available in a calibre release for a week.

As for whether removing and resending all books will fix the problems, the short answer is "I don't know". The connection cycle never deletes anything, so the "missing files" aren't being deleted. My current working theory is that CC is somehow mixing up their file names, but I see any way for that to happen. It could be that the scan-on-connect process is getting involved because of the above-mentioned cache problem, in which case cleaning up your CC library could help.

If you do decide to try cleaning, I suggest that you:
- delete all the books from CC's book folder(s) using a file manager.
- start CC and use "Find books with missing" and delete all.
- if at all possible, use only one format for you books, for example epub.
- if you don't care about file names then use CC's "Use book ID as filename" option so that you cannot end up having more than copy of a format for a book on your device.

You might also at this point try to see if the nook color can handle the larger cover files. We haven't had any reports from people saying that the NCs have stopped working, but that doesn't guarantee anything. My concern is that there isn't any way to back up once you change the option. You would need to uninstall and reinstall CC.

[JimmXinu]

Originally Posted by chaley

Fixing this is one reason I am going to change caching to be per device. Another reason is to not have mod time changes on one device not affect other devices. Unfortunately I won't be able to get to this for a week, which means that the changes won't be available for two weeks (at best).

No problem, the workaround is working fine. Thanks for your attention on this.