Thomas Arend [:tarend] Reporter
	Description • 14 years ago

Comparing launch time - see video at http://bit.ly/gjD3Kk (left: B3 right:B4)
(1) Set up two identical Nexus S devices, one with Beta 3, the other with Beta 4
(2) Set both browser start pages to http://www.mozilla.com/en-US/m/
(3) cold-restart browser on both devices

Result: Beta 4 brings up chrome a little faster but seems to take longer to render the page. Overall, from tap of the icon to showing content, Beta 3 is slightly faster.
Expected: Beta 4 launches and renders first page significantly faster than Beta 3

Can we do some detailed performance profiling?

	Brad Lassey [:blassey] (use needinfo?)
	Comment 1 • 14 years ago

Is this first run? or have you let each device create a profile already? We haven't done much for first run in this dev cycle.

	Thomas Arend [:tarend] Reporter
	Comment 2 • 14 years ago

This is not first run. Profiles were created on both phones before. I saw some variation in my tests (of course, this is not an exact method to measure performance) - in most cases the Beta 3 version showed the web page faster, as can be seen in the video. Only sometimes both versions seemed to show the web page at about the same time.

	Alon Zakai (:azakai)
	Comment 3 • 14 years ago

I will get ipc profiling (bug 596725) to work on device and see what that shows.

	Mark Finkle (:mfinkle) (use needinfo?)
	Comment 4 • 14 years ago

Bug 632005 landed and gave us a 14.6% Tp improvement. The improvement came from a reduction in ipc STATE messages and a reduction in XPConnect calls into a JS implementation of a webprogress listener.

I have been looking for more wins, but haven't found any yet.

Bug 632037 has some general optimization changes that improve Tp by another ~15%.

	Alon Zakai (:azakai)
	Comment 5 • 14 years ago

Startup IPC profiles (2 runs).

Not sure there is anything useful here. The latency just shows the child is busy while the parent floods it with stuff to do.

	Alon Zakai (:azakai)
	Comment 6 • 14 years ago

Some IPC profiling data for loading google.com (the nonmobile version).

	Alon Zakai (:azakai)
	Comment 7 • 14 years ago

IPC profile data for doing a google search for 'mozilla' in the awesomebar. Result is a google mobile page.

	Alon Zakai (:azakai)
	Comment 8 • 14 years ago

In google.com, we suffer

PStorageChild|Msg_GetValue [SYNC/RPC]    total latency:     0.0149    total processing:     0.6279

that is, 0.63 seconds are spent processing web storage. If we disable web storage, this would go away.

Otherwise nothing seems to jump out of the data.

	Doug Turner (:dougt)
	Comment 9 • 14 years ago

alon, could you create a followup to disable storage.

	Mark Finkle (:mfinkle) (use needinfo?)
	Comment 10 • 14 years ago

