Sugar Performance

Time profiling with Python's Hotshot

Python comes by default with three profiling tools: profiler, hotshot and timeit. Profiler and hotshot will detail the execution time of every method called, being profiler deprecated in favour of hotshot. Timeit will just tell you the execution time of a function.

One way of gathering runtime statistics with hotshot is this:

import hotshot

prof = hotshot.Profile("hotshot_sugar")
prof.start()

<...code to profile here...>

prof.stop()
prof.close()

from hotshot import stats

s = stats.load("hotshot_sugar")
s.sort_stats("time").print_stats()

The results that follow in this page were generated by inserting the contents of the installed bin/sugar script (e.g. /home/tomeu/sugar-jhbuild/build/bin/sugar in a jhbuild installation) between prof.start() and prof.stop().

Note that for hotshot to be able to process and print the performance information (recorded in "hotshot_sugar") the methods prof.stop() and prof.close() must be called. This means that we need to exit from the gtk main loop in order to be able to read the profiling information.

As I didn't found any other way for exiting from sugar, had to patch it in the following way:

diff --git a/shell/view/Shell.py b/shell/view/Shell.py
index 1e0ae30..aa17a0a 100644
--- a/shell/view/Shell.py
+++ b/shell/view/Shell.py
@@ -38,6 +38,7 @@ class Shell(gobject.GObject):
                self._key_grabber.grab('F4')
                self._key_grabber.grab('F5')
                self._key_grabber.grab('F6')
+               self._key_grabber.grab('F7')

                self._home_window = HomeWindow(self)
                self._home_window.show()
@@ -64,6 +65,8 @@ class Shell(gobject.GObject):
                        self._frame.toggle_visibility()
                elif key == 'F6':
                        self.start_activity('org.sugar.Terminal')
+               elif key == 'F7':
+                       gtk.main_quit()

        def __window_opened_cb(self, screen, window):
                if window.get_window_type() == wnck.WINDOW_NORMAL:

So pressing F7 will exit sugar and will show the profiling results in the console.

The results obtained from running sugar from the build 85 on qemu were the following:

        17358 function calls (16629 primitive calls) in 28.786 CPU seconds

  Ordered by: internal time

  ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       1   10.741   10.741   20.709   20.709 /usr/share/sugar/shell/Session.py:36(start)
      13    4.173    0.321    5.963    0.459 /usr/lib/python2.4/site-packages/dbus/proxies.py:16(__call__)
       1    2.168    2.168    2.398    2.398 /usr/lib/python2.4/site-packages/gtk-2.0/gtk/__init__.py:23(?)
      16    1.544    0.096    1.546    0.097 /usr/lib/python2.4/site-packages/dbus/proxies.py:44(__call__)
      21    0.881    0.042    0.881    0.042 /usr/lib/python2.4/site-packages/sugar/canvas/IconItem.py:121(_get_buffer)
       1    0.724    0.724    0.736    0.736 /usr/lib/python2.4/site-packages/libxml2.py:1(?)
       1    0.677    0.677    0.700    0.700 /usr/lib/python2.4/site-packages/sugar/session/DbusProcess.py:15(start)
       1    0.375    0.375    4.326    4.326 /usr/share/sugar/shell/Shell.py:1(?)
      10    0.355    0.035    0.387    0.039 /usr/lib/python2.4/site-packages/sugar/canvas/IconItem.py:18(_read_icon)
       1    0.282    0.282    1.019    1.019 /usr/lib/python2.4/site-packages/dbus/introspect_parser.py:1(?)
       1    0.268    0.268    0.424    0.424 /usr/share/sugar/shell/ConsoleWindow.py:53(__init__)
       1    0.262    0.262    0.273    0.273 /usr/lib/python2.4/site-packages/sugar/chat/sketchpad/Sketch.py:1(?)
       1    0.249    0.249    7.313    7.313 /usr/share/sugar/shell/Shell.py:44(__init__)
      12    0.232    0.019    0.571    0.048 /usr/lib/python2.4/site-packages/dbus/introspect_parser.py:5(process_introspection_data)
       1    0.184    0.184    0.184    0.184 /usr/lib/python2.4/site-packages/gtk-2.0/gtk/__init__.py:59(_init)
  133/19    0.184    0.001    0.449    0.024 /usr/lib/python2.4/sre_parse.py:374(_parse)
       8    0.184    0.023    0.941    0.118 /usr/lib/python2.4/site-packages/dbus/_dbus.py:168(add_signal_receiver)
       1    0.183    0.183    0.444    0.444 /usr/lib/python2.4/logging/__init__.py:27(?)
       1    0.173    0.173    0.929    0.929 /usr/lib/python2.4/site-packages/sugar/activity/Activity.py:1(?)
       1    0.153    0.153    0.680    0.680 /usr/share/sugar/shell/Owner.py:1(?)
       1    0.148    0.148    1.180    1.180 /usr/lib/python2.4/site-packages/dbus/_dbus.py:42(?)
      13    0.145    0.011    0.145    0.011 /usr/lib/python2.4/site-packages/dbus/proxies.py:154(_Introspect)
     121    0.135    0.001    0.226    0.002 /usr/lib/python2.4/sre_compile.py:202(_optimize_charset)
       1    0.134    0.134    0.483    0.483 /usr/share/sugar/shell/home/HomeWindow.py:1(?)
       1    0.127    0.127    0.156    0.156 /usr/lib/python2.4/socket.py:43(?)
       1    0.126    0.126    0.138    0.138 /usr/lib/python2.4/mimetools.py:1(?)
       1    0.126    0.126    0.698    0.698 /usr/lib/python2.4/site-packages/sugar/setup.py:3(?)
       1    0.126    0.126    6.865    6.865 /usr/share/sugar/shell/Session.py:1(?)
  289/18    0.124    0.000    0.385    0.021 /usr/lib/python2.4/sre_compile.py:27(_compile)
       2    0.097    0.049    0.100    0.050 /usr/lib/python2.4/site-packages/dbus/service.py:14(__new__)

Although some observations can be made about this results, would be more useful if someone executed this profiling on a test board and reported the result here.