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

Proposed by Michael Vogt on 2012-06-20
Status: Merged
Merged at revision: 3043
Proposed branch: lp:~mvo/software-center/more-performance-measurement
Merge into: lp:software-center
Diff against target: 229 lines (+43/-32)
7 files modified
softwarecenter/ui/gtk3/app.py (+4/-11)
softwarecenter/ui/gtk3/models/appstore2.py (+4/-3)
softwarecenter/ui/gtk3/panes/availablepane.py (+13/-6)
softwarecenter/ui/gtk3/panes/softwarepane.py (+9/-7)
softwarecenter/ui/gtk3/session/viewmanager.py (+3/-2)
softwarecenter/ui/gtk3/views/appview.py (+3/-1)
softwarecenter/utils.py (+7/-2)
To merge this branch: bzr merge lp:~mvo/software-center/more-performance-measurement
Reviewer Review Type Date Requested Status
Natalia Bidart 2012-06-20 Approve on 2012-06-20
Review via email: mp+111249@code.launchpad.net

Description of the change

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.

To post a comment you must log in.
Natalia Bidart (nataliabidart) wrote :

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

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'softwarecenter/ui/gtk3/app.py'
2--- softwarecenter/ui/gtk3/app.py 2012-06-04 11:06:20 +0000
3+++ softwarecenter/ui/gtk3/app.py 2012-06-20 15:47:25 +0000
4@@ -349,8 +349,7 @@
5 datadir)
6
7 # register view manager and create view panes/widgets
8- with ExecutionTime("ViewManager"):
9- self.view_manager = ViewManager(self.notebook_view, options)
10+ self.view_manager = ViewManager(self.notebook_view, options)
11
12 with ExecutionTime("building panes"):
13 self.global_pane = GlobalPane(self.view_manager, self.datadir,
14@@ -416,11 +415,9 @@
15 self.useful_cache = UsefulnessCache(True)
16 self.setup_database_rebuilding_listener()
17
18- with ExecutionTime("create plugin manager"):
19- # open plugin manager and load plugins
20- self.plugin_manager = PluginManager(self,
21- SOFTWARE_CENTER_PLUGIN_DIRS)
22- self.plugin_manager.load_plugins()
23+ # open plugin manager and load plugins
24+ self.plugin_manager = PluginManager(self, SOFTWARE_CENTER_PLUGIN_DIRS)
25+ self.plugin_manager.load_plugins()
26
27 # setup window name and about information (needs branding)
28 name = self.distro.get_app_name()
29@@ -485,7 +482,6 @@
30
31 # keep track of the current active pane
32 self.active_pane = self.available_pane
33- self.window_main.connect("realize", self.on_realize)
34
35 # launchpad integration help, its ok if that fails
36 try:
37@@ -552,9 +548,6 @@
38 pass
39
40 # callbacks
41- def on_realize(self, widget):
42- pass
43-
44 def on_available_pane_created(self, widget):
45 self.available_pane.searchentry.grab_focus()
46 self._update_recommendations_menuitem(
47
48=== modified file 'softwarecenter/ui/gtk3/models/appstore2.py'
49--- softwarecenter/ui/gtk3/models/appstore2.py 2012-06-11 10:00:20 +0000
50+++ softwarecenter/ui/gtk3/models/appstore2.py 2012-06-20 15:47:25 +0000
51@@ -98,15 +98,16 @@
52 }
53
54 def __init__(self, db, cache, icons, icon_size=48,
55- global_icon_cache=False):
56+ global_icon_cache=False):
57 GObject.GObject.__init__(self)
58 self.db = db
59 self.cache = cache
60
61 # get all categories
62 cat_parser = CategoriesParser(db)
63- self.all_categories = cat_parser.parse_applications_menu(
64- softwarecenter.paths.APP_INSTALL_PATH)
65+ with ExecutionTime("cat_parser.parse_applications_menu()"):
66+ self.all_categories = cat_parser.parse_applications_menu(
67+ softwarecenter.paths.APP_INSTALL_PATH)
68
69 # reviews stats loader
70 self.review_loader = get_review_loader(cache, db)
71
72=== modified file 'softwarecenter/ui/gtk3/panes/availablepane.py'
73--- softwarecenter/ui/gtk3/panes/availablepane.py 2012-06-18 21:57:36 +0000
74+++ softwarecenter/ui/gtk3/panes/availablepane.py 2012-06-20 15:47:25 +0000
75@@ -51,6 +51,8 @@
76 from softwarepane import SoftwarePane
77 from softwarecenter.ui.gtk3.session.viewmanager import get_viewmanager
78 from softwarecenter.ui.gtk3.session.appmanager import get_appmanager
79+from softwarecenter.utils import ExecutionTime
80+
81 from softwarecenter.backend.channel import SoftwareChannel
82 from softwarecenter.backend.unitylauncher import (UnityLauncher,
83 UnityLauncherInfo,
84@@ -132,12 +134,15 @@
85 if window is not None:
86 window.set_cursor(self.busy_cursor)
87
88- while Gtk.events_pending():
89- Gtk.main_iteration()
90+ with ExecutionTime("AvailablePane.init_view pending events"):
91+ while Gtk.events_pending():
92+ Gtk.main_iteration()
93
94- SoftwarePane.init_view(self)
95+ with ExecutionTime("SoftwarePane.init_view()"):
96+ SoftwarePane.init_view(self)
97 # set the AppTreeView model, available pane uses list models
98- liststore = AppListStore(self.db, self.cache, self.icons)
99+ with ExecutionTime("create AppListStore"):
100+ liststore = AppListStore(self.db, self.cache, self.icons)
101 #~ def on_appcount_changed(widget, appcount):
102 #~ self.subcategories_view._append_appcount(appcount)
103 #~ self.app_view._append_appcount(appcount)
104@@ -166,7 +171,8 @@
105 self.scroll_categories = Gtk.ScrolledWindow()
106 self.scroll_categories.set_policy(Gtk.PolicyType.AUTOMATIC,
107 Gtk.PolicyType.AUTOMATIC)
108- self.cat_view = LobbyViewGtk(self.datadir, APP_INSTALL_PATH,
109+ with ExecutionTime("create LobbyViewGtk"):
110+ self.cat_view = LobbyViewGtk(self.datadir, APP_INSTALL_PATH,
111 self.cache,
112 self.db,
113 self.icons,
114@@ -176,7 +182,8 @@
115 Gtk.Label(label="categories"))
116
117 # sub-categories view
118- self.subcategories_view = SubCategoryViewGtk(self.datadir,
119+ with ExecutionTime("create SubCategoryViewGtk"):
120+ self.subcategories_view = SubCategoryViewGtk(self.datadir,
121 APP_INSTALL_PATH,
122 self.cache,
123 self.db,
124
125=== modified file 'softwarecenter/ui/gtk3/panes/softwarepane.py'
126--- softwarecenter/ui/gtk3/panes/softwarepane.py 2012-06-18 20:26:49 +0000
127+++ softwarecenter/ui/gtk3/panes/softwarepane.py 2012-06-20 15:47:25 +0000
128@@ -211,8 +211,9 @@
129 self.search_aid = SearchAid(self)
130 self.box_app_list.pack_start(self.search_aid, False, False, 0)
131
132- self.app_view = AppView(self.db, self.cache,
133- self.icons, self.show_ratings)
134+ with ExecutionTime("SoftwarePane.AppView"):
135+ self.app_view = AppView(self.db, self.cache,
136+ self.icons, self.show_ratings)
137 self.app_view.connect("sort-method-changed",
138 self.on_app_view_sort_method_changed)
139
140@@ -227,11 +228,12 @@
141 self.scroll_details = Gtk.ScrolledWindow()
142 self.scroll_details.set_policy(Gtk.PolicyType.AUTOMATIC,
143 Gtk.PolicyType.AUTOMATIC)
144- self.app_details_view = AppDetailsView(self.db,
145- self.distro,
146- self.icons,
147- self.cache,
148- self.datadir)
149+ with ExecutionTime("SoftwarePane.AppDetailsView"):
150+ self.app_details_view = AppDetailsView(self.db,
151+ self.distro,
152+ self.icons,
153+ self.cache,
154+ self.datadir)
155 self.app_details_view.connect(
156 "different-application-selected", self.on_application_activated)
157 self.scroll_details.add(self.app_details_view)
158
159=== modified file 'softwarecenter/ui/gtk3/session/viewmanager.py'
160--- softwarecenter/ui/gtk3/session/viewmanager.py 2012-06-18 20:26:49 +0000
161+++ softwarecenter/ui/gtk3/session/viewmanager.py 2012-06-20 15:47:25 +0000
162@@ -21,7 +21,7 @@
163 from navhistory import NavigationHistory, NavigationItem
164 from softwarecenter.ui.gtk3.widgets.backforward import BackForwardButton
165 from softwarecenter.ui.gtk3.widgets.searchentry import SearchEntry
166-
167+from softwarecenter.utils import ExecutionTime
168
169 _viewmanager = None # the global Viewmanager instance
170
171@@ -147,7 +147,8 @@
172
173 self.notebook_view.set_current_page(page_id)
174 if view_widget:
175- view_widget.init_view()
176+ with ExecutionTime("view_widget.init_view() (%s)" % view_widget):
177+ view_widget.init_view()
178 return view_widget
179
180 def get_active_view(self):
181
182=== modified file 'softwarecenter/ui/gtk3/views/appview.py'
183--- softwarecenter/ui/gtk3/views/appview.py 2012-05-30 18:39:55 +0000
184+++ softwarecenter/ui/gtk3/views/appview.py 2012-06-20 15:47:25 +0000
185@@ -27,6 +27,7 @@
186 from softwarecenter.ui.gtk3.models.appstore2 import AppTreeStore
187 from softwarecenter.ui.gtk3.widgets.apptreeview import AppTreeView
188 from softwarecenter.ui.gtk3.models.appstore2 import AppPropertiesHelper
189+from softwarecenter.utils import ExecutionTime
190
191 LOG = logging.getLogger(__name__)
192
193@@ -65,7 +66,8 @@
194 Gtk.VBox.__init__(self)
195 #~ self.set_name("app-view")
196 # app properties helper
197- self.helper = AppPropertiesHelper(db, cache, icons)
198+ with ExecutionTime("Appview.__init__ create AppPropertiesHelper"):
199+ self.helper = AppPropertiesHelper(db, cache, icons)
200 # misc internal containers
201 self.header_hbox = Gtk.HBox()
202 self.header_hbox.set_border_width(StockEms.MEDIUM)
203
204=== modified file 'softwarecenter/utils.py'
205--- softwarecenter/utils.py 2012-06-12 15:36:01 +0000
206+++ softwarecenter/utils.py 2012-06-20 15:47:25 +0000
207@@ -63,16 +63,21 @@
208 with ExecutinTime("db flush"):
209 db.flush()
210 """
211- def __init__(self, info="", with_traceback=False):
212+ def __init__(self, info="", with_traceback=False,
213+ suppress_less_than_n_seconds=0.1):
214 self.info = info
215 self.with_traceback = with_traceback
216+ self.suppress_less_than_n_seconds = suppress_less_than_n_seconds
217
218 def __enter__(self):
219 self.now = time.time()
220
221 def __exit__(self, type, value, stack):
222+ time_spend = time.time() - self.now
223+ if time_spend < self.suppress_less_than_n_seconds:
224+ return
225 logger = logging.getLogger("softwarecenter.performance")
226- logger.debug("%s: %s" % (self.info, time.time() - self.now))
227+ logger.debug("%s: %s" % (self.info, time_spend))
228 if self.with_traceback:
229 log_traceback("populate model from query: '%s' (threaded: %s)")
230

Subscribers

People subscribed via source and target branches