905223 - move java-side session restore reading/processing to a background thread

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect)

Comment 1

[Nathan Froyd [:froydnj]]

Attachment: part 1 - factor out computations for determining what URL we were invoked with

We need to know whether we're loading an external URL much earlier than onWindowFocusChanged.
But we still need to know our passed URL and whether it's external in onWindowFocusChanged.
So let's try to factor out the computations a little bit so we can share code.

I'm not completely happy with how this turned out; I'm open to better ways of structuring
this.

Comment 2

[Nathan Froyd [:froydnj]]

Attachment: part 2 - move sessionstore loading onto the background thread

Bug 903553 discusses at some length just how bad JSON parsing in Java is.  With a session
of moderate size, we spend a significant amount of startup time (~200ms) parsing the
sessionstore file.  I don't think rewriting the session store file format is a good idea,
and trying to avoid some of the JSON file parsing and serialization (e.g. not serializing
into JSON for sending things into Gecko) would be...ugly.

If we can't avoid the work, how about we try to move it out of the critical path by parsing
on a background thread?  Traces indicate that there's a bunch of free time on the background
thread.  At the very least, the slow bits of reading the IO can be overlapped with other
main thread computation and (on dual-core devices) we can spin doing JSON ops while we're
on the main thread too.

Performance numbers coming in the next patch, which moves all of this even earlier.

Comment 3

[Nathan Froyd [:froydnj]]

Attachment: part 2b - try starting session restore a little earlier

Now that we're parsing on a background thread, why don't we try moving the parsing a
bit earlier so that we can try and ensure that we don't collide with other things we
were already doing on the background thread?

I tested this patch series on a Galaxy Nexus; we easily win several hundred ms of
startup time by doing this.  I don't have any single core devices to test this on;
suggestions for such beasts appreciated.

Comment 4

[Nathan Froyd [:froydnj]]

Chris, if you wanted to benchmark this with your robocop setup, that'd be appreciated.  If you don't, then at least you're aware of the bug, so ni?'ing you.

Comment 5

[Wesley Johnston (:wesj)]

Can we just not read the JSON here? We're just reading this to find a few very specific things about that tabs:

http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/GeckoApp.java#1619

We can pretty easily put that into some SharedPrefs that we save in onPause and pull out only when we're restoring session?

Comment 6

[Chris Kitching [:ckitching]]

