Normal for kobo to take forever on "processing content" ?

[davidfor]

Originally Posted by DNSB

"This is not a novel to be tossed aside lightly. It should be thrown with great force"

That's the biggest downside of ereaders: throwing a book across the room in disgust, is a little bit expensive.

[leftright]

I also have a large collection of books which stalled at 80% during Kobo Processing of the entire collection.

I discovered via Sigil and Calibre that several books had major errors in their TOC and structural errors in the code, I first cleaned them in Sigil, then fixed the TOC in Calibre and bug checked in calibre.

With a large unverified collection I would batch load the books.
Whenever I do a clean install of my entire collection to my Glo I batch load then, 200 per batch, let the Glo process 200 at a time and it works fine.

[chrisridd]

Breaking down the adobehost strace a little more.

First we can see some timestamp information in the clock_gettime calls. The numbers printed are time since some point in { seconds, nanoseconds }.

At 269.466764989 the file is opened, the first 16KB is read, and the file's closed. There isn't anything you can do with the first bit of a zip file except check the first bytes match "PK".

Then the file is opened again, and the last 2744 bytes read. I think that's a required zip file trailer, which lets the program find stuff in the rest of the file. Then the file is mmap()ed in, then closed, and then unmapped.

Just before 269.521851864, 1089 bytes is written to nickel including the text "DC.creator". So this looks like some (probably all) of the relevant metadata from the OPF file.

At 269.526128239, the file is opened for the third time, the first 16KB is read, and the file closed.

Then the file is opened again, the last 2744 bytes read, and then the whole file is mmap()ed again. After the file is closed and unmapped, 2213 bytes is written back including some file:// URL. We can't see most of this. There's no disk writes. Could this be the TOC?

However something is also logged at this point "<15>Jun 17 16:37:09 adobehost: v"... which may be worth finding.

It is now 270.338781864.

About 1/2 a second later at 270.801502864 the file is opened again so its first 16KB can be read again

Can we deduce anything from this? Well, the metadata extraction from the OPF is quick (55ms) so that doesn't seem to be the issue. Something else big is being passed back, which contains a file URL. Given the tests in this thread I'd guess that's the TOC. Generally the process looks inefficient because it keeps opening and closing the same file. I wonder if reading 16KB matches the block size used on the filesystem.

Overall the work took from 269.466764989 to 270.801502864, a little less than 1.5 seconds, but at least a third of that time is waiting for nickel.

BTW nice to see some Karl May! I've only ever read English translations of his books though :-(

[davidfor]

Originally Posted by chrisridd

Breaking down the adobehost strace a little more.

First we can see some timestamp information in the clock_gettime calls. The numbers printed are time since some point in { seconds, nanoseconds }.

At 269.466764989 the file is opened, the first 16KB is read, and the file's closed. There isn't anything you can do with the first bit of a zip file except check the first bytes match "PK".

The standards say that the file "mimetype" has to be the first in the archive and is not compressed. Reading the first 16KB would include this. This must contain the string "application/epub+zip" and checking this is supposed to be done to prove it is an epub.

Then the file is opened again, and the last 2744 bytes read. I think that's a required zip file trailer, which lets the program find stuff in the rest of the file. Then the file is mmap()ed in, then closed, and then unmapped.

So, read the zip catalogue (or whatever they want to call it) and load the whole file into memory (as needed). Will strace pick up the actual IO when this is done?

Just before 269.521851864, 1089 bytes is written to nickel including the text "DC.creator". So this looks like some (probably all) of the relevant metadata from the OPF file.

Does that sound like enough? If it is all the metadata that nickel uses, it will include the description and I have lots of books that would have more than that in the description.

At 269.526128239, the file is opened for the third time, the first 16KB is read, and the file closed.

Then the file is opened again, the last 2744 bytes read, and then the whole file is mmap()ed again. After the file is closed and unmapped, 2213 bytes is written back including some file:// URL. We can't see most of this. There's no disk writes. Could this be the TOC?

The file:// URL could be for the whole book as that is used for the key in the database. But, each chapter also gets a file:// URL in the database.

However something is also logged at this point "<15>Jun 17 16:37:09 adobehost: v"... which may be worth finding.

