Connection performance improvement?

[chaley]

Originally Posted by kaufman

I'll try that and see. It might take me a few days, because the two computers are in different locations. Having said that, if I make a change on one of the computers, then the cache on the other computer will no longer match the contents of the database? What does Calibre do in that situation?

The cache is trying to keep track of what is on the device. That is why CC sends its dates to calibre when it connects. It is verifying that the cache on the current computer is accurate. If you change something on computer A then connect, the cache on computer A will be accurate. However, the cache on computer B will be incorrect for any book that had its metadata changed. When you connect to computer B, calibre will tell CC that it needs up-to-date metadata for the books that were changed when connected to A. It uses this new metadata to determine if it needs to resend the metadata back to the device.

There is no relationship between the cache and calibre's database. It is normal that the database is out of sync with the cache because it is normal that calibre is out of sync with the device.

[kaufman]

Originally Posted by chaley

There is no relationship between the cache and calibre's database. It is normal that the database is out of sync with the cache because it is normal that calibre is out of sync with the device.

Got it. I thought it was a Calibre cache, not a device cache.

[kaufman]

So, I synced my phone last night, and I just synced again from the same computer this morning. CC is currently sending the metadata for 5300 books to Calibre. I made no global changes in Calibre. and didn't change any settings in CC. I don't know why it thinks it needs to send anything, much less the metadata for 5300 books.

I just sent you a debug log so you could take a look at why it was doing it.

[chaley]

Originally Posted by kaufman

So, I synced my phone last night, and I just synced again from the same computer this morning. CC is currently sending the metadata for 5300 books to Calibre. I made no global changes in Calibre. and didn't change any settings in CC. I don't know why it thinks it needs to send anything, much less the metadata for 5300 books.

I just sent you a debug log so you could take a look at why it was doing it.

What I see from that log:

1) You connected at 2014-10-09 01:35:15. This connection sent metadata for 21 books. Clearly the cache worked.

2) You connected again at 2014-10-09 22:54:27. This connection sent metadata for 66 books. Again, the cache worked.

3) You connected again at 2014-10-10 11:50:49. This connection sent metadata for 5293 books. Here, something either went wrong or a lot of books were changed in non-obvious ways.

So, the question is "what happened between 10:54 pm on the 9th and 11:50 am on the 10th?" Do you remember what you might have done? I am looking for something that either messed with the driver's cache (unlikely) or changed the mod time for more than 5000 books. For example, might you have changed a tag used in lots of books? Could you have changed something like a publisher, used everywhere? Any clues?

We know that the cache file wasn't deleted or corrupted, because if it was then metadata for more than 6,000 books would have been sent. This means that calibre thinks that the mod time for more than 5,000 books changed. I am assuming that the disk containing the cache is not out of space.

[kaufman]

I'm not 100% sure how this works. I have "Sync only from Calibre to CC" set, so I don't see how anything I do on the CC side could invalidate the device cache on the computer. Do changes in the calibre side force CC to send over its metadata again? Do you update based on modified date, or by comparing the two side's metadata?

In any case, I went to sleep last night after doing a sync, and I got up this morning, added a book to my library, and did another sync. I didn't do any metadata change on the Calibre side that would impact 5300 books. Except for a couple of books, I didn't make any metadata changes at all. I might have deleted a dozen or so non-epub metadata files. I just checked to be sure, and I don't have any custom column definitions that change their value automatically based on date or anything like that.

I have plenty of free space on my drive.

[chaley]

Originally Posted by kaufman

I'm not 100% sure how this works. I have "Sync only from Calibre to CC" set, so I don't see how anything I do on the CC side could invalidate the device cache on the computer. Do changes in the calibre side force CC to send over its metadata again? Do you update based on modified date, or by comparing the two side's metadata?

In any case, I went to sleep last night after doing a sync, and I got up this morning, added a book to my library, and did another sync. I didn't do any metadata change on the Calibre side that would impact 5300 books. Except for a couple of books, I didn't make any metadata changes at all. I might have deleted a dozen or so non-epub metadata files. I just checked to be sure, and I don't have any custom column definitions that change their value automatically based on date or anything like that.