(In reply to Nathan Froyd (:froydnj) from comment #4)
> Chris, if you wanted to benchmark this with your robocop setup, that'd be
> appreciated.  If you don't, then at least you're aware of the bug, so
> ni?'ing you.

Roger. I'll benchmark this and get back to you.

Comment 7

[Mark Finkle (:mfinkle) (use needinfo?)]

(In reply to Wesley Johnston (:wesj) from comment #5)
> Can we just not read the JSON here? We're just reading this to find a few
> very specific things about that tabs:
> 
> http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/GeckoApp.
> java#1619
> 
> We can pretty easily put that into some SharedPrefs that we save in onPause
> and pull out only when we're restoring session?

I'd rather not have data in SharedPrefs (which I hate in general) and the JSON file. One place of truth feels right.

Comment 8

[Chris Kitching [:ckitching]]

https://www.dropbox.com/s/pnb6fs7bpw5lsxu/FennecStartupLog.trace

Here's a startup profile using a single tab with session restore and the patches here.

This change hasn't really made it any faster, we just now do it on the backrground thread. (As expected, I suppose).
This still sucks very badly for single-core phones.

Comment 9

[Nathan Froyd [:froydnj]]

(In reply to Chris Kitching [:ckitching] from comment #8)
> https://www.dropbox.com/s/pnb6fs7bpw5lsxu/FennecStartupLog.trace
> 
> Here's a startup profile using a single tab with session restore and the
> patches here.
> 
> This change hasn't really made it any faster, we just now do it on the
> backrground thread. (As expected, I suppose).
> This still sucks very badly for single-core phones.

OK, that is actually consistent with the numbers I was seeing from startup traces.  But when I went and benchmarked with the startup numbers in about:telemetry, I was consistently seeing wins.  The benchmarking with about:telemetry is tedious (though maybe there's some way to get the numbers from robocop), but I felt much better about the rightness of the universe after looking at the numbers there.

Comment 10

[Chris Kitching [:ckitching]]

(In reply to Nathan Froyd (:froydnj) from comment #9)
> OK, that is actually consistent with the numbers I was seeing from startup
> traces.  But when I went and benchmarked with the startup numbers in
> about:telemetry, I was consistently seeing wins.  The benchmarking with
> about:telemetry is tedious (though maybe there's some way to get the numbers
> from robocop), but I felt much better about the rightness of the universe
> after looking at the numbers there.

You feel much better about the rightness of the universe by selecting only data which support your hypothesis? :P

And yes, this seems about what we expect - some performance improvement on multi-core devices, no real change on single-core devices. Also, no real change in total CPU time - just the concurrency has increased.
This is a useful patch, but it's not sufficient to make this problem go away. It mitigates it somewhat on more high-end devices (Where the problem was less present to start with anyway).

Comment 11

[Nathan Froyd [:froydnj]]

(In reply to Chris Kitching [:ckitching] from comment #10)
> (In reply to Nathan Froyd (:froydnj) from comment #9)
> > OK, that is actually consistent with the numbers I was seeing from startup
> > traces.  But when I went and benchmarked with the startup numbers in
> > about:telemetry, I was consistently seeing wins.  The benchmarking with
> > about:telemetry is tedious (though maybe there's some way to get the numbers
> > from robocop), but I felt much better about the rightness of the universe
> > after looking at the numbers there.
> 
> You feel much better about the rightness of the universe by selecting only
> data which support your hypothesis? :P

Somewhat. :p  It's certainly strange that the tracing profiler shows little to no speedup, whereas a different method of measuring time shows significant speedups.  Somebody's gotta be wrong...

> And yes, this seems about what we expect - some performance improvement on
> multi-core devices, no real change on single-core devices. Also, no real
> change in total CPU time - just the concurrency has increased.
> This is a useful patch, but it's not sufficient to make this problem go
> away. It mitigates it somewhat on more high-end devices (Where the problem
> was less present to start with anyway).

Agreed.  I don't, however, see a lot of ways to improve it generally.  Restoring the tabs (for a small session of six tabs, with < 2K of session restore data!) takes ~190ms on a Galaxy Nexus:

- 87ms to read the session file;
- 44ms to parse;
- 58ms to stringify JSON.

The first part is basically all Java I/O.  Can't do much about that.

The second part is likewise fairly constrained.  More than half of that is allocating JSON objects.  The rest of it is spent in Tabs.loadUrl, which is doing more JSON stuff.  I tried making Tabs.loadUrl more Javaish yesterday and it didn't seem to help (then again, Tabs.loadUrl takes about 11ms total, so...).

The second and third parts could possibly be sped up by using a faster JSON library.

Comment 12

[Brian Nicholson (:bnicholson)]

Comment on attachment 790279 [details] [diff] [review]
part 2 - move sessionstore loading onto the background thread

Review of attachment 790279 [details] [diff] [review]:
-----------------------------------------------------------------

::: mobile/android/base/GeckoApp.java
@@ +1297,5 @@
>  
> +        mSessionLoader = new Runnable() {
> +                @Override
> +                public void run() {
> +                    synchronized(this) {

Just making run() a synchronized method has the same effect.

@@ +1455,5 @@
>  
>          initializeChrome();
>  
> +        // Wait for the session loader to finish and send the data to Gecko.
> +        synchronized(mSessionLoader) {

I think there's a race here, albeit an unlikely one. The synchronization in the session loader runnable happens on a separate thread, so there's no guarantee about the execution order, even though the runnable has *probably* run already since it's created in onCreate().

Have you tried adding logging right before this, and at the beginning/end of the runnable? I'm curious to know a) how long the runnable is taking, and b) whether (and how long) this block actually ends up waiting.

Comment 13

[Chris Kitching [:ckitching]]

(In reply to Nathan Froyd (:froydnj) from comment #11)
> The second and third parts could possibly be sped up by using a faster JSON
> library.

And the only sane way to do that is to go native, as outlined in the other bug.

Joy. I'll finish native encode at some point.. I got native decode sort of working, although it broke all the unit tests and it's not clear how to debug segfaults on try which don't happen locally.

Comment 14

[Nathan Froyd [:froydnj]]

(In reply to Brian Nicholson (:bnicholson) from comment #12)
> Comment on attachment 790279 [details] [diff] [review]
> part 2 - move sessionstore loading onto the background thread
> 
> Review of attachment 790279 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: mobile/android/base/GeckoApp.java
> @@ +1297,5 @@
> >  
> > +        mSessionLoader = new Runnable() {
> > +                @Override
> > +                public void run() {
> > +                    synchronized(this) {
> 
> Just making run() a synchronized method has the same effect.

Indeed.

> @@ +1455,5 @@
> >  
> >          initializeChrome();
> >  
> > +        // Wait for the session loader to finish and send the data to Gecko.
> > +        synchronized(mSessionLoader) {
> 
> I think there's a race here, albeit an unlikely one. The synchronization in
> the session loader runnable happens on a separate thread, so there's no
> guarantee about the execution order, even though the runnable has *probably*
> run already since it's created in onCreate().

Ooo...good point.  That should be fixed, because it would come back to bite us.

> Have you tried adding logging right before this, and at the beginning/end of
> the runnable? I'm curious to know a) how long the runnable is taking, and b)
> whether (and how long) this block actually ends up waiting.

The runnable should take ~200ms on a Galaxy Nexus; at least that's about what it was taking before this patch series.  I can check to see how long that block winds up waiting.

(In reply to Chris Kitching [:ckitching] from comment #13)
> (In reply to Nathan Froyd (:froydnj) from comment #11)
> > The second and third parts could possibly be sped up by using a faster JSON
> > library.
> 
> And the only sane way to do that is to go native, as outlined in the other
> bug.

After having dealt with JNI, I don't know that I'd call that "sane"...

> Joy. I'll finish native encode at some point.. I got native decode sort of
> working, although it broke all the unit tests and it's not clear how to
> debug segfaults on try which don't happen locally.

Usually that means there's some sort of race (not necessarily a bug, just different event handling orders) or you have some uninitialized memory somewhere.

Comment 15

[Chris Kitching [:ckitching]]

(In reply to Nathan Froyd (:froydnj) from comment #14)
> After having dealt with JNI, I don't know that I'd call that "sane"...

I LIKE the JNI.

Plus, I've spent the last few days working on bug 794981, so I've had lots of recent practice.

Plus I once used it to implement an IPC scheme between PHP and Java using POSIX shared memory segments. That's in no way sane. Everyone else seems highly sane after that. :P

> Usually that means there's some sort of race (not necessarily a bug, just
> different event handling orders) or you have some uninitialized memory
> somewhere.

I see. That's both useful and unuseful at the same time. :P

Comment 16

[Brad Lassey [:blassey] (use needinfo?)]

Comment on attachment 790280 [details] [diff] [review]
part 2b - try starting session restore a little earlier

Review of attachment 790280 [details] [diff] [review]:
-----------------------------------------------------------------

I'd point to mfinkle for review here, and it looks like he's already redirected to brian

Comment 17

[Brad Lassey [:blassey] (use needinfo?)]

Comment on attachment 790276 [details] [diff] [review]
part 1 - factor out computations for determining what URL we were invoked with

Review of attachment 790276 [details] [diff] [review]:
-----------------------------------------------------------------

r=me, with nits changed

::: mobile/android/base/GeckoApp.java
@@ +1372,5 @@
>              Tabs.getInstance().loadUrl(url, flags);
>          }
>      }
>  
> +    private String intentURI() {

I'd prefer you pass in the Intent here.

@@ +1383,5 @@
> +
> +        return passedUri;
> +    }
> +
> +    private boolean invokedWithExternalURL() {

and I'd prefer you pass in the passedUri here

Comment 18

[Brian Nicholson (:bnicholson)]

Comment on attachment 790276 [details] [diff] [review]
part 1 - factor out computations for determining what URL we were invoked with

Review of attachment 790276 [details] [diff] [review]:
-----------------------------------------------------------------

::: mobile/android/base/GeckoApp.java
@@ +1372,5 @@
>              Tabs.getInstance().loadUrl(url, flags);
>          }
>      }
>  
> +    private String intentURI() {

nit: Following Java getter convention, this should be getIntentURI (or getIntentUri).

Comment 19

[Brian Nicholson (:bnicholson)]

Comment on attachment 790279 [details] [diff] [review]
part 2 - move sessionstore loading onto the background thread

Review of attachment 790279 [details] [diff] [review]:
-----------------------------------------------------------------

r- for the race mentioned in comment 12.

Comment 20

[Mark Finkle (:mfinkle) (use needinfo?)]

Comment on attachment 790279 [details] [diff] [review]
part 2 - move sessionstore loading onto the background thread

>diff --git a/mobile/android/base/GeckoApp.java b/mobile/android/base/GeckoApp.java

>+        ThreadUtils.postToBackgroundThread(mSessionLoader);

Your comment about doing this earlier to avoid running into other background thread work made me realize something: This could be run on any thread, not "the" background thread.

You have no way to know this, so I am just pointing it out. We started using ThreadUtils.xXXBackgroundThread for database related work. We wanted to serialize things coming and going into the databases. We were getting weird corruptions. But I digress!

Since this code has no database interactions, you can run it on any background thread.

We had talked about adding a ThreadUtils.xXXDatabaseThread, which used only a single thread, and change ThreadUtils.xXXBackgroundThread to use a pool of threads (for non-database related work).

Comment 21

[Jan Henning [:JanH]]

From margaret's comments in bug 1266339, it would be nice to finally move the session restore I/O off the main thread.

Comment 22

[Jan Henning [:JanH]]

Attachment: MozReview Request: Bug 905223 - Part 0 - Add target API annotations to get rid of errors in Android Studio. r=margaret

Android Studio doesn't recognise our version guards and is consequentially always showing two errors in GeckoApp, which makes it more difficult to spot when you've introduced an actual error.

Review commit: https://reviewboard.mozilla.org/r/52930/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/52930/

Comment 23

[Jan Henning [:JanH]]

Attachment: MozReview Request: Bug 905223 - Part 1 - Factor out external URL calculation. r=margaret

For session data parsing, we need to know whether we were invoked with an external URL or not. Since we want to move session data parsing forward to an earlier point in time, but also continue needing that external URL info during initialize() as well, we'll factor out those calculations into their own functions which can then be called from both places.

Review commit: https://reviewboard.mozilla.org/r/52932/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/52932/

Comment 24

[Jan Henning [:JanH]]

Attachment: MozReview Request: Bug 905223 - Part 2 - Move session data parsing into a background thread. r=jchen

Parsing the session store JSON data to restore the last session's tabs is both
- computationally relatively expensive
- involving disk I/O

therefore, we shouldn't be doing it on the main thread.

To make sure the session data is actually ready, subsequent code running from a different thread that needs to access it (sending the session restore string to Gecko, the Recent Tabs panel reading the "tabs from last time") waits on a CountDownLatch which is released once the relevant data has been processed.

Review commit: https://reviewboard.mozilla.org/r/52934/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/52934/

Comment 25

[Jan Henning [:JanH]]

Attachment: MozReview Request: Bug 905223 - Part 3 - Move the session parsing in front of the layout initialisation. r=margaret

Since we're doing this in background now anyway, we might as well start doing it slightly earlier and run in parallel to parts of the layout setup, so we don't bump immediately into the the following, preexisting bit of background initialisation.

Review commit: https://reviewboard.mozilla.org/r/52936/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/52936/

Comment 26

[Jan Henning [:JanH]]

Attachment: MozReview Request: Bug 905223 - DON'T LAND - Debug log

Check the state of the CountDownLatches to see whether they've been already released when calling await().

Review commit: https://reviewboard.mozilla.org/r/52938/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/52938/

Comment 27

[Jan Henning [:JanH]]

This is basically a resurrected version of Nathan's patches - the major difference is that I've opted for using CountDownLatches to wait for the background thread session data processing to have finished.

As it currently stands, this bug depends on bug 1266339, although it's not a hard dependency - it's just that I'd have to rewrite the bits touching GeckoProfile.updateSessionFile() if I wanted to land them in the reverse order.

Comment 28

[Mark Finkle (:mfinkle) (use needinfo?)]

Best to move review -> Margaret

Comment 29

[Jan Henning [:JanH]]

Comment on attachment 8753018 [details]
MozReview Request: Bug 905223 - Part 0 - Add target API annotations to get rid of errors in Android Studio. r=margaret

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52930/diff/1-2/

Comment 30

[Jan Henning [:JanH]]

Comment on attachment 8753019 [details]
MozReview Request: Bug 905223 - Part 1 - Factor out external URL calculation. r=margaret

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52932/diff/1-2/

Comment 31

[Jan Henning [:JanH]]

Comment on attachment 8753020 [details]
MozReview Request: Bug 905223 - Part 2 - Move session data parsing into a background thread. r=jchen

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52934/diff/1-2/

Comment 32

[Jan Henning [:JanH]]

Comment on attachment 8753021 [details]
MozReview Request: Bug 905223 - Part 3 - Move the session parsing in front of the layout initialisation. r=margaret

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52936/diff/1-2/

Comment 33

[Jan Henning [:JanH]]

Comment on attachment 8753022 [details]
MozReview Request: Bug 905223 - DON'T LAND - Debug log

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52938/diff/1-2/

Comment 34

[:Margaret Leibovic]

Comment on attachment 8753018 [details]
MozReview Request: Bug 905223 - Part 0 - Add target API annotations to get rid of errors in Android Studio. r=margaret

https://reviewboard.mozilla.org/r/52930/#review49894

Comment 36

[:Margaret Leibovic]

Sorry I've been slow to get around to reviewing this.

jchen, do you think you could help take a look at these patches? When I see threads I think of you :)

Comment 37

[(inactive) Jim Chen [:jchen] [:darchons]]

https://reviewboard.mozilla.org/r/52934/#review52236

I took a quick look, but I'm not too knowledgeable about session restore.

::: mobile/android/base/java/org/mozilla/gecko/GeckoApp.java:206
(Diff revision 2)
>      private final HashMap<String, PowerManager.WakeLock> mWakeLocks = new HashMap<String, PowerManager.WakeLock>();
>  
>      protected boolean mLastSessionCrashed;
>      protected boolean mShouldRestore;
> +    private String mRestoreMessage;
> +    private final CountDownLatch mSessionRestoreParsingFinished = new CountDownLatch(1);

See the other comment about using boolean flag and synchronization.

::: mobile/android/base/java/org/mozilla/gecko/GeckoApp.java:1542
(Diff revision 2)
> -                    Log.e(LOGTAG, "An error occurred during restore", e);
> -                    mShouldRestore = false;
> -                }
> -            }
> +        }
> -
> -            GeckoAppShell.notifyObservers("Session:Restore", restoreMessage);
> +        if (!mIsRestoringActivity) {
> +            GeckoAppShell.notifyObservers("Session:Restore", mRestoreMessage);

You can put this inside the background Runnable, so you shouldn't need to add mRestoreMessage at all.

::: mobile/android/base/java/org/mozilla/gecko/GeckoProfile.java:82
(Diff revision 2)
>      // Session store
>      private static final String SESSION_FILE = "sessionstore.js";
>      private static final String SESSION_FILE_BACKUP = "sessionstore.bak";
>      private static final long MAX_BACKUP_FILE_AGE = 1000 * 3600 * 24; // 24 hours
>  
> +    private final CountDownLatch mOldSessionDataProcessed = new CountDownLatch(1);

Instead of CountDownLatch, you should use, e.g., a boolean flag with synchronization,
```java
private boolean mOldSessionDataProcessed;
```

To signal completion, you would use,
```java
synchronized (this) {
    mOldSessionDataProcessed = true;
    notifyAll();
}
```

To wait for completion, you would use,
```java
synchronized (this) {
    while (!mOldSessionDataProcessed) {
        try {
            wait();
        } catch (final InterruptedException e) {
            // Ignore
        }
    }
}
```

Comment 38

[:Margaret Leibovic]

Comment on attachment 8753019 [details]
MozReview Request: Bug 905223 - Part 1 - Factor out external URL calculation. r=margaret

https://reviewboard.mozilla.org/r/52932/#review52300

::: mobile/android/base/java/org/mozilla/gecko/GeckoApp.java:1487
(Diff revision 2)
>          mWasFirstTabShownAfterActivityUnhidden = true; // Reset since we'll be loading a tab.
>  
>          final SafeIntent intent = new SafeIntent(getIntent());
>          final String action = intent.getAction();
>  
> -        final String uri = getURIFromIntent(intent);
> +        final String passedUri = getIntentURI();

Can we pass the intent as a parameter to this method? Otherwise we're creating the same SafeIntent twice.

Comment 39

[:Margaret Leibovic]

Comment on attachment 8753021 [details]
MozReview Request: Bug 905223 - Part 3 - Move the session parsing in front of the layout initialisation. r=margaret

https://reviewboard.mozilla.org/r/52936/#review52304

I'm not convinced this is necessary, and it makes me a bit nervous. This seems like something we could address in a follow-up bug, to measure any performance impact separately.

Comment 40

[Jan Henning [:JanH]]

Comment on attachment 8753018 [details]
MozReview Request: Bug 905223 - Part 0 - Add target API annotations to get rid of errors in Android Studio. r=margaret

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52930/diff/2-3/

Comment 41

[Jan Henning [:JanH]]

Comment on attachment 8753019 [details]
MozReview Request: Bug 905223 - Part 1 - Factor out external URL calculation. r=margaret

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52932/diff/2-3/

Comment 42

[Jan Henning [:JanH]]

Comment on attachment 8753020 [details]
MozReview Request: Bug 905223 - Part 2 - Move session data parsing into a background thread. r=jchen

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52934/diff/2-3/

Comment 43

[Jan Henning [:JanH]]

Comment on attachment 8753019 [details]
MozReview Request: Bug 905223 - Part 1 - Factor out external URL calculation. r=margaret

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52932/diff/3-4/

Comment 44

[Jan Henning [:JanH]]

Comment on attachment 8753020 [details]
MozReview Request: Bug 905223 - Part 2 - Move session data parsing into a background thread. r=jchen

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/52934/diff/3-4/

Comment 45

[(inactive) Jim Chen [:jchen] [:darchons]]

Comment on attachment 8753020 [details]
MozReview Request: Bug 905223 - Part 2 - Move session data parsing into a background thread. r=jchen

https://reviewboard.mozilla.org/r/52934/#review52626

Comment 46

[Jan Henning [:JanH]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=aaf84adcc14f

Comment 47

[Pulsebot]

https://hg.mozilla.org/integration/fx-team/rev/17386d25f260
https://hg.mozilla.org/integration/fx-team/rev/5fc62e209fc7
https://hg.mozilla.org/integration/fx-team/rev/d4f569803fec

Comment 48

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/17386d25f260
https://hg.mozilla.org/mozilla-central/rev/5fc62e209fc7
https://hg.mozilla.org/mozilla-central/rev/d4f569803fec