Zibi Braniecki [:zbraniecki][:gandalf] Reporter
	Description • 12 years ago

As I was profiling through window_manager.js in gaia, I found something odd.

The time between when new app's iframe is being injected into DOM and the moment when the new document's navigationStart happens is around ~550ms.

In particular I measured the timestamps between this:
https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/window_manager.js#L1139

and the mozbrowserloadstart event which equals the performance.timing.navigationStart timing from the child process.

Template app:
iframe.src: 1358303814312
mozbrowserloadstart: 1358303814892
diff: 580


SMS app:
iframe.src: 1358304442682
mozbrowserloadstart: 1358304443254
diff: 572

I tested it against the web browser app which is in-process 

iframe.src: 1358305636023
mozbrowserloadstart: 1358305636179
diff: 156

Is that a static cost of creating an OOP iframe?

	Justin Lebar (not reading bugmail)
	Comment 1 • 12 years ago

> Is that a static cost of creating an OOP iframe?

My first rule of performance optimization is to profile rather than guess at the answer to this sort of question.  But also, I don't know.  :)

I saw a ~500ms speed-up of app startup in bug 819000 by loading about:blank into the app's docshell when we preload the app process.  Perhaps we're seeing the overhead of setting up all the things that happen on the first docshell navigation.

Unfortunately loading about:blank is complicated to do right, because at the point that we're doing that, the process is not hooked up to IPC, etc.  It's something I hope I or someone else can look into, but not for v1...

	Zibi Braniecki [:zbraniecki][:gandalf] Reporter
	Comment 2 • 12 years ago

Justin: do you have any idea how can I profile that? Gecko profiler shows nothing in b2g(system) and nothing in the child process. I just don't know how to profile it properly...

	Justin Lebar (not reading bugmail)
	Comment 3 • 12 years ago

> Gecko profiler shows nothing in b2g(system) and nothing in the child process.

You mean, the Gecko profiler shows that the system and child processes are completely idle during app startup?  That seems quite incorrect.

How are you profiling, exactly?

TBH I've had relatively little luck with the Gecko profiler on B2G because last time I checked it was unable to get C++ stacks.  It could only get the innermost C++ stack frame.  This is apparently because the mechanism we use for unwinding stacks doesn't work when run from a signal handler.

Perhaps we should look into getting a working native-ccode profiler on B2G.  Maybe we can get perf to work, for example.

	Zibi Braniecki [:zbraniecki][:gandalf] Reporter
	Comment 4 • 12 years ago

(In reply to Justin Lebar [:jlebar] from comment #3)
> > Gecko profiler shows nothing in b2g(system) and nothing in the child process.
> 
> You mean, the Gecko profiler shows that the system and child processes are
> completely idle during app startup?

Positive.

>  That seems quite incorrect.

Yeah, that's what concerns me. I don't know what's going on there and I don't know how to find out.

> How are you profiling, exactly?

I run the Gecko profiler on native device.
1) ./profile.sh start
2) unlock phone, switch to second card
3) wait 20 seconds idle
4) tap Template app
5) wait for it to load
6) ./profile.sh capture

Here are the dumps:

1) b2g(system) - http://people.mozilla.com/~bgirard/cleopatra/#report=968c496a759ae08a770d5db00266a6fe009abb02
2) homescreen - http://people.mozilla.com/~bgirard/cleopatra/#report=f028cccaf438af771fb77dfd0abc6177d212af75
3) preallocated - http://people.mozilla.com/~bgirard/cleopatra/#report=3c925c5ec3df7b5a8010dcfb31ba5ecec6ed95e4
4) template app - http://people.mozilla.com/~bgirard/cleopatra/#report=8390622226d3fd427169794a5022fee757a3eb56

Honestly, the template app profile is confusing beyond measure to me. No DOM, no JS, no CSS, it looks like it's missing 90% of the meat.

But that's not the issue with this bug. I can measure the Gecko's DOM/CSS/JS parsing and execution from within the child process and I know it's there and I know how much it takes.

What I don't know is why the system profile is 4385-4699 shows no more than 50ms boot activity, while the interval between iframe's activation and child process init is over 550ms.
That's what bothers me. If system process is not active, and child process is not yet active, is it kernel that takes this time? Or is it Gecko? Or some other dark magic?

Any ideas what it may be or who may have some clues?

	Justin Lebar (not reading bugmail)
	Comment 5 • 12 years ago

> No DOM, no JS, no CSS, it looks like it's missing 90% of the meat.

Indeed.  But perhaps what's going on here is that we're missing the non-innermost parts of the stacks.  All of the stacks you see are either JS or explicit annotations for Cleopatra, AIUI.  So all of the DOM could be hidden under __futex_syscall3 or something.

Also, the template app doesn't have a lot of DOM/CSS, so it's not so surprising that it might be hard to find in the (severely truncated) profile.

I still admit it looks pretty weird, though; the explanation above is not entirely satisfying to me.

> What I don't know is why the system profile is 4385-4699 shows no more than 50ms boot activity, 
> while the interval between iframe's activation and child process init is over 550ms.

There's 662ms of activity in the homescreen app over its lifetime, so maybe that's OK.  But I agree, the template app is confounding, as there's only 179ms of activity in it, and that is, I presume, counting the time it spends as the preallocated app.  How long does it take you to load the template app?

	Zibi Braniecki [:zbraniecki][:gandalf] Reporter
	Comment 6 • 12 years ago

(In reply to Justin Lebar [:jlebar] from comment #5)
> There's 662ms of activity in the homescreen app over its lifetime, so maybe
> that's OK.  But I agree, the template app is confounding, as there's only
> 179ms of activity in it, and that is, I presume, counting the time it spends
> as the preallocated app.  How long does it take you to load the template app?

Most recent profile: https://bugzilla.mozilla.org/show_bug.cgi?id=809668#c9

The navigationStart in 400ms is an optimistic one, more often I get those 550ms described here, but the total stays the same 1100ms, out of which ~500-600ms is the actual time between navigationStart and when document is ready.

Which nicely matches the missing variable here - the stuff from before navigationStart on child process.

	Zibi Braniecki [:zbraniecki][:gandalf] Reporter
	Comment 7 • 12 years ago

dupe of bug 797189 per jlebar's comment on IRC.