Nexus 7 Gen 2 takes 1600+ ms each page turn getting first and last visible CFI

[jdempcy]

This issue is a Bug

Expected Behaviour

Page turns should be faster.

Observed behaviour

In a very simple book (The Iliad, Feedbooks) it takes 1600 milliseconds just getting the first and last visible CFIs to turn pages in chapters with approximately 20 or more screens. Some smaller chapters take 800 milliseconds or longer. This is on top of other time spent turning the page.

I am testing with a 2014 Nexus 7 Gen 2.

Steps to reproduce

1. First, open The Iliad.
2. Then turn pages and notice that the larger chapters take multiple seconds for each page turn.
3. You may verify that it is fetching the first and last visible CFIs which adds over a second to each page turn.

Test file(s)

This occurs in all books but the one I am using for testing is: http://www.feedbooks.com/book/2962/the-iliad-of-homer

Product

SDKLauncher-Android

[rkwright]

@jmgeffroy Does this ring any bells for you? Are you seeing this kind of performance hit in your Android device?

[jmgeffroy]

@rkwright As I said in a PM to @bluefirepatrick and @jdempcy, no, I tried again with the same book and it's very fast. But we are currently still using a pretty old version of the plugin It could be interesting to look at the diffs that could explain this difference of behavior. UPDATE Feb. 13, 2017: To be clear, I meant we don't have the issue in our own apps (based on an old version), but I do observe the issue with the latest Android launcher.

[jccr]

This sounds pretty bad.. I have a Nexus 7 Gen 2. @jdempcy Do you think I could reproduce this by pointing it to a cloud reader instance on the Chrome browser app? That's what I'll try first.

[jccr]

@jdempcy I'm using http://readium.firebaseapp.com with Accessible EPUB. The firstVisibleCFI call is taking 60-200ms on my Nexus 7 Gen 2*.

Edit: Typo.. I meant Gen 2. Also I'm using the Chrome Browser

[jdempcy]

@JCCR I just tested http://readium.firebaseapp.com with Nexus 7 Gen 2 in Chrome Browser and it is blazing fast. However, I am not sure if page turns are calling firstVisibleCFI or not. Nor do I know how to open the JS console and execute the call manually to check.

I was thinking that perhaps SDKLauncher-Android is using the LauncherUI JavaScript Interface to make the calls to firstVisibleCFI within the webview.

Also, it is very fast on small spine items for me in SDKLauncher-Android. I'm seeing the 800+ms times when I navigate in spine items with 20 or 30 screens.

Thanks for checking! I can confirm that readium.firebaseapp.com does not seem to have the slow page turn issue.

If you want to let me know how to test calling firstVisibleCFI from a JS console in Android, I'll try that.

EDIT: I just realized I can click the link icon in the top nav to open the "Share reader bookmark…" dialog which will call firstVisibleCFI. It takes about half a second to do so in some spine items in Accessible EPUB 3 by my visual estimate. (However, I am not running console.time/console.timeEnd methods to confirm this.)

But, for instance, in the chapter "Conventions Used in This Book" from the TOC, clicking the link and opening "Share reader bookmark…" is very fast, like ~100ms.

EDIT 2: I just tried "A First Course in Linear Algebra" — navigate to the Archetype X chapter from the table of contents and try bookmarking that one. For me, in the Nexus 7 Gen 2 in Chrome it takes what seems like at least 800ms. (Again, just visually estimating.)

This isn't bad when it's just bookmarking, but multiply by two for first and last visible CFI on every page turn in SDKLauncher-Android and it feels quite slow. Again, this is only affecting the larger chapters on SDKLauncher-Android, so at least that is one saving grace. I shudder to think what would happen if someone tries opening an export from Google Drive, however, which makes ePubs consisting of a single spine item!

[rkwright]

Note that Linear Algebra is notoriously slow but still ...

[jmgeffroy]

If you want to let me know how to test calling firstVisibleCFI from a JS console in Android, I'll try that.

@jdempcy In the console, you can do: ReadiumSDK.reader.getFirstVisibleCfi();

[jccr]

@jdempcy Thanks for sharing your investigation. Even with my own findings I can extrapolate that with 20-30 screens the performance can degrade to the levels that you are seeing.

I'll keep investigating this

[jmgeffroy]

Did you notice that time seems to be spent mostly in getNormalizedRectangles(), more precisely there:

for (var i = 0, l = clientRectList.length; i < l; ++i) {
            if (clientRectList[i].height > 0) {
                // Firefox sometimes gets it wrong,
                // adding literally empty (height = 0) client rectangle preceding the real one,
                // that empty client rectanle shouldn't be retrieved
                clientRectangles.push(
                    normalizeRectangle(clientRectList[i], leftOffset, topOffset));
            }
        }

[jmgeffroy]

Since this code seems a fix for a Firefox issue, maybe you could try doing a short-circuit it for Android ?

[jccr]

@jmgeffroy You are right. From a run that took ~224ms. It was stuck in that function for 7ms.

[jccr]

Let me annotate that flamegraph to explain what I see.

[jmgeffroy]

@JCCR Strange, here I see 100ms spent in this loop for a 125ms run...

[jccr]

@jmgeffroy

It must have some significance because this is a place where the garbage collector seems to have run for an unusually long time. I should add that I'm now testing on a Nexus 5X device. I'm three pages in to the Accessible Epub Chapter 2.

[jmgeffroy]

@JCCR While testing with the SDKLauncher on my Samsung GNote 3, when turning 1 page, I see that: I don't know if it helps, I'll have to stop for now. Good luck!

