datastore initialization should happen the activity has been brought up

[tomeu]

During activity startup, a new entry in the DS is created. This contributes significantly to the slow startup.

This should probably happen only once the activity is up and running and only once the user has done something worth saving.

[mtd]

Attaching a straw man patch...this certainly improves Terminal's perceived startup time (by about >1.4 seconds it takes to write to the datastore).

Before (note datastore object is created by activity.py before Terminal's init() says "Starting the Terminal activity"):

bash-3.2$ more ~/.sugar/default/logs/org.laptop.Terminal-4.log   
1215392301.740669 WARNING root: Activity directory lacks a MANIFEST file.
1215392303.542658 DEBUG root: terminal.py: imports took 1.61535310745 secs
1215392303.783406 DEBUG root: Creating a jobject.
1215392303.797043 DEBUG root: datastore.write
1215392303.904979 DEBUG root: dbus_helpers.create: d211e814-816b-471b-a95d-d1e971c2251f
1215392303.907042 DEBUG root: Written object d211e814-816b-471b-a95d-d1e971c2251f to the datastore.
1215392303.970035 DEBUG root: *** Act fa7b6b7574efaaad9924ae1cd307b789ea7a94c5, mesh instance None, scope private
1215392303.972049 DEBUG root: Starting the Terminal activity
1215392303.974206 DEBUG root: burned 0.00501704216003 secs before I tried to init
1215392303.984277 DEBUG root: burned 0.42459487915 secs in activity.py's __init__
1215392304.790131 WARNING root: No gtk.AccelGroup in the top level window.
1215392304.861921 WARNING root: No gtk.AccelGroup in the top level window.
** (sugar-activity:3757): DEBUG: Got client ID "1023c02c4ebb456f2121539230641872000000031880003"
** (sugar-activity:3757): DEBUG: Setting initial properties
** (sugar-activity:3757): DEBUG: Received SaveYourself(SmSaveLocal, !Shutdown, SmInteractStyleNone, !Fast) in state idle
** (sugar-activity:3757): DEBUG: Sending SaveYourselfDone(True) for initial SaveYourself
** (sugar-activity:3757): DEBUG: Received SaveComplete message in state save-yourself-done

After (note datastore object is now created by activity.py *after* Terminal's init() says "Starting the Terminal activity"):

bash-3.2$ more ~/.sugar/default/logs/org.laptop.Terminal-1.log
1215393792.080565 WARNING root: Activity directory lacks a MANIFEST file.
1215393793.716737 DEBUG root: terminal.py: imports took 1.53287696838 secs
1215393794.002742 DEBUG root: Starting the Terminal activity
1215393794.004603 DEBUG root: burned 0.0048360824585 secs before I tried to init
1215393794.006282 DEBUG root: burned 0.28128194809 secs in activity.py's __init__
1215393794.434895 WARNING root: No gtk.AccelGroup in the top level window.
1215393794.472340 WARNING root: No gtk.AccelGroup in the top level window.
** (sugar-activity:2798): DEBUG: Got client ID "109c1fd4bc94ef0f0f121539379517423900000026420001"
** (sugar-activity:2798): DEBUG: Setting initial properties
1215393795.178198 DEBUG root: Creating a jobject.
1215393795.185803 DEBUG root: datastore.write
1215393795.611513 DEBUG root: dbus_helpers.create: 8d4c92b5-6233-4b45-a238-dc3e6b404354
1215393795.614680 DEBUG root: Written object 8d4c92b5-6233-4b45-a238-dc3e6b404354 to the datastore.
1215393795.622676 DEBUG root: *** Act 5c6d5e2caf35703928221925f11e4fd4e305a480, mesh instance None, scope private
** (sugar-activity:2798): DEBUG: Received SaveYourself(SmSaveLocal, !Shutdown, SmInteractStyleNone, !Fast) in state idle
** (sugar-activity:2798): DEBUG: Sending SaveYourselfDone(True) for initial SaveYourself
** (sugar-activity:2798): DEBUG: Received SaveComplete message in state save-yourself-done

[mtd]

can also be seen in my sugar-toolkit repo at http://dev.laptop.org/git?p=users/mdengler/sugar-toolkit;a=commit;h=215249d3f2c843496b088f641ff3f86c78e8df7c

[tomeu]

Martin, just put some prints and got that the time that it takes to write the initial entry to the DS is ~130 ms. Are you sure that in your tests delaying datastore object creation improves startup time by 1.4s.?

[mtd]

(warning, this is a long one. Summary: I think we're both right, so something hard-to-measure is going on and the patch is probably interesting.)

Replying to tomeu:

Martin, just put some prints and got that the time that it takes to write the initial entry to the DS is ~130 ms. Are you sure that in your tests delaying datastore object creation improves startup time by 1.4s.?

You're right - my 1.4 s improvement came from comparing the time the datastore object was written before my change with the time it was written after the change, which is a pretty useless comparison, sorry:

t0_before: 1215392301.740669 WARNING root: Activity directory lacks a MANIFEST file.
t0_after : 1215392303.907042 DEBUG root: Written object d211e814-816b-471b-a95d-d1e971c2251f to the datastore.

t0_after - t0_before = 2.16 seconds

t1_before: 1215393792.080565 WARNING root: Activity directory lacks a MANIFEST file.
t1_after : 1215393795.614680 DEBUG root: Written object 8d4c92b5-6233-4b45-a238-dc3e6b404354 to the datastore.

t1_after - t1_before = 3.49 seconds

(t1_after - t1_before) - (t0_after - t0_before) = 1.43 seconds.

Based on when the "Starting the Terminal activity" line is printed, the improvement is much less:

t0_before: 1215392301.740669 WARNING root: Activity directory lacks a MANIFEST file.
t0_after : 1215392303.972049 DEBUG root: Starting the Terminal activity

t0_after - t0_before = 2.23 seconds

t1_before: 1215393792.080565 WARNING root: Activity directory lacks a MANIFEST file.
t1_after : 1215393794.002742 DEBUG root: Starting the Terminal activity

t1_after - t1_before = 1.92 seconds

(t0_after - t0_before) - (t1_after - t1_before) = 0.31 seconds.

The improvement to startup time is thus ~0.2 seconds, consistent with what you're seeing (obviously the error margin percentage on our measurements is quite large).

However I've just done a different test: measuring the difference in time when the gobject idle callbacks get called before and after my patch. I've done two measurements, one "warm" (start Terminal twice and take the second run's timings) and one cold (the first Terminal run's timings).

Here are the timings:

Warm:

bash-3.2$ grep "START\|END" ~/tmp/*6472-*3.log
/home/olpc/tmp/org.laptop.Terminal-6472-ante3.log:1216215672.568288 DEBUG root: START: Starting the Terminal activity
/home/olpc/tmp/org.laptop.Terminal-6472-ante3.log:1216215674.996866 DEBUG root: END:   Terminal gobject idle loop started.
/home/olpc/tmp/org.laptop.Terminal-6472-post3.log:1216215938.344544 DEBUG root: START: Starting the Terminal activity
/home/olpc/tmp/org.laptop.Terminal-6472-post3.log:1216215939.885097 DEBUG root: END:   Terminal gobject idle loop started.
bash-3.2$ # ante3: 5.00 - 2.56 = 2.44
bash-3.2$ # post3: 9.89 - 8.34 = 1.55

Warm change after my patch: -0.89 seconds (better).

Cold:

$ grep "START\|END" ~/tmp/*6472-*2.log
/home/olpc/tmp/org.laptop.Terminal-6472-ante2.log:1216214997.162661 DEBUG root: START: Starting the Terminal activity
/home/olpc/tmp/org.laptop.Terminal-6472-ante2.log:1216214999.892204 DEBUG root: END:   Terminal gobject idle loop started.
/home/olpc/tmp/org.laptop.Terminal-6472-post2.log:1216214825.109634 DEBUG root: START: Starting the Terminal activity
/home/olpc/tmp/org.laptop.Terminal-6472-post2.log:1216214826.991132 DEBUG root: END:   Terminal gobject idle loop started.
$ # ante2: 9.89 - 7.16 = 2.73
$ # post2: 6.99 - 5.11 = 1.88

Cold change after my patch: -0.85 seconds (better).

Here is the diff I applied to a slightly-old terminal.py:

diff terminal.py:

--- /home/olpc/Activities/Terminal.activity/terminal.py.orig	2008-02-11 16:06:18.000000000 +0000
+++ /home/olpc/Activities/Terminal.activity/terminal.py	2008-07-16 13:38:37.000000000 +0000
@@ -15,6 +15,9 @@
 # along with this program; if not, write to the Free Software
 # Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA  02110-1301  USA
 
+import time
+t0 = time.time()
+
 import os
 
 import logging
@@ -32,13 +35,21 @@
 
 import vte
 import pango
+import gobject
+
+t1 = time.time()
+logging.debug("terminal.py: imports took %s secs" % (t1 - t0))
 
 class TerminalActivity(activity.Activity):
 
     def __init__(self, handle):
+        logging.debug('START: Starting the Terminal activity')
+        t2 = time.time()
         activity.Activity.__init__(self, handle)
+        t3 = time.time()
         
-        logging.debug('Starting the Terminal activity')
+        logging.debug('burned %s secs before I tried to init' % (t2 - t1))
+        logging.debug('burned %s secs in activity.py\'s __init__' % (t3 - t2))
         
         self.set_title(_('Terminal Activity'))
         self.connect('key-press-event', self.__key_press_cb)
@@ -83,8 +96,12 @@
         self.set_canvas(box)
         box.show()
         
+        gobject.idle_add(self.__terminal_init_idle_cb)
         self._vte.grab_focus()
 
+    def __terminal_init_idle_cb(self):
+        logging.debug("END:   Terminal gobject idle loop started.")
+
     def _copy_cb(self, button):
         if self._vte.get_has_selection():
             self._vte.copy_clipboard()

[tomeu]

Ok, in view of this results, I think that we should continue this analysis in the next release, as we don't get any more all the benefits we expected and the patch would be quite invasive.