Merge lp:~mvo/software-center/more-performance-measurement into lp:software-center

[Michael Vogt]

This branch adds some more "probe" points that run "with ExecutionTime()" to get a better idea where the
time is spend on startup. To run:
$ ./software-center --measure-startup-time

It also adds a new limit of "0.1"s by default to avoid reportng time intervals that are mostly irrelevant.
Running this on my box shows that e.g. out of 4.6s startup until the window is fully ready about 1.2s
are spend in the apt cache open, 0.4s are spend parsing the applications menu and 0.6s creating the
LobbyViewGtk. So this branch should help figuring out what needs speedup or could be delayed/loaded in
the background.

[Natalia Bidart (nataliabidart)]

Branch looks good.

This is the output from my box, but is worth noting that this was run using a 'warm' disk cache:

nessita@dali:~/canonical/software-center/review_more-performance-measurement$ PYTHONPATH=. ./software-center --measure-startup-time
2012-06-20 13:33:37,600 - softwarecenter.performance - DEBUG - create review loader: 0.164757013321
2012-06-20 13:33:37,607 - softwarecenter.performance - DEBUG - create SoftwareCenterApp: 0.29595708847
1340210018.0
2012-06-20 13:33:37,996 - softwarecenter.performance - DEBUG - ** main window visible after: 1.1121571064 seconds
2012-06-20 13:33:38,538 - softwarecenter.performance - DEBUG - open the apt cache (in event loop): 0.562124013901
2012-06-20 13:33:38,538 - softwarecenter.performance - DEBUG - AvailablePane.init_view pending events: 0.834131002426
2012-06-20 13:33:38,738 - softwarecenter.performance - DEBUG - cat_parser.parse_applications_menu(): 0.198755025864
2012-06-20 13:33:38,738 - softwarecenter.performance - DEBUG - Appview.__init__ create AppPropertiesHelper: 0.198960065842
2012-06-20 13:33:38,744 - softwarecenter.performance - DEBUG - SoftwarePane.AppView: 0.205328941345
2012-06-20 13:33:38,952 - softwarecenter.performance - DEBUG - SoftwarePane.AppDetailsView: 0.20628619194
2012-06-20 13:33:38,969 - softwarecenter.performance - DEBUG - SoftwarePane.init_view(): 0.430808067322
2012-06-20 13:33:39,334 - softwarecenter.performance - DEBUG - populate model from query: 'Xapian::Query((<alldocuments> AND ATapplication))' (threaded: False): 0.152559041977
2012-06-20 13:33:39,449 - softwarecenter.performance - DEBUG - create LobbyViewGtk: 0.447153091431
2012-06-20 13:33:39,606 - softwarecenter.performance - DEBUG - view_widget.init_view() (<AvailablePane object at 0x3276e60 (softwarecenter+ui+gtk3+panes+availablepane+AvailablePane at 0x311a6a0)>): 1.90255093575
2012-06-20 13:33:39,606 - softwarecenter.performance - DEBUG - show() & gtk events until visible: 1.99886608124
2.72254014015
2012-06-20 13:33:39,606 - softwarecenter.performance - DEBUG - ** main window fully ready after: 2.72254014015 seconds

review: Approve

=== modified file 'softwarecenter/ui/gtk3/app.py'
--- softwarecenter/ui/gtk3/app.py	2012-06-04 11:06:20 +0000
+++ softwarecenter/ui/gtk3/app.py	2012-06-20 15:47:25 +0000
@@ -349,8 +349,7 @@
                                  datadir)
 
         # register view manager and create view panes/widgets