[jccr]

@jmgeffroy Yes. I just browsed through the source mapped code and saw something similar to your screenshot. Thanks!

[jmgeffroy]

@JCCR You're welcome. Sorry I fall asleep (2:30am here), can't help much more for now :-)

[jccr]

@jdempcy Give the branch of this PR a shot: https://github.com/readium/readium-shared-js/pull/371

It should help reduce the time taken by at least 30%

I have some more ideas to reduce this further such as turning on that caching stuff you might have seen in there. It's disabled because the logic to invalidate the visibleLeafNodes cache was never finished. It requires new code in ReaderView/ReflowableView.

@jmgeffroy getNormalizedRectangles is now the next biggest thing. The Firefox specific code is just the condition check in this if statement: if (clientRectList[i].height > 0) { So far I see that the whole body of the function is needed. Firefox or not.

What slows this function down is getClientRects() and createRange(). Not sure how to optimize the use of this yet as it's essential to the function's implementation.

[jccr]

@jdempcy You also need to have readium-cfi-js set to the branch of this PR too: https://github.com/readium/readium-cfi-js/pull/59

[jdempcy]

@JCCR Yes! Nice work. I can confirm that a page that was previously taking ~650ms is now consistently ~400ms for getFirstVisibleCfi().

[jccr]

I would also like to note that I tried to "clean up" usage of $element[0] vs just a direct reference element when passing along element refs in the private functions of the CfiNavLogic class. After the refactoring I was curious to see if it would perform better.. But doing this caused reallllly bad results. Something that took 400ms now took 2s+. In the timeline profile results I saw that when normalizeRectangles was doing element.getClientRects() instead of $element[0].getClientRects() there was a long chain of "recalculating layout" events.

Somehow using the element ref indirectly like this prevented the browser from triggering layout recalculation (which is what we want to keep things fast).

I think the reduced example case is like this:

var example = $example[0]; 
(slowFunction(el) {
el.getClientRects();
})(example); //loop this many times

/** VS **/

(fastFunction($el) {
$el[0].getClientRects();
})($example); //loop this many times

Take away: Don't clean up the $element[0] usage! It might not be as readable but it's serving us well somehow.

[jdempcy]

I noticed that saveCurrentPosition() also calls getFirstVisibleCfi() on every page turn.

By caching this value instead of computing it each time, we could conceivably greatly speed up page turns as well.

I can implement caching in our own client app, since we are calling getFirstVisibleCfi() on each page turn as well, but it would be nice if the method itself had some intelligent caching where subsequent calls without pagination changes in the interim would return a cached value rather than computing it anew.

[jdempcy]

Also, I noticed with your pull request, Juan, that while the getFirstVisibleCfi() method returns accurate locations, getLastVisibleCfi() returns "/4/NaN/NaN/NaN" for me every time. Do you know why this might be?

On the topic of performance improvements, is there anything else we could do on the Android side to get page turning faster? Has throttling the saveCurrentPosition() call been tested in the past? I am considering doing something like setting a timeout on it for 1000ms (for instance) and then canceling the timeout if the user turns the page before that time. It would be really nice to be able to page through multiple pages quickly, so we are exploring any and all ideas that would help reach this goal.

Thanks again for all your hard work! Let me know if there is anything I can help with.

[rkwright]

@jdempcy There is a similar report here

[jccr]

@jdempcy In regards to /4/NaN/.../NaN Are you using the scroll view in this scenario?

[bluefirepatrick]

No, we are using paginated.

[danielweck]

Is this now fixed by https://github.com/readium/readium-cfi-js/pull/61 ?

[jdempcy]

I have pulled down the latest readium-cfi-js develop, which I see has all these changes merged in.

I rebuilt readium-shared-js and included it in our app. I have confirmed that Juan's changes to readium-cfi-js are in the build artifact we are using (readium-shared-js_all.js).

Unfortunately, I have not found any noticeable change in performance.

Here are the timings for a chapter from The Iliad on a Nexus 7 Gen 2, before the change:

host_app_feedback.js:221 pageRequest: 1612.946ms host_app_feedback.js:221 pageRequest: 1489.319ms host_app_feedback.js:221 pageRequest: 1372.375ms host_app_feedback.js:221 pageRequest: 1434.906ms host_app_feedback.js:221 pageRequest: 1352.600ms

Here they are, after:

host_app_feedback.js:221 pageRequest: 1850.800ms host_app_feedback.js:221 pageRequest: 1485.717ms host_app_feedback.js:221 pageRequest: 1407.807ms host_app_feedback.js:221 pageRequest: 1385.986ms host_app_feedback.js:221 pageRequest: 1353.272ms host_app_feedback.js:221 pageRequest: 1296.051ms

This is for the same chapter.

I've set the timer to start when openPageNext() is called, and to end when the PAGINATION_CHANGED event is fired.

The first one is always a little longer because it is moving across spine items. The latter timings are all within the same range of ~1300-1500 ms which I have consistently seen.

So, there doesn't seem to be any difference.

I thought we would see at least a little improvement, so I've triple-checked to make sure Juan's changes are included here, and they are.

I wish I had better news. This doesn't seem to impact the CFI calculation timings at all, at least in my testing.

[rkwright]

@JCCR Any thoughts?

[jccr]

@jdempcy Are these changes in too?

https://github.com/readium/readium-shared-js/pull/371/files

There were change sets for both readium-shared-js and readium-cfi-js