Calibre Companion syncing experience: issues with a large ondevice library

[Sefiriot]

Firstly, hats off to chaley for giving us this application-- it worked on my cellphone when a previous version of calibre wouldn't recognise it at all, and it keeps everything about my covers and tags-- I can browse for what I feel like reading now anytime on my device. Now it's even better with the latest GUI updates-- the grouping drawer with searchbar is a lovely addition. I'm absolutely glad I bought this app, despite the little hole it's put in my online budget.

Transferral of my book files to my device (Samsung Galaxy Note N7000) proceeds amazingly fast even when handling up to 400 or 500 books at once-- no complaints there.

The main issue for me now is the app's (and/or calibre) tendency to frequently time out while sending/receiving metadata with my large on-device library (8k+ epubs) at connection startup.

Often when I start connecting my device to calibre, I get a timeout debug message (text of error message at bottom) and I have to retry connecting to calibre. Back when the ondevice library was smaller, at around 2k or so it didn't happen as often, but now it usually takes me 2-3 tries before the connection between calibre and my device starts sending/receiving metadata, after which it usually remains stable-- occasional interruptions can happen here as well, though less often with the latest release, I noticed.

Pretty sure it's not the Wi-Fi connection at fault since both laptop and cellphone can have the full 5 bars of reception and still experience timeouts.

I understand a large on-device library with (eventually)11k~ books or more is not really an intended use-case for the app, but some way to speed up metadata send/receive would be great if possible, since it seems that's where CC or calibre itself is choking. I don't really mind waiting for all the data to sync-- as it is, it currently takes around 40 minutes for everything to sync up nicely, but not having to anxiously babysit the transfer at the beginning for fear of an unexpected timeout would be nice.

That said, the current version of CC has definitely improved on the previous iteration, since previously there was no way I could get 7k book's worth of metadata synced without having to retry more than 4 times. Now I only have to connect twice-- or once! That's some wizardly improvement there.


calibre debug message on timeout:

There was a timeout while communicating with the device in function: Device did not respond in reasonable time

Traceback (most recent call last):
  File "site-packages\calibre\gui2\device.py", line 85, in run
  File "site-packages\calibre\gui2\device.py", line 476, in _books
  File "site-packages\calibre\devices\smart_device_app\driver.py", line 49, in _synchronizer
  File "site-packages\calibre\devices\smart_device_app\driver.py", line 1011, in books
  File "site-packages\calibre\devices\smart_device_app\driver.py", line 565, in _call_client
  File "site-packages\calibre\devices\smart_device_app\driver.py", line 598, in _receive_from_client
TimeoutError: There was a timeout while communicating with the device in function: Device did not respond in reasonable time

[chaley]

You are right -- 8000 books is beyond what we thought we were dealing with. However, you are doing it, and DoctorOhh (another MobileRead & CC user) has more than that. IIRC he is up to close to 10,000. We are happy that CC doesn't fall over dead.

Could you provide the entire debug log? I need to see where CC and calibre were in the sync process.

Had CC finished sending metadata up to calibre? Had it even started sending metadata up to calibre?

One thing you might try: turn off CC's auto-scan for new books. It could be that the scan is (sometimes) taking longer than calibre is willing to wait. Turn it off in settings -> Wireless connection settings.

Another thing: be sure that your phone's main memory is not full. Bad things happen if CC runs out of space for its database.

[theducks]

Charles
is there any way to stop (or temporarily extend the time) the Android device from sleeping (the network) during the Synch. This was the issue when I first tried to send a big batch. I say, First because I don't even try that as it will always fail it I don't stroke the screen to keep it from sleeping.

[Sefiriot]

Heh. Well my calibre library is already at 12k+. Let's hope CC won't fall over and die at 20k, which is where I'm pretty sure my library will be at in less than 6 months. Pretty sure the main memory isn't full, but could you please clarify what you mean by main memory? The Galaxy Note's internal memory structure is plain weird since there's the 2GB system storage, then the 11GB or so memory that seems to be what the system sees as USB storage (mnt\sdcard). Do you mean the 2GB internal? Currently all my books are on mnt\ext_sd\Books, which is the actual external SD. calibre's files are in mnt\sdcard, which has 6GB of free space left.