-        with ExecutionTime("ViewManager"):
-            self.view_manager = ViewManager(self.notebook_view, options)
+        self.view_manager = ViewManager(self.notebook_view, options)
 
         with ExecutionTime("building panes"):
             self.global_pane = GlobalPane(self.view_manager, self.datadir,
@@ -416,11 +415,9 @@
             self.useful_cache = UsefulnessCache(True)
             self.setup_database_rebuilding_listener()
 
-        with ExecutionTime("create plugin manager"):
-            # open plugin manager and load plugins
-            self.plugin_manager = PluginManager(self,
-                SOFTWARE_CENTER_PLUGIN_DIRS)
-            self.plugin_manager.load_plugins()
+        # open plugin manager and load plugins
+        self.plugin_manager = PluginManager(self, SOFTWARE_CENTER_PLUGIN_DIRS)
+        self.plugin_manager.load_plugins()
 
         # setup window name and about information (needs branding)
         name = self.distro.get_app_name()
@@ -485,7 +482,6 @@
 
         # keep track of the current active pane
         self.active_pane = self.available_pane
-        self.window_main.connect("realize", self.on_realize)
 
         # launchpad integration help, its ok if that fails
         try:
@@ -552,9 +548,6 @@
             pass
 
     # callbacks
-    def on_realize(self, widget):
-        pass
-
     def on_available_pane_created(self, widget):
         self.available_pane.searchentry.grab_focus()
         self._update_recommendations_menuitem(
 
=== modified file 'softwarecenter/ui/gtk3/models/appstore2.py'
--- softwarecenter/ui/gtk3/models/appstore2.py	2012-06-11 10:00:20 +0000
+++ softwarecenter/ui/gtk3/models/appstore2.py	2012-06-20 15:47:25 +0000
@@ -98,15 +98,16 @@
         }
 
     def __init__(self, db, cache, icons, icon_size=48,
-        global_icon_cache=False):
+                 global_icon_cache=False):
         GObject.GObject.__init__(self)
         self.db = db
         self.cache = cache
 
         # get all categories
         cat_parser = CategoriesParser(db)
-        self.all_categories = cat_parser.parse_applications_menu(
-            softwarecenter.paths.APP_INSTALL_PATH)
+        with ExecutionTime("cat_parser.parse_applications_menu()"):
+            self.all_categories = cat_parser.parse_applications_menu(
+                softwarecenter.paths.APP_INSTALL_PATH)
 
         # reviews stats loader
         self.review_loader = get_review_loader(cache, db)
 
=== modified file 'softwarecenter/ui/gtk3/panes/availablepane.py'
--- softwarecenter/ui/gtk3/panes/availablepane.py	2012-06-18 21:57:36 +0000
+++ softwarecenter/ui/gtk3/panes/availablepane.py	2012-06-20 15:47:25 +0000
@@ -51,6 +51,8 @@
 from softwarepane import SoftwarePane
 from softwarecenter.ui.gtk3.session.viewmanager import get_viewmanager
 from softwarecenter.ui.gtk3.session.appmanager import get_appmanager
