software-center terribly slow, ubuntu freezing

[Michael Krištof]

When I launch software-center it takes really long, pc is unusable, when I try to do something in the meanwhile it even freezes.

ProblemType: Bug
DistroRelease: Ubuntu 11.10
Package: software-center 4.1.21
ProcVersionSignature: Ubuntu 3.0.0-10.16-generic 3.0.4
Uname: Linux 3.0.0-10-generic x86_64
ApportVersion: 1.22.1-0ubuntu2
Architecture: amd64
Date: Fri Sep 9 14:49:57 2011
PackageArchitecture: all
ProcEnviron:
 LANGUAGE=en_US:en
 PATH=(custom, no user)
 LANG=en_US.UTF-8
 SHELL=/bin/bash
SourcePackage: software-center
UpgradeStatus: Upgraded to oneiric on 2011-09-07 (1 days ago)

[Esmaeil MIRZAEE (esmaeilmirzaee)]

I think the same issue happened in the Bug #556375. and according to the that bug this bug must be modified before.

[philinux (philcb)]

From a cold boot SC takes 15 seconds to be usable. Also installing software takes much longer than synaptic.

64 bit. AMD athlon 64 x2 dual core 5200+
2 gig ram.

[Jussier (jussierneto)]

Here I use if a i5 2410M, 4 GB of Ram 64bit and takes 12 seconds to fully load and go.

[xiangxw (963632192-m)]

Yes, it's really slow.

[philinux (philcb)]

Any movement on this.

Is there a reason that it takes so long to be usable?

[studentz (studenz)]

Same here
any clue?

[Manveru (manveru)]

Take a Geany for example - clicking on any additional package freezes Ubuntu Software Center for 30~60 seconds... additionally at that time compiz and Xorg consumes suspiciously lot of processor time.

[Nogero (oregonbob)]

Yes, Ubuntu Software center is horribly slow, inconsistent, hangs, poorly designed and confusing. The "add-on" section is weird too. If you click "Aply changes" in the addon section it just goes ahead and starts installing the software without confirmation. Who designed/wrote this stuff and how did it get into a once great product like Ubuntu?

[Matthew Paul Thomas (mpt)]

Nogero, that is obviously a different bug. Please report it separately.

[Timothy Arceri (t-fridey)]

Running software-center with --measure-startup-time I get the following:

software-center --measure-startup-time
2012-09-08 18:10:08,170 - softwarecenter.performance - DEBUG - opening the pkginfo: 0.0926611423492
2012-09-08 18:10:08,315 - softwarecenter.performance - DEBUG - opening the xapiandb: 0.144290924072
2012-09-08 18:10:08,326 - softwarecenter.performance - DEBUG - building the icon cache: 0.0107450485229
2012-09-08 18:10:08,474 - softwarecenter.performance - DEBUG - creating the backend: 0.146363019943
2012-09-08 18:10:08,475 - softwarecenter.performance - DEBUG - get the app-manager: 0.000198125839233
2012-09-08 18:10:08,566 - softwarecenter.performance - DEBUG - ViewManager: 0.0550661087036
2012-09-08 18:10:09,024 - softwarecenter.performance - DEBUG - building panes: 0.456971883774
2012-09-08 18:10:10,201 - softwarecenter.performance - DEBUG - create review loader: 1.17366814613
2012-09-08 18:10:10,208 - softwarecenter.performance - DEBUG - create plugin manager: 0.00152015686035
2012-09-08 18:10:10,372 - softwarecenter.performance - DEBUG - create SoftwareCenterApp: 2.48159313202
1347091811.46
2012-09-08 18:10:11,464 - softwarecenter.performance - DEBUG - ** main window visible after: 8.91763997078 seconds
2012-09-08 18:10:14,439 - softwarecenter.performance - DEBUG - open the apt cache (in event loop): 2.97348093987
2012-09-08 18:10:20,205 - softwarecenter.performance - DEBUG - calculate nr_apps and nr_pkgs: : 0.460212945938
2012-09-08 18:10:20,395 - softwarecenter.performance - DEBUG - append new matches to existing ones:: 0.0014967918396
2012-09-08 18:10:20,396 - softwarecenter.performance - DEBUG - populate model from query: 'Xapian::Query((<alldocuments> AND ATapplication))' (threaded: False): 0.662683010101
2012-09-08 18:10:21,344 - softwarecenter.performance - DEBUG - calculate nr_apps and nr_pkgs: : 0.352252006531
2012-09-08 18:10:22,130 - softwarecenter.performance - DEBUG - append new matches to existing ones:: 0.00371217727661
2012-09-08 18:10:22,130 - softwarecenter.performance - DEBUG - populate model from query: 'Xapian::Query((<alldocuments> AND ATapplication))' (threaded: False): 1.13835787773
2012-09-08 18:10:23,334 - softwarecenter.performance - DEBUG - estimate item count for query: 'Xapian::Query(<alldocuments>)': 0.140356779099
2012-09-08 18:10:24,610 - softwarecenter.performance - DEBUG - show() & gtk events until visible: 14.2379748821
22.0645909309
2012-09-08 18:10:24,611 - softwarecenter.performance - DEBUG - ** main window fully ready after: 22.0645909309 seconds