I have plenty of free space on my drive.

My apologies. My questions about changing tags etc were giant red herrings for exactly the reasons you mention. Changing in calibre can (should) change the relationship between the contents of the cache and CC's database.

Overnight I had an idea. Do you have more than one library? And do these libraries share content? And if so, did you switch to that other library while connected? The reason to ask: when you switch libraries while connected, calibre goes through the book matching process for the books on the device and changes the cache. I can't see how this would break things, but I thought I would ask.

The only ways I can see that would really break the cache are:
- If two devices with the same unique ID connect to the same library. I don't see a way that this can happen.
- If the cache file is being altered somehow. Again, I don't see why this could happen.
- If there is a problem encoding data to write into the cache file. If this happens then the cache would be cut off at the book with the problem. There would also be a message in calibre's debug log, but you wouldn't ever see that unless you always run in debug mode.

One experiment that is worth trying when you feel like it. Make sure calibre is not running even in the tray, then go to ~/Library/Caches and delete all files of the form wireless_device_{long_string_of_digits}_metadata_c ache.json. Start calibre, then connect your device. It will send all metadata because the cache is empty. Disconnect, quit calibre, then look in that folder. There should be one file wireless_device... , and it should be very long. Restart calibre in debug mode, then connect. CC should send no metadata. Disconnect. The mod time on the file will change. Its length might change slightly.

This experiment will show us if something basic is broken. If everything works as described then we know that calibre and CC are agreeing on the contents of the cache. If CC sends metadata then something has gone wrong, and I hope that calibre's debug log will tell me. Send me that debug log by email.

Thanks for your patience and for your help!

[kaufman]

Originally Posted by chaley

Overnight I had an idea. Do you have more than one library? And do these libraries share content? And if so, did you switch to that other library while connected? The reason to ask: when you switch libraries while connected, calibre goes through the book matching process for the books on the device and changes the cache. I can't see how this would break things, but I thought I would ask.

I do have multiple libraries; ebooks, PDF, Comics. I'm not sure what you mean by sharing content. They don't have any of the same books, but I do copy books from all three libraries to CC. I don't remember what switching I did last night, but I just tried the following test.

1. Start up Calibre in ebooks library.
2. Start up CC on my phone
3. Connect CC via wireless
4. Transfer a book
5. Switch to Comics library
6. Transfer a book
7. Disconnect
8. Exit Calibre
9. Exit CC
10. Restart Calibre
11. Switch Back to ebooks Library
12. Start CC on my phone
13. Connect wirelessly

It is currently sending the metadata for 1923 books.

Bingo.

I'm happy to try the other tests you mentioned, but perhaps you don't need me to any more.

Originally Posted by chaley

Thanks for your patience and for your help!

My pleasure. Always glad to help.

[kaufman]

Originally Posted by chaley

The only thing I have done that will have slowed down the "analyzing" phase is book syncing. If that option is on then calibre must check the date of every book file, which requires going to the disk. That could account for the 20 seconds being more than it was before.

Is it possible to do this manually? I've decided I don't want to do this on every connection because of the slow-down. What I would love to have "Update Changed book files" on the Device Menu right below "Update cached metadata".

Is this even possible? If so, does it require CC changes, or are you sending over the book modification dates anyhow?

[chaley]

Originally Posted by kaufman

I do have multiple libraries; ebooks, PDF, Comics. I'm not sure what you mean by sharing content. They don't have any of the same books, but I do copy books from all three libraries to CC. I don't remember what switching I did last night, but I just tried the following test.

1. Start up Calibre in ebooks library.
2. Start up CC on my phone
3. Connect CC via wireless
4. Transfer a book
5. Switch to Comics library
6. Transfer a book
7. Disconnect
8. Exit Calibre
9. Exit CC
10. Restart Calibre
11. Switch Back to ebooks Library
12. Start CC on my phone
13. Connect wirelessly