I'm enclosing my log from this evening: the first successful session, with "search folders for new books" on in CC failed sending books halfway, not sure why, since this is maybe only the second time it's happened. The only thing out of SOP for me was the need to autoconvert two books, as you'll see in the log (see line 4184). The second session when CC connected to calibre was done without the "scan for new books" option active; connected at first try so that might be a possible issue.

A method of cancelling the file send in CC, or getting out of it would be a good idea here, since when calibre timed out and stopped on my laptop, CC remained stuck on the file receiving screen; had to force stop the app.

If you look to the very end of the log, you'll see another timeout message while sending. Calibre Companion then crashed on my phone, and when I restarted it, it no longer displays any of the books on my device. This is the second time this week it's happened to me: once on the previous version and now on the current version. I'm not sure what's causing these crashes. That said, I don't want to be syncing my entire library all over again if I can avoid it.

ETA: Tried syncing CC after crash with calibre wiped out library on device (book files are all intact though). It partially synced (got around 90 books) then failed when sending metadata to calibre with this message:

'NoneType' object has no attribute 'lpath'

Traceback (most recent call last):
  File "site-packages\calibre\gui2\device.py", line 85, in run
  File "site-packages\calibre\gui2\device.py", line 476, in _books
  File "site-packages\calibre\devices\smart_device_app\driver.py", line 49, in _synchronizer
  File "site-packages\calibre\devices\smart_device_app\driver.py", line 1033, in books
  File "site-packages\calibre\devices\smart_device_app\driver.py", line 693, in _set_known_metadata
AttributeError: 'NoneType' object has no attribute 'lpath'

Will provide a complete debug log later once this latest sync attempt finishes-- I'm letting it run while I go to bed since it's closer to dawn that I'd like right now.

[DoctorOhh]

Originally Posted by theducks

is there any way to stop (or temporarily extend the time) the Android device from sleeping (the network) during the Synch. This was the issue when I first tried to send a big batch. I say, First because I don't even try that as it will always fail it I don't stroke the screen to keep it from sleeping.

Not going to sleep while connected is currently part of CC, at least my device never goes to sleep during this process.

[theducks]

Originally Posted by DoctorOhh

Not going to sleep while connected is currently part of CC, at least my device never goes to sleep during this process.

Do you know when this keepalive was added? Or could it be a TAB2 issue?
I could see a device 'disconnect' in the middle of a largish transfer

[DoctorOhh]

Originally Posted by theducks

Do you know when this keepalive was added? Or could it be a TAB2 issue?
I could see a device 'disconnect' in the middle of a largish transfer

According to the change log about a year ago.

Spoiler:

Version 1.2 (13/Aug/2012) NEW FEATURES:

• Attempt to detect connecting to the content server instead of the device handler.
• Prevent WiFi sleeping when connected
• Add the CC version number to the dialog with calibre.

BUG FIXES:

• Make transfer and initialization dialogs sticky.

Version 1.3 (14/Aug/2012) NEW FEATURES:

• Better IP address and password dialogs
• Multi-level sorting

BUG FIXES:

• Fix crash caused by missing covers.
• Make progress bars survive application sleeping

[chaley]

Originally Posted by theducks

Charles
is there any way to stop (or temporarily extend the time) the Android device from sleeping (the network) during the Synch. This was the issue when I first tried to send a big batch. I say, First because I don't even try that as it will always fail it I don't stroke the screen to keep it from sleeping.

As DoctorOhh said, we thought we had already done this.

I just tried an experiment on my Galaxy Tab 10.1. I first set my screen timeout to 15 seconds. I connected, then set the device aside to see if it would ever sleep. Half-hour later, the screen was still on, no sleep. I then "ejected" the device from calibre. A few seconds later the screen went dark then the tab went to sleep.

Does your 10.2 do something different?

[Sefiriot]

