0.7 -- Sending metadata to device is SSSSLLLOOOOOOOOOOW

[chaley]

Originally Posted by slantybard

chaley - I was curious if you can comment on the philosophy behind changing how calibre handles metadata and the devices? Ie, why change from 0.6 series method and the new 0.7 series method. Thanks for any info.

Are you asking why we made the change?

First, note that what I say below are my thoughts. Kovid could easily have a different rationale or longer-term reasons for why he started this work.

Calibre wants to know several bits of information about the books stored on a device. The obvious are correct title and authors, but having series, tags, dates, and some other information is also very helpful. The vast majority of devices do not store this information in a way that Calibre can see, and storing the information in file path names can go only so far. Because of this, calibre before 0.7 was severely limited in what it could do with the books. For example, using 0.6, the on device feature would have been very difficult, and perhaps impossible, to get close to right while providing even marginally acceptable performance. Detecting changes in collection information (and subsequent rebuilding) would have been impossible.

The goal was to store enough calibre metadata on the device to overcome these problems and to pave the way to future features, such as syncing. We are most of the way there. What is missing is the custom field information, which will be added in a few releases once we get time to finish the work.

Sony devices do store metadata, and are the only calibre-supported devices to do so, modulo the iPad, which I know little about. The issue we have been facing, as evidenced by this thread, is caused by Sony not publishing their database semantics. We must find what the information really means and how it changes by experimentation and reverse engineering, and in the process made some mistakes that hurt performance and correctness. For example, some things we have found are that the Sony truncates authors back to the first one when it rebuilds metadata, that it uses the local time of the PC instead of GMT when checking timestamps, and that it fabricates metadata for formats that can't have it (such as txt) or don't have it even though they can. We tested on our personal devices, but we clearly did not encounter all the corner cases. Thanks to the help of people on this forum, we think that the 0.7.2 release will have it right.

Did I answer your question?

[kovidgoyal]

An additional important consideration (which applies to non sony devices) is metadata caching. For non sony devices calibre used to have to reread metadata from files each time it connected, which was very slow. Now it caches the emtadata.

[slantybard]

thank you both chaley and kovid for explaining the changes in metadata handling. your replies totally make sense.

[alecE]

Finally managed to run 0.7.2 - great improvement.
Previously it was taking 2m 30s to update metadata, now it's taking 11s.

Thanks.

[FizzyWater]

I paged through my collection and added a book here, a book there, another book...and it's updating the metadata for each individual "send to device". And each of those is taking more than 3 minutes (I have LOTS of books).

Could you at least consider having the metadata update once at the end of all jobs run?

It won't allow me to stop any of these "extra" jobs - so I can't even stop it.

NOTE: Windows XP, calibre 0.7.4

[chaley]

Originally Posted by FizzyWater

I paged through my collection and added a book here, a book there, another book...and it's updating the metadata for each individual "send to device". And each of those is taking more than 3 minutes (I have LOTS of books).

Could you at least consider having the metadata update once at the end of all jobs run?

Sorry, but that would be a very risky change. There is an excellent chance that I would break things badly.

It won't allow me to stop any of these "extra" jobs - so I can't even stop it.

NOTE: Windows XP, calibre 0.7.4

This is puzzling. Although the jobs clearly are taking that long, there is no fundamental reason they should, and I can't see 'coding inefficiency' reason that they would. However, there must be, so ...

If you are willing to help, could you run calibre in debug mode? Calibre will produce a log telling me in much finer granularity where it is spending the time. That could give me the necessary clues to where the time is being used.

To run in debug mode, first open a command box (start, run, type cmd in the box, and OK). In the command box, type:

cd \
calibre-debug  -g  >calibre_debug.txt   2>&1

The first line makes your current folder be the root of c: (or whatever drive windows is installed on). This is done so you can find the debug file later. The second line starts calibre in debug mode, writing information to the file calibre_debug.txt.

Next, send a book to your device (I hope it will take as long as before). Do as little as possible in addition, or the log could be filled with lots of extra stuff, making it hard to isolate what is going on. Now quit calibre. Using a file manager (explorer), go to C:\. You should see the file calibre_debug.txt. This file is what I want you to post.

The only personal information the file will contain is the title of the book you sent and the collections that must be created for the book (if any). Feel free to look at it, but be aware that the file is in 'Unix' format, and many windows programs (like notepad) will show you one really long line instead of the correct many short lines. Email the file to me if you have any concerns about posting it. Send it to "calibre-debug [at] charles dot haleys dot name" (no quotes, make the obvious substitutions).

Thank you in advance.

[DoctorOhh]

Originally Posted by FizzyWater

I paged through my collection and added a book here, a book there, another book...and it's updating the metadata for each individual "send to device". And each of those is taking more than 3 minutes (I have LOTS of books).

It would help a little if this was the current version.

It takes 3 seconds for calibre to grab my book list once it recognizes my device and show all books when I first connect. I then added a book here and a book there, each job took a few seconds to transfer the book and update the metadata.

I am using 0.7.5 Win XP sp3. I can't recreate your anomaly. What you're experiencing is not how it is designed to work.