It is currently sending the metadata for 1923 books.

Bingo.

I can see only two ways this can happen. The first: when two different books in different libraries share the same uuid (unique ID). To have this happen to 2000 books stretches credibility to breaking. The second: books coming from different libraries end up as a single book in CC (they share a file path). This too isn't credible because if there were 2000 of them you would notice that some books are not on your device.

Could you do the same experiment while running calibre in debug mode? That might give me enough info to figure out what is happening. You would end up making two logs. Might as well send me the CC debug log as well, just in case.

Again, thanks.

[chaley]

Originally Posted by kaufman

Is it possible to do this manually? I've decided I don't want to do this on every connection because of the slow-down. What I would love to have "Update Changed book files" on the Device Menu right below "Update cached metadata".

Is this even possible? If so, does it require CC changes, or are you sending over the book modification dates anyhow?

No, what you are asking for isn't possible. CC must know about whether the flag is set or not when it connects and discusses what metadata calibre might need.

What I could do is add an "Ask on connect" option to CC. If set, CC would pop up a dialog when you tap "Connect as wireless device" asking you if you want to sync books during this connect.

[kaufman]

Originally Posted by chaley

What I could do is add an "Ask on connect" option to CC. If set, CC would pop up a dialog when you tap "Connect as wireless device" asking you if you want to sync books during this connect.

That would be great. Thanks.

You could also make it a check box on the connect dialog.

[kaufman]

Originally Posted by chaley

I can see only two ways this can happen. The first: when two different books in different libraries share the same uuid (unique ID). To have this happen to 2000 books stretches credibility to breaking. The second: books coming from different libraries end up as a single book in CC (they share a file path). This too isn't credible because if there were 2000 of them you would notice that some books are not on your device.

It also seems unlikely, because the last time it was 5300 books. You would think that if it was one of those two things, it would be the same number of books each time.

Originally Posted by chaley

Could you do the same experiment while running calibre in debug mode? That might give me enough info to figure out what is happening. You would end up making two logs. Might as well send me the CC debug log as well, just in case.

Running tests now.

[chaley]

Originally Posted by kaufman

That would be great. Thanks.

You could also make it a check box on the connect dialog.

Can't do a check box that works in a natural fashion, but I can do two menu lines.

I did it without adding an option. Instead I changed the meaning of the existing option to show another line on the connect menu. These screen captures show what it looks like.

[kaufman]

Originally Posted by chaley

Can't do a check box that works in a natural fashion, but I can do two menu lines.

I did it without adding an option. Instead I changed the meaning of the existing option to show another line on the connect menu. These screen captures show what it looks like.

Love it. Perfect.

Still running the tests. Messed up the first time and then had to make breakfast for the kids.


EDIT: Logs sent.

[chaley]

Originally Posted by kaufman

So, I synced my phone last night, and I just synced again from the same computer this morning. CC is currently sending the metadata for 5300 books to Calibre. I made no global changes in Calibre. and didn't change any settings in CC. I don't know why it thinks it needs to send anything, much less the metadata for 5300 books.

I just sent you a debug log so you could take a look at why it was doing it.

With the help of Kaufman's experiments and logs, I found the problem.

When a device disconnects, calibre writes the metadata cache file to the disc, a process that can take some time if there are a lot of books on the device. For example, for Kaufman with some 6,000 books on the device, writing the cache took around 10 seconds. The write is done in the background as part of the disconnect sequence. The problem is that if the user quits calibre while this write is happening then the write process is killed, leaving the cache with an indeterminate number of entries. If is of course perfectly reasonable to quit calibre after disconnecting, especially as it doesn't indicate that it is busy doing something. I needed to find a way to ensure that quitting "early" doesn't corrupt the cache.

After some discussion with Kovid, I made two changes. The first is to write the cache after metadata is sent to CC, ensuring that the cache file is always "close-to" up-to-date. The second is to write the information to a tmp file then replace the existing cache with that file. This guarantees that the cache is either fully replaced or not touched. Both of these changes are in calibre source now and will be in the next calibre release.