I'm trying to figure out how I can narrow the cause down further but I'm not a python coder so Matthew any hints on where this looks to be coming from would be great.

[Timothy Arceri (t-fridey)]

It seems with the latest speedup2 code changes in 5.3.14.2 Software Center gets to main window visible faster but is slower elsewhere. Here the output from my machine.

timothy@timothy-1005P:~$ software-center --measure-startup-time
2012-10-03 21:31:15,025 - softwarecenter.performance - DEBUG - import InstalledPane: 0.22905087471
2012-10-03 21:31:15,186 - softwarecenter.performance - DEBUG - import AvailablePane: 0.160007953644
2012-10-03 21:31:15,219 - softwarecenter.performance - DEBUG - import SoftwareCenterApp: 0.760882139206

(software-center:2727): Gtk-WARNING **: Theme parsing error: softwarecenter.css:34:20: Not using units is deprecated. Assuming 'px'.

(software-center:2727): Gtk-WARNING **: Theme parsing error: softwarecenter.css:34:22: Not using units is deprecated. Assuming 'px'.

(software-center:2727): Gtk-WARNING **: Theme parsing error: softwarecenter.css:56:20: Not using units is deprecated. Assuming 'px'.

(software-center:2727): Gtk-WARNING **: Theme parsing error: softwarecenter.css:56:22: Not using units is deprecated. Assuming 'px'.

(software-center:2727): Gtk-WARNING **: Theme parsing error: softwarecenter.css:60:20: Not using units is deprecated. Assuming 'px'.

(software-center:2727): Gtk-WARNING **: Theme parsing error: softwarecenter.css:60:22: Not using units is deprecated. Assuming 'px'.
2012-10-03 21:31:15,770 - softwarecenter.performance - DEBUG - building panes: 0.269058942795
2012-10-03 21:31:16,785 - softwarecenter.performance - DEBUG - create review loader: 1.01208305359
2012-10-03 21:31:16,838 - softwarecenter.performance - DEBUG - create SoftwareCenterApp: 1.61830401421
1349263877.67
2012-10-03 21:31:17,679 - softwarecenter.performance - DEBUG - ** main window visible after: 4.12693214417 seconds
2012-10-03 21:31:24,870 - softwarecenter.performance - DEBUG - open the apt cache (in event loop): 7.18893790245
2012-10-03 21:31:24,872 - softwarecenter.performance - DEBUG - AvailablePane.init_view pending events: 7.35508584976
2012-10-03 21:31:26,612 - softwarecenter.performance - DEBUG - cat_parser.parse_applications_menu(): 1.73268795013
2012-10-03 21:31:26,613 - softwarecenter.performance - DEBUG - Appview.__init__ create AppPropertiesHelper: 1.73359298706
2012-10-03 21:31:26,667 - softwarecenter.performance - DEBUG - SoftwarePane.AppView: 1.78860497475
2012-10-03 21:31:26,908 - softwarecenter.performance - DEBUG - import AppDetailsView: 0.226464033127
2012-10-03 21:31:27,606 - softwarecenter.performance - DEBUG - SoftwarePane.AppDetailsView: 0.6971180439
2012-10-03 21:31:27,742 - softwarecenter.performance - DEBUG - SoftwarePane.init_view(): 2.86804413795
2012-10-03 21:31:28,916 - softwarecenter.performance - DEBUG - calculate nr_apps and nr_pkgs: : 0.858962059021
2012-10-03 21:31:28,936 - softwarecenter.performance - DEBUG - populate model from query: 'Xapian::Query((<alldocuments> AND ATapplication))' (threaded: False): 0.880316019058
2012-10-03 21:31:29,750 - softwarecenter.performance - DEBUG - calculate nr_apps and nr_pkgs: : 0.418337106705
2012-10-03 21:31:30,531 - softwarecenter.performance - DEBUG - populate model from query: 'Xapian::Query((<alldocuments> AND ATapplication))' (threaded: False): 1...