+from softwarecenter.utils import ExecutionTime
+
 from softwarecenter.backend.channel import SoftwareChannel
 from softwarecenter.backend.unitylauncher import (UnityLauncher,
                                                   UnityLauncherInfo,
@@ -132,12 +134,15 @@
         if window is not None:
             window.set_cursor(self.busy_cursor)
 
-        while Gtk.events_pending():
-            Gtk.main_iteration()
+        with ExecutionTime("AvailablePane.init_view pending events"):
+            while Gtk.events_pending():
+                Gtk.main_iteration()
 
-        SoftwarePane.init_view(self)
+        with ExecutionTime("SoftwarePane.init_view()"):
+            SoftwarePane.init_view(self)
         # set the AppTreeView model, available pane uses list models
-        liststore = AppListStore(self.db, self.cache, self.icons)
+        with ExecutionTime("create AppListStore"):
+            liststore = AppListStore(self.db, self.cache, self.icons)
         #~ def on_appcount_changed(widget, appcount):
             #~ self.subcategories_view._append_appcount(appcount)
             #~ self.app_view._append_appcount(appcount)
@@ -166,7 +171,8 @@
         self.scroll_categories = Gtk.ScrolledWindow()
         self.scroll_categories.set_policy(Gtk.PolicyType.AUTOMATIC,
                                         Gtk.PolicyType.AUTOMATIC)
-        self.cat_view = LobbyViewGtk(self.datadir, APP_INSTALL_PATH,
+        with ExecutionTime("create LobbyViewGtk"):
+            self.cat_view = LobbyViewGtk(self.datadir, APP_INSTALL_PATH,
                                        self.cache,
                                        self.db,
                                        self.icons,
@@ -176,7 +182,8 @@
             Gtk.Label(label="categories"))
 
         # sub-categories view
-        self.subcategories_view = SubCategoryViewGtk(self.datadir,
+        with ExecutionTime("create SubCategoryViewGtk"):
+            self.subcategories_view = SubCategoryViewGtk(self.datadir,
             APP_INSTALL_PATH,
             self.cache,
             self.db,
 
=== modified file 'softwarecenter/ui/gtk3/panes/softwarepane.py'
--- softwarecenter/ui/gtk3/panes/softwarepane.py	2012-06-18 20:26:49 +0000
+++ softwarecenter/ui/gtk3/panes/softwarepane.py	2012-06-20 15:47:25 +0000
@@ -211,8 +211,9 @@
         self.search_aid = SearchAid(self)
         self.box_app_list.pack_start(self.search_aid, False, False, 0)
 
-        self.app_view = AppView(self.db, self.cache,
-                                self.icons, self.show_ratings)
+        with ExecutionTime("SoftwarePane.AppView"):
+            self.app_view = AppView(self.db, self.cache,
+                                    self.icons, self.show_ratings)
         self.app_view.connect("sort-method-changed",
             self.on_app_view_sort_method_changed)
 
@@ -227,11 +228,12 @@
         self.scroll_details = Gtk.ScrolledWindow()
         self.scroll_details.set_policy(Gtk.PolicyType.AUTOMATIC,
                                         Gtk.PolicyType.AUTOMATIC)
-        self.app_details_view = AppDetailsView(self.db,
-                                               self.distro,
-                                               self.icons,
-                                               self.cache,
-                                               self.datadir)
+        with ExecutionTime("SoftwarePane.AppDetailsView"):
+            self.app_details_view = AppDetailsView(self.db,
+                                                   self.distro,
+                                                   self.icons,
+                                                   self.cache,
+                                                   self.datadir)
         self.app_details_view.connect(
             "different-application-selected", self.on_application_activated)
         self.scroll_details.add(self.app_details_view)
 
=== modified file 'softwarecenter/ui/gtk3/session/viewmanager.py'
--- softwarecenter/ui/gtk3/session/viewmanager.py	2012-06-18 20:26:49 +0000
+++ softwarecenter/ui/gtk3/session/viewmanager.py	2012-06-20 15:47:25 +0000
@@ -21,7 +21,7 @@
 from navhistory import NavigationHistory, NavigationItem
 from softwarecenter.ui.gtk3.widgets.backforward import BackForwardButton
 from softwarecenter.ui.gtk3.widgets.searchentry import SearchEntry
-
+from softwarecenter.utils import ExecutionTime
 
 _viewmanager = None  # the global Viewmanager instance
 
@@ -147,7 +147,8 @@
 
         self.notebook_view.set_current_page(page_id)
         if view_widget:
-            view_widget.init_view()
+            with ExecutionTime("view_widget.init_view() (%s)" % view_widget):
+                view_widget.init_view()
         return view_widget
 
     def get_active_view(self):
 
=== modified file 'softwarecenter/ui/gtk3/views/appview.py'
--- softwarecenter/ui/gtk3/views/appview.py	2012-05-30 18:39:55 +0000
+++ softwarecenter/ui/gtk3/views/appview.py	2012-06-20 15:47:25 +0000
@@ -27,6 +27,7 @@
 from softwarecenter.ui.gtk3.models.appstore2 import AppTreeStore
 from softwarecenter.ui.gtk3.widgets.apptreeview import AppTreeView
 from softwarecenter.ui.gtk3.models.appstore2 import AppPropertiesHelper
+from softwarecenter.utils import ExecutionTime
 
 LOG = logging.getLogger(__name__)
 
@@ -65,7 +66,8 @@
         Gtk.VBox.__init__(self)
         #~ self.set_name("app-view")
         # app properties helper
-        self.helper = AppPropertiesHelper(db, cache, icons)
+        with ExecutionTime("Appview.__init__ create AppPropertiesHelper"):
+            self.helper = AppPropertiesHelper(db, cache, icons)
         # misc internal containers
         self.header_hbox = Gtk.HBox()
         self.header_hbox.set_border_width(StockEms.MEDIUM)
 
=== modified file 'softwarecenter/utils.py'
--- softwarecenter/utils.py	2012-06-12 15:36:01 +0000
+++ softwarecenter/utils.py	2012-06-20 15:47:25 +0000
@@ -63,16 +63,21 @@
     with ExecutinTime("db flush"):
         db.flush()
     """
-    def __init__(self, info="", with_traceback=False):
+    def __init__(self, info="", with_traceback=False,
+                 suppress_less_than_n_seconds=0.1):
         self.info = info
         self.with_traceback = with_traceback
+        self.suppress_less_than_n_seconds = suppress_less_than_n_seconds
 
     def __enter__(self):
         self.now = time.time()
 
     def __exit__(self, type, value, stack):
+        time_spend = time.time() - self.now
+        if time_spend < self.suppress_less_than_n_seconds:
+            return
         logger = logging.getLogger("softwarecenter.performance")
-        logger.debug("%s: %s" % (self.info, time.time() - self.now))
+        logger.debug("%s: %s" % (self.info, time_spend))
         if self.with_traceback:
             log_traceback("populate model from query: '%s' (threaded: %s)")