Certification System 201101-7174 boots 7.93 seconds slower

[Brian Murray]

During QA review of bootchart data provided by the Hardware Certification team
it was determined that certification system 201101-7174 boots 7.93 seconds slower with
a Natty image from 20110302 than with a Maverick image from 20101007.

System url:
 https://certification.canonical.com/hardware/201101-7174
Maverick Results:
 http://people.canonical.com/~hwcert/boot-metrics/maverick/20101007/201101-7174
Natty Results:
 http://people.canonical.com/~hwcert/boot-metrics/natty/20110302/201101-7174

[Robbie Williamson (robbiew)]

So looking at both charts, Natty is booting **faster** up to the portion that X begins (at 16sec), then we slow down with Unity. The Maverick chart has Xorg starting at 18sec, but we didn't have Unity enabled by default...so total time is faster.

[Robbie Williamson (robbiew)]

What does the Natty chart look like if it's booted into the Classic Desktop, without Unity?

[Brendan Donegan (brendan-donegan)]

I notice the bug status has been changed to 'Incomplete'. Is it the boot metrics from Classic Desktop that are being looked for, or something else?

[Brian Murray (brian-murray)]

The boot metrics from a Classic Desktop for this system should be enough information to move this bug out of the incomplete state.

[Sebastien Bacher (seb128)]

the natty chart shows that zg which is loaded by the unity-places is doing lot of io for over 9 seconds

[Mikkel Kamstrup Erlandsen (kamstrup)]

I'm very surprised that Zeitgeist would take 9s of churning under normal circumstances. This may happen if there is a big ~/.local/share/recently-used.xbel that needs indexing - or if the full text index is not up-to-date and needs regeneration. How ever both these conditions should be out-of-the-ordinary conditions.

Any chance you can grab the logs from Zeitgeist? You can probably find it in ~/.cache/zeitgeist/daemon.log

BEWARE: The Zeitgeist log may contain private info - if anyone attaches it here it may be worth quickly skimming!

[Mikkel Kamstrup Erlandsen (kamstrup)]

One thing maybe worth adding - the daemons - and the Unity places in general - are designed to be activated lazily by Unity.

The .place files in /usr/share/unity/places contain all metadata necessary for Unity to put some icons on the screen. There is absolutely no need to start the unity place daemons on startup. So it may be worth pursuing that Unity and Unity-2d doesn't launch the daemons until after the desktop is "ready"?

[Victor Tuson Palau (vtuson)]

if natty is to include Unity by default, does it matter how quick it boots to Classic desktop?

[Robbie Williamson (robbiew)]

@Victor: it only matters to whether or not we have a real "regression" from 10.10, but overall...not really...the default is slower and needs to be fixed.

[Mikkel Kamstrup Erlandsen (kamstrup)]

I need to know what the home dir of that image looks like? If there's a ~/.local/share/recently-used.xbel it means Zeitgeist will index it once it's started. This can be an expensive op, but is also a one-off. Otoh if there are no recent docs logged in the recently-used.xbel then it means Zeitgeist has nothing whatsoever to do at startup, and it should be close to a freebie - which would make the reported behaviour highly mysterious.

[Mikkel Kamstrup Erlandsen (kamstrup)]

(marking incomplete until we have the requested feedback)

[Brian Murray (brian-murray)]

This is on a fresh installation of Ubuntu. Would there be anything in recently-used.xbel for a fresh installation?

[Brian Murray (brian-murray)]

I happened to have a fresh install of Natty in a virtual machine which I've done nothing with and there is no .local/share/recently-used.xbel in my home directory so I'd think there wouldn't be one these certification systems.

[Mikkel Kamstrup Erlandsen (kamstrup)]

Ok Brian... That definitely deepens the mystery.

Without any recent files to log Zeitgeist will, on a first run, parse a few .pyc files (it is a Python program after all! ;-)) and then create a few empty tables in a sqlite db. Nothing that would remotely require 9s of IO time.