Hopefully someone in the know can ask the right questions to help unravel this mystery.

Update: I see while I was twiddling my thumbs browsing the calibre manual that chaley has given you guidance. Hopefully y'all can work this out.

[FizzyWater]

Originally Posted by chaley

If you are willing to help, could you run calibre in debug mode? Calibre will produce a log telling me in much finer granularity where it is spending the time. That could give me the necessary clues to where the time is being used.

To run in debug mode, <snip!>

I'll try that when I get home from work. And thanks so much for the step-by-step...I wouldn't have known how to run in debug mode without your instructions!

Originally Posted by dwanthny

It would help a little if this was the current version.

I've gotten the impression that version 0.7.5 is a buggy release. For exapmle, I saw on a different thread that there's a known bug when importing HTML files. Since I sometimes start with HTML, I didn't want to install the update - I was waiting for 0.7.6.

I normally watch the posts here for a couple of days before installing any new Calibre updates!

[DoctorOhh]

Originally Posted by FizzyWater

I've gotten the impression that version 0.7.5 is a buggy release. For exapmle, I saw on a different thread that there's a known bug when importing HTML files. Since I sometimes start with HTML, I didn't want to install the update - I was waiting for 0.7.6.

I normally watch the posts here for a couple of days before installing any new Calibre updates!

Perfectly understandable, and a very smart of dealing with upgrades.

I was actually referring to 0.7.6

[FizzyWater]

Originally Posted by chaley

Email the file to me if you have any concerns about posting it. Send it to "calibre-debug [at] charles dot haleys dot name" (no quotes, make the obvious substitutions).

File sent. I'd be willing to try upgrading to 0.7.6 and re-running this in debug mode, if you think it would be helpful. The problem seems to be something in my database, though, because the file seems to be renumbering each file, one at a time?

Originally Posted by dwanthny

Perfectly understandable, and a very smart of dealing with upgrades. I was actually referring to 0.7.6

Hmmm...when I opened Calibre yesterday, it didn't notify me that 0.7.6 was available...maybe it was rolled out later in the day. I've already seen one bug thread about 0.7.6, so I'm hesitant about installing it, too. I'm waiting to see if it's a fluke...

[DoctorOhh]

Originally Posted by FizzyWater

Hmmm...when I opened Calibre yesterday, it didn't notify me that 0.7.6 was available...maybe it was rolled out later in the day.

It was rolled out late yesterday or more likely very early this morning.

I hope y'all are successful in correcting your problem.

[chaley]

@FizzyWater: Thank you for sending me the log. I found a (i hope 'the') problem. It was in a place I never would have looked, and has nothing to do with Sonys and collections. A program component supplied by the Python people is using a very inefficient method to write to disks. Interestingly enough, they even say so in the middle of their code. (For those who want to know, the metadata cache code uses JSON, which is using unbuffered writes. Combine that with using unbuffered I/O with removable storage, the norm on XP I think, and you have performance death.)

Under Win7, both my phone card and my PRS-300 are forced to a performance-enhanced mode (write behind is forced on), so I can't completely measure the effects of the fix. However, even in my case I see a 10-times improvement, with 1500 books taking 1 second instead of 10. My guess is that you will see more improvement than that.

In addition, using your log and the one June sent earlier, I isolated two spots in the Sony driver that could be improved. Fizzywater's log indicates that building collections took 11 seconds for 1500 books. With the code changes, that time should drop to below 7 seconds, perhaps as low as 5. A drop in your bucket, but as one supermarket here says, "every little helps".

I have neither an XP machine nor a 505 to test with, so I can't be sure of the magnitude of the improvement. My guess is that in FizzyWater's case, the time will drop from approximately 220 seconds to approximately 25. It could drop to as low as 10, but I am not holding my breath.

@FizzyWater: the remapping messages in the log are not a problem. Remapping happens because calibre puts the books before the playlists in the Sony database, which can change their ID. It looks like the new book you added was given id 200. Also, the numbers in the front of the log are time in tenths of seconds from when the device was connected. Looking at the log, you will see that the vast majority of the time is taken between USBMS: starting sync_booklists and USBMS: finished sync_booklists. Fortunately for me, from calibre's point of view not much happens between those two messages, so it was relatively easy to chase the problem to its external source.

[DoctorOhh]

Originally Posted by chaley

I have neither an XP machine nor a 505 to test with, so I can't be sure of the magnitude of the improvement. My guess is that in FizzyWater's case, the time will drop from approximately 220 seconds to approximately 25. It could drop to as low as 10, but I am not holding my breath.

@chaley, I agree every bit does help. I have an XP sp3 box and a 505. I posted my job times earlier in this thread. I couldn't come close to replicating his times.

Great job with digging in and finding the little things that hide in the dark.

[FizzyWater]

Originally Posted by chaley

@FizzyWater: Thank you for sending me the log. I found a (i hope 'the') problem.

Woo-hoo!

So? 0.7.7? Or a little longer than that...

[chaley]

Originally Posted by FizzyWater

So? 0.7.7? Or a little longer than that...

0.7.7.