View Single Post
Old 06-18-2015, 01:43 AM   #78
chrisridd
Guru
chrisridd ought to be getting tired of karma fortunes by now.chrisridd ought to be getting tired of karma fortunes by now.chrisridd ought to be getting tired of karma fortunes by now.chrisridd ought to be getting tired of karma fortunes by now.chrisridd ought to be getting tired of karma fortunes by now.chrisridd ought to be getting tired of karma fortunes by now.chrisridd ought to be getting tired of karma fortunes by now.chrisridd ought to be getting tired of karma fortunes by now.chrisridd ought to be getting tired of karma fortunes by now.chrisridd ought to be getting tired of karma fortunes by now.chrisridd ought to be getting tired of karma fortunes by now.
 
chrisridd's Avatar
 
Posts: 983
Karma: 2209358
Join Date: Nov 2011
Location: London, UK
Device: Kobo Aura, Kobo Aura ONE, PocketBook InkPad Color 3
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 :-(
chrisridd is offline   Reply With Quote