Left CC and my laptop running while I slept-- woke up in the morning to find that CC had managed to sync and find most of what was on my device, taking an hour or more to do so. The only titles I had to manually match to my library were (and in this case usually are) anthology ePubs made by the FFDL plugin. Got fed up of manually matching some 300+ titles and took the faster way out by deleting what didn't match to the library and resending to device.

Interestingly, calibre 1.0 seems to be able to display whether matches between device and library are by UUID or author; quite useful that. Synced more books over, updated some, overall things have behaved themselves so far. I'll probably be running CC and syncing to calibre again later in the evening; we'll see how my device and calibre install react to an on-device library of 8944 books as of the moment.

I'd attach the log here directly but it's too large to do so, so it's in my Dropbox.

@chaley, for future reference: would you rather have the raw logs as-is, or would you rather I try and redact some of the stuff that's not looking useful to CC debugging? I tend to leave calibre open most of the day and the logs can get really big, as you can see.

[chaley]

Originally Posted by Sefiriot

Heh. Well my calibre library is already at 12k+. Let's hope CC won't fall over and die at 20k, which is where I'm pretty sure my library will be at in less than 6 months. Pretty sure the main memory isn't full, but could you please clarify what you mean by main memory? The Galaxy Note's internal memory structure is plain weird since there's the 2GB system storage, then the 11GB or so memory that seems to be what the system sees as USB storage (mnt\sdcard). Do you mean the 2GB internal? Currently all my books are on mnt\ext_sd\Books, which is the actual external SD. calibre's files are in mnt\sdcard, which has 6GB of free space left.

It is hard to know what I mean without handling the device and seeing what memory is used for what.

CC uses two memory locations: one for its database and settings and one for its books. The first is in the same place that the device stores apps, and the second is in visible storage (sdcard). It would not surprise me if CC's database is in the 2GB hunk. A database for 10,000 books could easily be 100 megabytes large, or more.

I'm enclosing my log from this evening ...

OK, lots here.

First thing I see: the first connection failed before sending any metadata up to calibre. This is consistent with the "scan for books" problem, where the scan takes longer than 60 seconds. One reason this can happen is if CC is storing books in a folder where other things are being kept. In one case we saw, the person set the root of the SD card as CC's folder, so the scan was walking the entire SD card. If I read your post correctly, you changed the setting between the first and second connect, and the second connect worked properly.

Another thing I see is that the network transfers are very slow. I am seeing 15 to 60 seconds per 100 books when uploading metadata. On all of our devices that number is 2 to 4 seconds. I have no explanation for this difference.

Looking at the times to upload books, they also are way out of line. On our Tab 10.1, the slowest device we own, sending a 400 MB book file takes around a half second. On your device I am seeing 4 to 30 seconds.

Things went south at line 4180 of the log, where we see our first timeout. There is no indication why the timeout occurred, but no transfers after that point worked until you reconnected at line 4390. At this point the time to upload metadata has gotten substantially worse, with all the times around 60 seconds per 100 books. This connection attempt aborted 2800 books into the "send metadata" cycle.

The next connection attempt, at line 4496, is interesting because the times to send metadata has gone back to what it was in the first connection. Do you have any idea why? Did you reboot your device? Or something else? I am also confused about why calibre felt it needed to send metadata for 292 books. Had you changed tags or otherwise modified books?

We also see the same slowdown when sending metadata back. On my tab 10.1 it takes between 100 and 200 milliseconds per book. On you device it is taking 1 to 2 seconds per book. As before, I have no idea why this would be.

Things broke again at line 7547, with another timeout. Looking at the transactions above the timeout, it seems clear that something happened on the CC side. What, exactly, is a mystery.