It is now 270.338781864.

About 1/2 a second later at 270.801502864 the file is opened again so its first 16KB can be read again

Can we deduce anything from this? Well, the metadata extraction from the OPF is quick (55ms) so that doesn't seem to be the issue. Something else big is being passed back, which contains a file URL. Given the tests in this thread I'd guess that's the TOC. Generally the process looks inefficient because it keeps opening and closing the same file. I wonder if reading 16KB matches the block size used on the filesystem.

The filesystem is FAT32. The cluster size is probably 4KB unless you have updated the size of your internal card. Then it might be 16KB. Of course, the filesystem driver might read multiple blocks.

Overall the work took from 269.466764989 to 270.801502864, a little less than 1.5 seconds, but at least a third of that time is waiting for nickel.

Ouch, all those file opens and rereads of the same part. An obvious reason for something like that is if the a process is checking the file for something and then passing it to another process/routine and it opens the file again. nickel doing the first and then the adobehost/RMSDK doing the second makes sense from a coding point of view. It is inefficient at runtime, but simple to code.

[frostschutz]

Originally Posted by davidfor

Will strace pick up the actual IO when this is done?

Don't think so. I could do a block dump but it will only catch the first read, not subsequent re-reads from cache.

Originally Posted by davidfor

Ouch, all those file opens and rereads of the same part.

Well, that's handled by the Linux VFS cache. So it's more like a memory copy than a physical read. But it raises questions regarding how the data is processed behind the scenes. Reading 16KB of already cached data might not take particularly long. But re-parsing and re-validating of the same data might add up.

[JSWolf]

Originally Posted by xor_

Of course someone adding 8,500 books is an extreme case. But FWIW, I've seen annoyingly long delays with just a few tens of books. I let it run over night, and in the morning it still wasn't finished.

I've read of Kindles slowing down due to problematic books when indexing.

[chrisridd]

Originally Posted by davidfor

The standards say that the file "mimetype" has to be the first in the archive and is not compressed. Reading the first 16KB would include this. This must contain the string "application/epub+zip" and checking this is supposed to be done to prove it is an epub.

That's true, but I don't recall if you can read a zip file from start to finish like that. I think you have to begin from the end of the file and work backwards. But you might be right and this is a sanity check of the mimetype file.

Originally Posted by davidfor

So, read the zip catalogue (or whatever they want to call it) and load the whole file into memory (as needed). Will strace pick up the actual IO when this is done?

No, strace only shows the system calls and not the underlying I/O. In this case the I/O is handled by the virtual memory system in the kernel, and the caller just sees the file as an array of bytes which are "magically" paged in.

Originally Posted by davidfor

The file:// URL could be for the whole book as that is used for the key in the database. But, each chapter also gets a file:// URL in the database.

Could be. I think you can tell strace to dump out more of the details of each read and write instead of truncating it, so that would (might) reveal more.

Originally Posted by davidfor

Ouch, all those file opens and rereads of the same part. An obvious reason for something like that is if the a process is checking the file for something and then passing it to another process/routine and it opens the file again. nickel doing the first and then the adobehost/RMSDK doing the second makes sense from a coding point of view. It is inefficient at runtime, but simple to code.

Yeah, it might not be so bad as the OS is likely to cache some of the reads, but it does look a bit clumsy. The multi-process architecture is good if the adobehost bit decides to crash or misbehave.

Getting timestamps in the strace output would be useful. I can't see where the time's spent apart from in the OPF scanning (55ms). It looks a bit like the TOC stuff which is ironic if it isn't used any more.

[davidfor]

Originally Posted by chrisridd

That's true, but I don't recall if you can read a zip file from start to finish like that. I think you have to begin from the end of the file and work backwards. But you might be right and this is a sanity check of the mimetype file.

Yes, as it is the first file, the contents will be a bare string immediately after the zip header and easy to check.

Getting timestamps in the strace output would be useful. I can't see where the time's spent apart from in the OPF scanning (55ms). It looks a bit like the TOC stuff which is ironic if it isn't used any more.

The ToC is used. It is what you see when you open the ToC in the book.