(In reply to comment #9)
> alon, could you create a followup to disable storage.

Whoa - let's not be hasty. What storage are we talking about?

	Mark Finkle (:mfinkle) (use needinfo?)
	Comment 11 • 14 years ago

What is this about:

PHttpChannelParent|Msg_OnStatus               total latency:     8.5068    total processing:     0.0199    total: 45:45:45
PHttpChannelParent|Msg_OnProgress               total latency:     1.8206    total processing:     0.0126    total: 4:4:4

They are at the top of the list and it jumps out at me

	Alon Zakai (:azakai)
	Comment 12 • 14 years ago

(In reply to comment #9)
> alon, could you create a followup to disable storage.

We can do that in bug 627635, where discussion about disabling web storage already took place. I posted about the data from here in that bug.

Disabling web storage is very easy, it's just a matter of deciding to do so. (Or we can just pref it off by default.)

	Alon Zakai (:azakai)
	Comment 13 • 14 years ago

(In reply to comment #11)
> What is this about:
> 
> PHttpChannelParent|Msg_OnStatus               total latency:     8.5068   
> total processing:     0.0199    total: 45:45:45
> PHttpChannelParent|Msg_OnProgress               total latency:     1.8206   
> total processing:     0.0126    total: 4:4:4
> 
> They are at the top of the list and it jumps out at me

These do have a lot of latency, but the definition of latency is "*total* of |amount of time between sending the message, to starting to do something about it on the other side|".

The reported amount should possibly be 'average latency' and not total. Average latency for the first is 0.18, for the second 0.45. That is still significant, and we should perhaps look more into this, but I suspect it is just that there is a burst of HTTP traffic, and a lot of messages end up overlapping.

	Alon Zakai (:azakai)
	Comment 14 • 14 years ago

Here is a picture of IPC traffic (parent process), just to clarify the latency issue. Each line is a single message. As you can see, there is a lot of overlap.

	Mark Finkle (:mfinkle) (use needinfo?)
	Comment 15 • 14 years ago

On simple sites, like google.com, I don't see much OnProgress and OnStatus message traffic. But on CNN or Yahoo, I see several hundred message sent.

I still can't determine if removing the messages makes the Tp any faster. My tools are failing me at the moment.

	Mark Finkle (:mfinkle) (use needinfo?)
	Comment 16 • 14 years ago

Filed bug 633442 to try to reduce the messages. I found removing them yields a 8.7% Tp improvement

	Alon Zakai (:azakai)
	Comment 17 • 14 years ago

Here is some preliminary data from a new event profiling patch I am working on. Patch is at http://hg.mozilla.org/users/azakai_mozilla.com/patches/file/tip/enventigating_no_rtti

The patch automatically rewrites the C++ codebase so that we can identify all runnables (and, partially, events). The output shows what runnables/events took up our time.

This file is for the parent process, and is for warm startup + load wikipedia's 'wiki' page.

Notes:

* main|side means which thread the event/runnable ran in.

Caveats:

* No checking for recursion. If one runnable ends up running additional runnables inside it, its total time will include its children.
* nsTimerEvent is not very informative yet, since we don't know which timer event is active here. I will try later to use my wakeup patch to help with that.
* DoWorkRunnable is a runnable that does IPC stuff. So pretty much all IPC stuff will look like this. But we have separate profiling data for IPC data.
* Only events/runnables that take longer than 0.01 seconds are noticed.
* Events are identified by their numerical identifiers, not string names yet.

	Alon Zakai (:azakai)
	Comment 18 • 14 years ago

Child process stuff.

	Mark Finkle (:mfinkle) (use needinfo?)
	Comment 19 • 14 years ago

Moving this investigation to blocking final. We have got 2 improvements from this work in for beta 5, which is good. Hopefully, more will come.

	Alon Zakai (:azakai)
	Comment 20 • 14 years ago

More raw profiling data than you can shake a stick at. Includes timer identifications.

	Alon Zakai (:azakai)
	Comment 21 • 14 years ago

Some commentary on this data:

1. Sync spends ~0.5 seconds on first startup, and ~0.1 seconds on warm startup later, on the main thread. This is without setting anything up for sync.

2. SessionStore takes some time in first startup and subsequent startups, sometimes quite a lot (2.3 seconds in one case!), but mostly 0.1 seconds or so. On every page load in the parent process, however, we spend some ~0.05 seconds in SessionStore (and sometimes significantly more), in the main thread.

3. |./dom/base/nsJSEnvironment.cpp:3591| and |./content/events/src/nsEventStateManager.cpp:809| are the GC timer. This takes ~0.3 secs on first startup, then 0.1-0.3 seconds every few page loads (not every one) and on first warm startup.

4. First warm startup after first run is not very fast. Subsequent warm startups are much faster. Visually, one difference is that the "Add-ons for your Fennec" thingie spins for a long time here. In the profiling data, |./dom/base/nsGlobalWindow.cpp:8826| is high, which is a setTimeout or Interval. Does the Addons thingie do a lot of stuff in a timeout? If so can we make it a web worker?

5. AsyncAssociateIconToPage and InsertVisitedURIs can take a second or more in some cases, less (or even 0) in others. At least they are on a side thread, but still a lot of time is spent in these two.

6. icanhascheezburger.com: Very intensive website. The parent process actually has little activity in it - no more than other websites - which is very good, and shows how responsive the browser is. In the child process, almost all the work is in PaintTask.

	Alon Zakai (:azakai)
	Comment 22 • 14 years ago

> 1. Sync spends ~0.5 seconds on first startup, and ~0.1 seconds on warm startup
> later, on the main thread. This is without setting anything up for sync.

I'm having trouble building for Android now for some reason, but on Linux desktop built today, I don't see sync anymore (unless I do something with it), confirming what dougt said to me on IRC. So it seems this is not an issue.

	Mark Finkle (:mfinkle) (use needinfo?)
	Comment 23 • 14 years ago

FWIW:

Runnable|./mobile/components/SessionStore.js:378

This is where the sessions store does a delayed write to disk of the current session. I'm not sure why it's triggered at startup. At most, it should wait 2 secs before writing out the state. If a new state request is triggered while we're waiting to write out the state, we ignore it.

	Mark Finkle (:mfinkle) (use needinfo?)
	Comment 24 • 14 years ago

Making this a meta bug for page load issues