So, where does all of this leave us? My guess is that your device is being very challenged, either in working memory or storage or both. The long network times could be caused by the device running out of working memory and needed to "garbage collect" (go find memory that isn't used any more). If storage is being challenged, then the database update would run extremely slowly because the device must do operations carefully and in an order that doesn't exacerbate the situation.

The above theory is consistent with your database being corrupted. Possibly at some point the database manager on your device was unable to do an update and was unable to roll back previous updates, a situation what would destroy CC's database. If you can determine how much of the 2GB of "system memory" is being used, then check if it is near the limit. Also, look at the "app data" for CC in settings to see how much memory it is using. These numbers do not count the books.

ETA: Tried syncing CC after crash with calibre wiped out library on device (book files are all intact though). It partially synced (got around 90 books) then failed when sending metadata to calibre with this message:

'NoneType' object has no attribute 'lpath'

Traceback (most recent call last):
  File "site-packages\calibre\gui2\device.py", line 85, in run
  File "site-packages\calibre\gui2\device.py", line 476, in _books
  File "site-packages\calibre\devices\smart_device_app\driver.py", line 49, in _synchronizer
  File "site-packages\calibre\devices\smart_device_app\driver.py", line 1033, in books
  File "site-packages\calibre\devices\smart_device_app\driver.py", line 693, in _set_known_metadata
AttributeError: 'NoneType' object has no attribute 'lpath'

Will provide a complete debug log later once this latest sync attempt finishes-- I'm letting it run while I go to bed since it's closer to dawn that I'd like right now.

This error means that CC's database is not in good shape. It sent empty metadata to calibre for the book in question. The only way I can think of where that can happen is that the db does not actually contain the metadata, something that can happen only if there is a problem while writing the info to the DB.

Bottom line: I am concerned that you are pushing your device and CC beyond its limits. There is no way that CC can survive database corruption introduced by Android for whatever reason. It is also difficult for CC to survive slowdowns required by Android to "maintain" the database.

One thing we can do is up the timeout, but I don't think that will help anything.

[chaley]

Originally Posted by Sefiriot

Left CC and my laptop running while I slept-- woke up in the morning to find that CC had managed to sync and find most of what was on my device, taking an hour or more to do so. The only titles I had to manually match to my library were (and in this case usually are) anthology ePubs made by the FFDL plugin. Got fed up of manually matching some 300+ titles and took the faster way out by deleting what didn't match to the library and resending to device.

You must have turned "Scan" back on?

Interestingly, calibre 1.0 seems to be able to display whether matches between device and library are by UUID or author; quite useful that.

It has done that for a long time. Seeing that info requires running in debug mode.

Synced more books over, updated some, overall things have behaved themselves so far. I'll probably be running CC and syncing to calibre again later in the evening; we'll see how my device and calibre install react to an on-device library of 8944 books as of the moment.

If I am understanding things correctly, you reinitialized CC's database then connected with scan books turned on.

One interesting thing to note is that the times to upload books are better now. Not as good as we see, but better. This leads me to think that the clean DB has improved things. I am unaware of any reason that an SQLite db suffers from bit rot, but perhaps it does.

Are you using the new "Update cached metadata on device" function? I am trying to explain the log entries at lines 27450. It is good to note that these times to update the metadata are not as far out of line as others have been.

I'd attach the log here directly but it's too large to do so, so it's in my Dropbox.

@chaley, for future reference: would you rather have the raw logs as-is, or would you rather I try and redact some of the stuff that's not looking useful to CC debugging? I tend to leave calibre open most of the day and the logs can get really big, as you can see.

I have the log. You can delete it if you want.

"As is" is fine. There is no need for you to spend time going through it, unless you want to for privacy reasons.

[kovidgoyal]

@chaley: sqlite dbs can get fragmented, running vacuum or roundtripping via SQL usually fixes that, see for example: http://web.utk.edu/~jplyon/sqlite/SQ...ation_FAQ.html

[chaley]

Originally Posted by kovidgoyal

@chaley: sqlite dbs can get fragmented, running vacuum or roundtripping via SQL usually fixes that, see for example: http://web.utk.edu/~jplyon/sqlite/SQ...ation_FAQ.html

Thanks. We should add this somewhere. Not sure where that "somewhere" should be, though. Perhaps a specific menu item "Clean database".

[Sefiriot]

Yes, turned "Scan" back on. Was that what happened to the database? All I had was that CC crashed-- that's the end of the first log. Reopening CC after clearing device RAM showed a blank database with no books, so I turned "scan" back on, connected it to calibre and left it to do its thing. And yes, I am using the update cached metadata on device function. Is there any reason to avoid using it? I thought that since my device/connection don't seem to take well to sending big loads of metadata at once, sending it in smaller bursts where possible would be better.

You also asked why calibre'd be updating metadata for 292 books-- I believe it's to do with something that's cropped up in calibre 1.0 due to its database changes: updating my fanfic books with the FanfictionDownloader Plugin seems to be updating the author link field at the same time (see here), and thus changing the last_modified value on all books by that author whether needed or not. Thus I only updated some 20 books, but ended up with lots more that had their time in calibre changed. Since CC uses that value, I *think* that's what calibre was sending.

Hmm. I believe that the 2GB memory slot is system memory where apps live-- it has currently 700MB free. Task manager shows that the device's RAM is nearly always headed towards full, and looks pretty close to the limit considering how many apps seem to *love* running in the background. I'm going to see what cruft I can afford to get rid of and free up space; the phone isn't as snappish as it used to be back when I first got it, true.

Do you get logs submitted through normal Android error reports when the app crashes? The CC crash that wiped the database, or seemed to at least had some rather interesting error info when I looked at it on the phone, which I didn't think to screenshot at the time. I'm not too sure now, but I believe that error message indicating empty metadata happened when CC was sending information for that book where calibre had previously timed out whilst in mid-transfer during session 1-- and the crash promptly wiped the database.

If CC's database is corrupt, is there anyway to force a rebuild? Would uninstalling, reinstalling and then letting CC match against calibre for books already on device do the trick?

[DoctorOhh]

Originally Posted by Sefiriot

Often when I start connecting my device to calibre, I get a timeout debug message (text of error message at bottom) and I have to retry connecting to calibre.

I've been fortunate and never have had any hiccup on initial connect.

Originally Posted by Sefiriot

Pretty sure it's not the Wi-Fi connection at fault since both laptop and cellphone can have the full 5 bars of reception and still experience timeouts.

You are most likely correct, but I wouldn't rule out the Wi-Fi connection. Interference from microwave ovens, baby monitors, phones or neighbors are hard to pinpoint. Even if you have 5 bars, your tablet still needs to send to calibre. My last tablet worked great, but there were spots in my house that it had trouble with the Wi-Fi even though it looked like it should be fine. I would never try to sync with calibre from the furthest point away from my router with the previous tablet. Additionally if your router is set to auto select the best channel sometimes the process of switching channels (to avoid wireless interference) seems to cause quirks.

Originally Posted by Sefiriot

I understand a large on-device library with (eventually)11k~ books or more is not really an intended use-case for the app, but some way to speed up metadata send/receive would be great if possible, since it seems that's where CC or calibre itself is choking.

I have almost 10k books on my device. I connected it the other day intending to just sync the 40 odd tags I updated, but forgot I had copied my calibre library to a new location and installed a different version of calibre. So CC apparently (my guess) decided I needed to have all of my covers sync'd again, An hour and 45 minutes later it completed. But subsequent connections after this took only 5 minutes.

Originally Posted by chaley

You are right -- 8000 books is beyond what we thought we were dealing with. However, you are doing it, and DoctorOhh (another MobileRead & CC user) has more than that. IIRC he is up to close to 10,000. We are happy that CC doesn't fall over dead.

It's working great for me. When I was putting the books on it took quite a while (as I expected) and I limited sending the books in batches of 1000. I had the occasional glitch, but nothing I would attribute to CC or calibre. I did a factory reset on my tablet once so I actually sent all of the books to the tablet twice.

During the hiccups I did have, I never lost any books on my device. Sometimes they weren't all sent because of an error, but I picked up where the transfer left off and continued on.

Originally Posted by Sefiriot

we'll see how my device and calibre install react to an on-device library of 8944 books as of the moment.

Good luck.