#6472 NORM 8.2.0 (: datastore initialization should happen the activity has been brought up
Zarro Boogs per Child
bugtracker at laptop.org
Wed Jul 16 09:58:19 EDT 2008
#6472: datastore initialization should happen the activity has been brought up
----------------------+-----------------------------------------------------
Reporter: tomeu | Owner: tomeu
Type: defect | Status: new
Priority: normal | Milestone: 8.2.0 (was Update.2)
Component: sugar | Version:
Resolution: | Keywords: 8.2.0:?
Next_action: design | Verified: 0
Blockedby: | Blocking:
----------------------+-----------------------------------------------------
Comment(by 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 [comment:4 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()
--
Ticket URL: <http://dev.laptop.org/ticket/6472#comment:5>
One Laptop Per Child <http://laptop.org/>
OLPC bug tracking system
More information about the Bugs
mailing list