If we believe that ZG is the culprit (which I agree it looks like) we need to dig in and figure out why it's so sluggish. Here's something that should work:

 1) Fresh Natty install
 2) Log in to a *classic* session. This should mean that Zeitgeist is not started via DBus activation
 3) Start Gnome Terminal
 4) (optional) set up a range of io-monitoring tools
 5) Run zeitgeist-daemon from the terminal and attach the full stdout to this bug
 6) Maybe also attach ~/.cache/zeitgeist/daemon.log if it's != from the stdout spew

[Brian Murray (brian-murray)]

Logging into a classic session seems to have started zeitgeist as I saw the following running - zeitgeist-datahub and zeitgeist-daemon. I'm attaching .cache/zeitgeist/daemon.log from the relevant system.

[Brian Murray (brian-murray)]

The zeitgeist daemon log file.

[Mikkel Kamstrup Erlandsen (kamstrup)]

Thanks a bunch Brian. Still, it appears that ZG takes a lot less than 9s to start up on your system, more like 1.2s (which is still surprisingly much considering we have almost nothing to do on startup).

If we pull out the points in the log that does seem to take a noticeable amount of time it'll be:

[2011-03-22 09:33:46,387] - DEBUG - zeitgeist.sql - Updating sql schema
[2011-03-22 09:33:46,898] - INFO - zeitgeist.sql - DB set up in 514.949083328ms
--- ~500ms (as it also says in the log)

This is creating a sqlite db file and setting up a (fairly complex) set of empty sqlite tables. I am pretty sure we'll see shorter setup times on subsequent runs. For reference my system does this step in ~7ms when the DB is already set up.

[2011-03-22 09:33:46,899] - DEBUG - zeitgeist.extension - Searching for user extensions in: /home/ubuntu/.local/share/zeitgeist/extensions
[2011-03-22 09:33:47,215] - DEBUG - zeitgeist.extension - No extra extensions
--- ~300ms

This is a bit surprising - as there will be no user defined extensions installed, this should basically amount to the time it takes to "traverse" an empty directory. Is this running a live session or something where FS access may be expensive for uncached blocks?

[2011-03-22 09:33:47,217] - DEBUG - zeitgeist.fts - Opening full text index: /home/ubuntu/.local/share/zeitgeist/fts.index
[2011-03-22 09:33:47,362] - INFO - zeitgeist.fts - Empty index detected. Doing full rebuild
--- ~150ms

This is the time it takes to create an empty Xapian index. A bit much, granted, but this ought to be close to free on subsequent runs where the index structure is already on disk. For reference I have 40ms on my system for this step (with about 10k items in the index).

[Mikkel Kamstrup Erlandsen (kamstrup)]

Hmmm - hold on. I think I may be going out on a limb here...

Is there any way we can see more specifically what ZG is doing for those 9s? The legend on the figure says "Uninterruptible sleep" which for all we know can just as well be hanging around waiting for access to the disk, without really doing much..?

Meaning that the culprit could be something else than ZG hogging the disk, and ZG IO time is just the symptom?

[Mikkel Kamstrup Erlandsen (kamstrup)]

I am looking at this article on Phoronix http://www.phoronix.com/scan.php?page=article&item=ubuntu_natty_boot&num=1 and it seems that none of the tested systems there indicate ZG as a culprit for slower startup.

The fact that ZG is even started on login is bug #772265, which will likely be fixed for Oneiric. I must also note that it seems like the Phoronix bootcharts doesn't use the lazy place loading that landed just before beta2 - this should remove the IO and CPU time hogged by unity-applications-daemon... /me puzzled

[Sebastien Bacher (seb128)]

is that still an issue in precise?

[Evan Peck (colors)]

Anything going on here? Is this still a problem in Quantal? And Mikkel, what were you able to figure out / fix?

Thank you!

[Marco Trevisan (Treviño) (3v1n0)]

I think this bug is now obsolete and we can safely close it. In case we have other issues, please open a new bug.