[Nicholas Shatokhin (robotex)]

Python is not good choice for desktop systems. It's too slow for it.

[Timothy Arceri (t-fridey)]

I still have to verify this with actual benchmarking but one place that looks like it will benefit from optimising is here:

softwarecenter.performance - DEBUG - cat_parser.parse_applications_menu(): 1.73268795013

The code called is in /softwarecenter/db/categories.py and from a quick scan over the code its possible that the _parse_menu_tag method (and the various other parsing methods it calls) are causing performance issues. There is quite a lot of if else statements inside loops to read the xml elements and also some recursive calls inside those loops.

As lmxl is being used to read the xml file and it is actually a C library wrapper my assumption is it would be better to use xpath calls to read/checkfor the xml elements rather than looping through the xml elements.

Anyway I might not get to check this for a while so posting this for anyone else that is interested, it should be a fairly easy programming task if this is in fact what it taking a long time to execute.

[Timothy Arceri (t-fridey)]

Ran a quick performance test here is the result:

2012-10-04 22:23:11,027 - softwarecenter.performance - DEBUG - _parse_menu_tag: 1.55758905411
2012-10-04 22:23:11,324 - softwarecenter.performance - DEBUG - cat_parser.parse_applications_menu(): 1.86049294472

So there is definitely over a second that could be shaved off here.

[Timothy Arceri (t-fridey)]

Ok, turns out the xml parsing isn't to bad after all. I tracked this one all the way back to:

# get cataloged_times
cataloged_times = {}
CF = "/var/lib/apt-xapian-index/cataloged_times.p"
if os.path.exists(CF):
    try:
        cataloged_times = pickle.load(open(CF))
    except Exception as e:
        LOG.warn("failed to load file %s: %s", CF, e)

Taking 1.4 seconds on my machine. Not sure what can be done to improve times here probably nothing short of pickle optimisations.

Guess I should move on to tracking down the cause of the remaining 19 or so seconds it takes my machine to boot. Unless anyone has any more ideas for this one?

[Timothy Arceri (t-fridey)]

I just couldn't leave this one alone. The cataloged_times is just a dictionary so there is no real need to use pickle to serialise it. I loaded the file into python and created a serialise file using msgpack instead.
This reduced the file size from 3.1MB to 1.7MB. I then changed software center to load this file instead of the pickle one bingo! this reduced the load time by 1.1 seconds to just 0.1 of a second.

Only thing is the change would also need to be made to the upstream apt-xapian-index code that actually creates/updates this file, I'm unsure at this point where this code is located.

[Timothy Arceri (t-fridey)]

I've filled my suggested improvement in the debian bug system for apt-xapian-index I guess its now up to upstream to agree.

 http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=689717

[Timothy Arceri (t-fridey)]

ok, so it seems another big bottleneck in startup is Xapian calls.

Specifically calls to get_mset() these calls take over 4 seconds in total on my machine.

Most of these calls are made from _blocking_perform_search() in softwarecenter/db/enquire.py

Again aside from upstream optimizations to Xapian there doesn't appear to be any easy way around this. The maxitems parameter can be set to 0 to speedup get_mset() but this reduces the accuracy of the mset.get_matches_estimated() call which it seems the software center relies on being accurate so I dont think this change can be made.

So with the pickle load time and Xapian calls that I have tracked so far that adds up to around 25% of the startup time.

[Timothy Arceri (t-fridey)]

Sorry my last post was a bit vague as to the triggers for the bottlenecks.

To follow up my last entry:
the get_mset() calls are actually made in _get_estimate_nr_apps_and_nr_pkgs which is called from _blocking_perform_search()

These are Triggered by _build_homepage_view in softwarecenter/ui/gtk3/views/lobbyview.py

The _update_top_rated_content() and _update_whats_new_content() calls are the triggers of the slow get_mset() calls.

[dino99 (9d9)]

oneiric have reached EOL now ; closing that report. Feel free to report against a newer version if needed, with ubuntu-bug