[eschwartz]

Originally Posted by JSWolf

I've read of Kindles slowing down due to problematic books when indexing.

No, it just stops altogether. As in, jamming up the indexer actually stops it, shockingly enough.

What is your point?

[xor_]

Originally Posted by DNSB

While I'd agree that Kobo's error checking is about as useful as a screendoor on a submarine, any commercially produced epubs should pass Flightcrew and/or epubcheck without major errors. For non-commercial epubs, I'll allow a bit of leniency though many of them are more standards compliant than many of the commercial epubs. I have not found an epub that validated with no major errors and caused my Kobo reader to hang during processing.

I agree the major choking is probably due to bad formatting. But if you can't parse it within a reasonable time frame, how about failing gracefully? Give me a message saying "book xyz's fomatting isn't up to our high quality standards. Please fix or do sumpm." And then move on to processing the next book instead of just sitting there, blocking the device and burning CPU cycles.

As is, we get the worst of both options. The device is unusable, and the software won't even tell us which of the books it finds offensive.

The other aspect is a question of priorities. The normal book-reading with turning a page every other minute can't be all that CPU-intensive. Seems like a no-brainer to let the user do that while you do whatever processing you think you have to do in the background? Then give them a message about the results of your processing?

[shalym]

Originally Posted by JSWolf

I've read of Kindles slowing down due to problematic books when indexing.

Yes...but you can still use your Kindle to read, even if a book is stuck indexing. Can you use your Kobo if a "problematic book" hangs up the processing?

Shari

[chrisridd]

Originally Posted by davidfor

The ToC is used. It is what you see when you open the ToC in the book.

Well that's true. It is a trade off between generating it on demand, or when you open the book, or when you add the book to the reader - and it seems like Kobo's chosen the latter. Perhaps because it is so slow? ;-)

I wonder if we can figure out some tests to see what about the ToC extraction is so slow. Does nesting make a difference - as Kobo doesn't support multiple levels?

[DNSB]

Originally Posted by leftright

I also have a large collection of books which stalled at 80% during Kobo Processing of the entire collection.

I discovered via Sigil and Calibre that several books had major errors in their TOC and structural errors in the code, I first cleaned them in Sigil, then fixed the TOC in Calibre and bug checked in calibre.

With a large unverified collection I would batch load the books.
Whenever I do a clean install of my entire collection to my Glo I batch load then, 200 per batch, let the Glo process 200 at a time and it works fine.

With a bit of batch file magic, you can use epubcheck and/or Flightcrew (the same checker currently used in Sigil) to check a large batch of epubs with any errors being recorded in a log file. I've done this on a couple of occasions and it does make locating the troublemakers much easier.

Once the ebooks are cleaned up and transferred sucessfully to a Kobo, I don't worry about smaller batches for those ebooks.

[davidfor]

Originally Posted by chrisridd

Well that's true. It is a trade off between generating it on demand, or when you open the book, or when you add the book to the reader - and it seems like Kobo's chosen the latter. Perhaps because it is so slow? ;-)

I think it's tradition. The way they handled books in the early readers was different to now. My understanding is they unpacked them all. Extracting the ToC while doing that wouldn't be much work. Plus, my memory has the ToC available from outside the book in at least one firmware version. As things have changed, this hasn't as there has been no real reason to, and as any good programmer knows, you do not touch working code.

I wonder if we can figure out some tests to see what about the ToC extraction is so slow. Does nesting make a difference - as Kobo doesn't support multiple levels?

I think it's just size. My test the other day had flat ToCs. Most of my books have either one or two levels. There doesn't seem to be any difference with those two.

[eschwartz]

Originally Posted by davidfor

I think it's tradition. The way they handled books in the early readers was different to now. My understanding is they unpacked them all. Extracting the ToC while doing that wouldn't be much work. Plus, my memory has the ToC available from outside the book in at least one firmware version. As things have changed, this hasn't as there has been no real reason to, and as any good programmer knows, you do not touch working code.

Slow code could arguably be called not-really-working code.

I could see it as being quite reasonable to branch off the code and try to update it to work with the new paradigm for their other code that they did, somehow, end up changing.