Slow app startup time

[Rick Spencer]

Since upgrading to trusty, applications have been taking longer and longer to load. While on the one hand, there is feature work and investigation to do, see: https://blueprints.launchpad.net/ubuntu/+spec/appdev-1311-sdk-apps-performance on the other hand, this is a regression and should be handled via a bug report for that reason.

[Bill Filler (bfiller)]

I've been doing some testing on both the emulator and using Nexus 4. Testing startup time of Contacts app from unity, the command line, and upstart.

The results can be found here:
https://docs.google.com/a/canonical.com/spreadsheet/ccc?key=0As1Fg7XBGWTjdDJ3VHptQUN5RGNnVmpmZTVFLXg2cEE#gid=0

There is a clear performance hit using upstart but not yet clear what exactly is causing the slowdown. Some of the timing suggests that part of it may be chaining upstart jobs and the overhead associated with that. But most likely there are other causes.

[Bill Filler (bfiller)]

Related bug: https://bugs.launchpad.net/touch-preview-images/+bug/1124265

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Ted Gould (ted)]

Introduction
============

To try and figure out what is happening on the application startup in upstart-app-launch I added LTTng tracepoint support and measured the startup in several cases. Spanning both legacy and click apps along with a secondary activation. The times are slower than desired and can be improved.

All tests were done on a Galaxy Nexus with Upstart App Launch trunk.

Browser Start
=============

The web browser is a legacy app, so we can look at that use-case. But it also has good support for secondary activation with multiple URLs, so we can do that as well. This test involved dispatching the http://ubuntu.com URL and the http://canonical.com URL.

In the first instance case we see the time from Upstart signaling the starting of the job until the first tracepoint of the legacy single instance detection script taking about 550ms. This time is primarily click being used to detect with this is a click application. After deciding it isn't desktop-single is used to read the desktop file to see if we're managing the single instance nature of the app (we are). Determining that takes about 1.2ms. Then we switch to using the application-legacy job to manage the new instance.

It takes roughly 90ms to get from the application job to the first tracepoint in the pre-start script of the application-legacy job. This is where we look for the Surface Flinger process. It then connects to DBus and immediately sends the starting handshake to Unity. It takes roughly 13ms to connect to DBus and send that signal. To find the desktop file parse it and setup the environment takes about 43ms. We then wait for Unity to return the handshake and go to exec. Switching from pre-start to the main exec utility seems to add an additional 43ms.

Overall from the start signal to exec'ing the process takes roughly 750ms.

Browser Secondary
=================

The secondary activation goes through the same first steps as the browser, but after determining that we should be managing the single instance nature of the app, it checks to see if it is running. It seems that this check takes 41ms.

It then takes us 10ms to setup DBus and emit the signal for Unity to resume the app. We then figure out the PID of the app we're looking for, costing 13ms. We then go massively parallel on DBus to figure out which connection matches that PID. The analysis of that is complex, but at the end it takes us about 120ms to find the connection and send it the new URL. We then request focus from Unity and wait for about 14ms.

Overall it takes about 732ms to send the DBus message to the webbrowser.

Calculator Start
================

The calculator is a click application, so it goes through the application-click path. We don't have any tracepoint in the initial application job. For click packages it looks for the appid in click to ensure it's a click app and then launches the application-click job. Between the two start signals is 602ms.

When getting to the pre-start script for click packages the first thing we do is initialize DBus and tell Unity the app is coming. This takes 45ms. The next thing we do is ask click for the package directory for the packa...

[Ted Gould (ted)]

Overview
========

I took all of the pending merges for upstart-app-launch and created a mega-merge branch. This is what trunk should look like after all the code reviews are done. And started to get some results on that. It includes most of the optimizations that were suggested in the previous post except the change to libclick, which isn't available yet. Overall the before and after:

First start:: Was: 750ms Mega-merge: 228ms
Second start:: Was: 738ms Mega-merge: 143ms

Analysis
========

While most of the gains were as expected, we also got an additional delay that was known, but not included in the previous tests. In the previous results we didn't have the handshake with Unity to ensure that Unity knows an appid is starting before allowing it to execute. This handshake seems to be adding an additional 58ms to the first start up of an application. I've passed this along to the Unity team so they can investigate further.

Further Work
============

I don't see any other hot spots in upstart-app-launch that can be worked on currently. When we drop surface flinger I expect about a 30ms increase and perhaps the unity callback can be optimized as well to decrease startup time. Not dicussed here is the click path which will be greatly improved with libclick.

NOTE: All results on a Galaxy Nexus, N4 is likely to be much faster.

[Ted Gould (ted)]

My fan base said they want more results, and you know, I'll do anything for the fans. Using the mega-merge branch and starting a click application (sudoku). Comparing results:

Was: 1.8s Mega-merge: 1.236s

The majority of the time is in the two click calls (507ms each) which are slated to be removed with libclick when it becomes available. When that happens it is expected that click application launching will be roughly the same as legacy application launching.

[Colin Watson (cjwatson)]

My measurements differed a little from Ted's, since removing one of those click calls saved about 0.7 seconds; perhaps click itself slowed down in the meantime (easy to do in Python). Anyway, this will help:

  https://code.launchpad.net/~cjwatson/upstart-app-launch/libclick-pkgdir/+merge/209909

[Colin Watson (cjwatson)]

And here's the other half of that work:

  https://code.launchpad.net/~cjwatson/upstart-app-launch/libclick-manifest/+merge/210520

I haven't closed the upstart-app-launch task since I don't know if Ted has anything else on his hit-list, but there probably isn't very much left to find there.

[Ted Gould (ted)]

On Wed, 2014-03-12 at 00:38 +0000, Colin Watson wrote:

> I haven't closed the upstart-app-launch task since I don't know if Ted
> has anything else on his hit-list, but there probably isn't very much
> left to find there.

I think that if there are other things we want to do they should
probably be other bugs. Thanks Colin for the help!

[Colin Watson (cjwatson)]

trusty-proposed image 254 has these changes.

upstart-app-launch (0.3+14.04.20140321-0ubuntu1) trusty; urgency=low

  [ Colin Watson ]
  * Use libclick to get the package directory, saving about 0.7 seconds
    from Click application startup (on mako).
  * Use libclick to get package manifests, saving about 0.7 seconds from
    Click application startup (on mako).

 -- Ubuntu daily release <email address hidden> Fri, 21 Mar 2014 17:56:24 +0000