Ticket #5228 (new defect)

Opened 5 years ago

Last modified 5 years ago

launching activities is slow

Reported by: tomeu Owned by: tomeu
Priority: high Milestone: 9.1.0-cancelled
Component: sugar Version:
Keywords: performance, 9.1.0:? Cc: cjb, cscott, bernie, mstone, gdesmott, smcv, daf, morgs, mtd
Action Needed: never set Verified: no
Deployments affected: Blocked By:
Blocking:

Description (last modified by jg) (diff)

A very simple activity like Edit takes 7.5s. to start: 

1196459309.944826 DEBUG root: TIME ActivitiesTray._activity_clicked_cb
1196459309.990664 DEBUG root: TIME ActivitiesTray._activity_clicked_cb finished
1196459315.327806 DEBUG root: TIME Activity.__init__
1196459315.430712 DEBUG root: TIME activity realized
1196459317.179460 DEBUG root: TIME Activity.__init__ finished
1196459317.715276 DEBUG root: TIME Activity.__canvas_map_cb
1196459317.717275 DEBUG root: TIME Activity.__canvas_map_cb finished

https://dev.laptop.org/~marco/edit-activity/

Attachments

startup.kgrind (298.0 kB) - added by tomeu 5 years ago.
profile summarized in the comment above
imports3.log (4.1 kB) - added by tomeu 5 years ago.

Change History

  Changed 5 years ago by tomeu

If donut icon doesn't pulse during activity launch, time goes down to 6.5s.: 

1196459668.283356 DEBUG root: TIME ActivitiesTray._activity_clicked_cb
1196459668.330895 DEBUG root: TIME ActivitiesTray._activity_clicked_cb finished
1196459672.702312 DEBUG root: TIME Activity.__init__
1196459672.791678 DEBUG root: TIME activity realized
1196459674.307667 DEBUG root: TIME Activity.__init__ finished
1196459674.772826 DEBUG root: TIME Activity.__canvas_map_cb
1196459674.774815 DEBUG root: TIME Activity.__canvas_map_cb finished

  Changed 5 years ago by tomeu

We can recover one second by disabling ipython startup when not debugging: #5273.

  Changed 5 years ago by tomeu

After disabling ipython: 

1196704380.26		 DEBUG root: TIME ActivitiesTray._activity_clicked_cb
1196704380.27	0.00	 DEBUG root: TIME ActivityCreationHandler.__init__
1196704380.27	0.01	 DEBUG root: TIME ActivityCreationHandler._create_activity
1196704380.28	0.01	 DEBUG root: TIME ActivityCreationHandler._create_activity: [u'sugar-activity', u'editactivity.EditActivity', '-b', dbus.String(u'org.laptop.Edit', variant_level=1), '-a', 'b9c2bfef9c7dc63e45d585eab636e6c21ea3540c']
1196704380.34	0.05	 DEBUG root: TIME ActivityCreationHandler._create_activity finished
1196704380.34	0.00	 DEBUG root: TIME ActivityCreationHandler.__init__ finished
1196704380.34	0.00	 DEBUG root: TIME ActivitiesTray._activity_clicked_cb finished
1196704380.57	0.22	 DEBUG root: TIME sugar-activity after logger.start()
1196704382.03	1.46	 DEBUG root: TIME importing activity module
1196704383.42	1.39	 DEBUG root: TIME sugar-activity after module.start()
1196704383.42	0.01	 DEBUG root: TIME sugar-activity after ActivityBundle(bundle_path)
1196704383.43	0.00	 DEBUG root: TIME sugar-activity after gettext
1196704383.43	0.01	 DEBUG root: TIME EditActivity.__init__
1196704383.43	0.00	 DEBUG root: TIME Activity.__init__
1196704383.56	0.12	 DEBUG root: TIME activity realized
1196704385.06	1.50	 DEBUG root: TIME Activity.__init__ finished
1196704385.42	0.36	 DEBUG root: TIME EditActivity.__init__ finished
1196704385.53	0.11	 DEBUG root: TIME Activity.__canvas_map_cb
1196704385.53	0.00	 DEBUG root: TIME Activity.__canvas_map_cb finished
1196704385.54	0.00	 DEBUG root: TIME sugar-activity after create_activity_instance(constructor, handle)

  Changed 5 years ago by marco

Note that this is a huge regression from Trial-3. With 623 the Chat seems to start 3x faster compared to current joyride.

  Changed 5 years ago by marco

  • priority changed from normal to high

  Changed 5 years ago by jg

  • description modified (diff)
  • milestone changed from Never Assigned to Update.1

  Changed 5 years ago by cjb

  • cc cjb added
  • keywords performance added

  Changed 5 years ago by mstone

  • cc cscott, bernie, mstone added

  Changed 5 years ago by tomeu

Unmodified 1197488548.04 INFO root: TIME _activity_clicked_cb 1197488556.07 8.03 INFO root: TIME canvas_map_cb 1197488816.74 INFO root: TIME _activity_clicked_cb 1197488824.9 8.16 INFO root: TIME canvas_map_cb 1197488837.18 INFO root: TIME _activity_clicked_cb 1197488845.25 8.07 INFO root: TIME canvas_map_cb

8.09

Without ipython 1197488926.82 INFO root: TIME _activity_clicked_cb 1197488934.55 7.72 INFO root: TIME canvas_map_cb 1197488953.16 INFO root: TIME _activity_clicked_cb 1197488960.85 7.69 INFO root: TIME canvas_map_cb 1197489135.19 INFO root: TIME _activity_clicked_cb 1197489142.88 7.7 INFO root: TIME canvas_map_cb 1197489146.23 INFO root: TIME _activity_clicked_cb 1197489153.95 7.73 INFO root: TIME canvas_map_cb 1197489159.94 INFO root: TIME _activity_clicked_cb 1197489167.62 7.68 INFO root: TIME canvas_map_cb

7.7

Without pulsing 1197489351.81 INFO root: TIME _activity_clicked_cb 1197489358.42 6.61 INFO root: TIME canvas_map_cb 1197489421.31 INFO root: TIME _activity_clicked_cb 1197489427.16 5.85 INFO root: TIME canvas_map_cb 1197489432.69 INFO root: TIME _activity_clicked_cb 1197489439.56 6.87 INFO root: TIME canvas_map_cb 1197489448.23 INFO root: TIME _activity_clicked_cb 1197489454.8 6.57 INFO root: TIME canvas_map_cb 1197489465.55 INFO root: TIME _activity_clicked_cb 1197489472.1 6.55 INFO root: TIME canvas_map_cb

6.49

  Changed 5 years ago by tomeu 

Unmodified		
1197488548.04		 INFO root: TIME _activity_clicked_cb
1197488556.07	8.03	 INFO root: TIME __canvas_map_cb
1197488816.74		 INFO root: TIME _activity_clicked_cb
1197488824.9	8.16	 INFO root: TIME __canvas_map_cb
1197488837.18		 INFO root: TIME _activity_clicked_cb
1197488845.25	8.07	 INFO root: TIME __canvas_map_cb
	8.09	

Without ipython		
1197488926.82		 INFO root: TIME _activity_clicked_cb
1197488934.55	7.72	 INFO root: TIME __canvas_map_cb
1197488953.16		 INFO root: TIME _activity_clicked_cb
1197488960.85	7.69	 INFO root: TIME __canvas_map_cb
1197489135.19		 INFO root: TIME _activity_clicked_cb
1197489142.88	7.7	 INFO root: TIME __canvas_map_cb
1197489146.23		 INFO root: TIME _activity_clicked_cb
1197489153.95	7.73	 INFO root: TIME __canvas_map_cb
1197489159.94		 INFO root: TIME _activity_clicked_cb
1197489167.62	7.68	 INFO root: TIME __canvas_map_cb
	7.7	

Without pulsing		
1197489351.81		 INFO root: TIME _activity_clicked_cb
1197489358.42	6.61	 INFO root: TIME __canvas_map_cb
1197489421.31		 INFO root: TIME _activity_clicked_cb
1197489427.16	5.85	 INFO root: TIME __canvas_map_cb
1197489432.69		 INFO root: TIME _activity_clicked_cb
1197489439.56	6.87	 INFO root: TIME __canvas_map_cb
1197489448.23		 INFO root: TIME _activity_clicked_cb
1197489454.8	6.57	 INFO root: TIME __canvas_map_cb
1197489465.55		 INFO root: TIME _activity_clicked_cb
1197489472.1	6.55	 INFO root: TIME __canvas_map_cb
	6.49

  Changed 5 years ago by tomeu

Current: 8.09s. Without ipython: 7.7s. Without ipython + without pulsing: 6.49s. Without ipython + without pulsing + without journal: 4.68s.

  Changed 5 years ago by tomeu

Without ipython + with pulsing at 5fps (instead of 10fps): 7.01s.

  Changed 5 years ago by tomeu

Without ipython + without pulsing + with journal patch #5393: 5.25s.

follow-up: ↓ 15   Changed 5 years ago by tomeu

Without ipython + with pulsing at 5fps (instead of 10fps) + with journal patch #5393: 5.59s.

in reply to: ↑ 14   Changed 5 years ago by cjb

Replying to tomeu:

Without ipython + with pulsing at 5fps (instead of 10fps) + with journal patch #5393: 5.59s.

Ship it! :)

  Changed 5 years ago by tomeu

Results of profiling /usr/bin/sugar-activity: 

26.70% import editactivity
  24.74% from sugar.activity import activity
    8.01% from sugar.graphics import style
    7.43% from sugar.graphics import window

25.04% create_activity_instance
  22.89% EditActivity()
    15.60% Activity()
      7.22% PresenceService.get_activity()
      4.99% DataStore.write()
     6.96% ActivityToolbox()
       6.75% ActivityToolbar()
         4.97% ComboBox.append_item()
           3.37% gtk.IconTheme.lookup_icon()

15.84% import activityhandle
  14.64% import presenceservice
    12.67% from sugar.presence import activity
      12.55% import telepathy
         9.47% from telepathy import server
            2.98% from telepath.server import conn
            2.97% from telepath.server import channel
         2.01% from telepathy import client

 9.63% from dbus import service
   9.28% from dbus import decorators
     9.20% import inspect
       8.93% import tokenize
         8.46% map()
           8.46% re.compile()
           
 8.88% import pygtk
 3.77% import activitybundle
   2.67% from sugar.bundle import bundle

Changed 5 years ago by tomeu

profile summarized in the comment above

  Changed 5 years ago by tomeu

This patch to python will make it print the time that each import takes. 

--- ../Python.orig/Python-2.5.1/Python/import.c 2007-03-14 00:04:29.000000000 +0100
+++ Python/import.c     2007-12-14 18:56:47.000000000 +0100
@@ -666,11 +666,21 @@
                PyErr_Clear(); /* Not important enough to report */
        Py_DECREF(v);
 
+  time_t  t0, t1; /* time_t is defined on <bits/types.h> as long */
+  clock_t c0, c1; /* clock_t is defined on <bits/types.h> as long */
+  
+    t0 = time(NULL);
+    c0 = clock();
+  
        v = PyEval_EvalCode((PyCodeObject *)co, d, d);
        if (v == NULL)
                goto error;
        Py_DECREF(v);
 
+    t1 = time(NULL);
+    c1 = clock();
+    printf ("\timported %s cpu: %f real: %ld\n", pathname, (float) (c1 - c0)/CLOCKS_PER_SEC, (long) (t1 - t0));
+
        if ((m = PyDict_GetItemString(modules, name)) == NULL) {
                PyErr_Format(PyExc_ImportError,
                             "Loaded module %.200s not found in sys.modules",

  Changed 5 years ago by gdesmott

  • cc mtone, gdesmott added; mstone removed

  Changed 5 years ago by tomeu

  • cc mstone added; mtone removed

  Changed 5 years ago by tomeu

See #5525 for the ipython issue.

  Changed 5 years ago by tomeu

See #5526 for the pulsing issue.

  Changed 5 years ago by marco

  • milestone changed from Update.1 to Retriage, Please!

We are past code freeze so I don't think we should do more work on this for Update.1. We should probably land #5525 though.

follow-up: ↓ 24   Changed 5 years ago by tomeu

Just tried to launch Edit with a python built by Michael that measures the time that takes to read and parse a module.

It took 238.7ms in total.

The read and parse times for modules inside IPython is 116ms, almost half of total.

So I think that points to the module level code as the reason why importing modules is slow, not the reading and parsing of the modules.

in reply to: ↑ 23 ; follow-up: ↓ 26   Changed 5 years ago by bernie

Replying to tomeu:

So I think that points to the module level code as the reason why importing modules is slow, not the reading and parsing of the modules.

I thought we had made it clear long time ago that activity startup time is definitely not dominated by I/O, syscalls or .pyc parsing time (as many claimed).

The bigger offenders, pygtk and the telepathy bindings, just do way too much initialization work at import time, such as connecting to X11 and dbus, instantiating lots of wrappers, etc.

But while we can't possibly rewrite all the poorly designed bindings out there, we can at least push them in places where they aren't imported unless strictly needed.

follow-ups: ↓ 27 ↓ 28   Changed 5 years ago by gdesmott

  • cc smcv, daf, morgs added

When using the new sharing API, activity should only use some constants from the telepathy module. Will that make any difference if instead of importing telepathy and use these constants as "telepathy.foo", we'll import them using "from telepathy import foo, bar" (I have no clue how Python import actually works) ?

in reply to: ↑ 24 ; follow-up: ↓ 29   Changed 5 years ago by tomeu

Replying to bernie:

Replying to tomeu:

So I think that points to the module level code as the reason why importing modules is slow, not the reading and parsing of the modules.

I thought we had made it clear long time ago that activity startup time is definitely not dominated by I/O, syscalls or .pyc parsing time (as many claimed). The bigger offenders, pygtk and the telepathy bindings, just do way too much initialization work at import time, such as connecting to X11 and dbus, instantiating lots of wrappers, etc. But while we can't possibly rewrite all the poorly designed bindings out there, we can at least push them in places where they aren't imported unless strictly needed.

Nice to see that we agree at last. Now we need to know which modules will make a difference when moved somewhere else.

in reply to: ↑ 25   Changed 5 years ago by tomeu

Replying to gdesmott:

When using the new sharing API, activity should only use some constants from the telepathy module. Will that make any difference if instead of importing telepathy and use these constants as "telepathy.foo", we'll import them using "from telepathy import foo, bar" (I have no clue how Python import actually works) ?

If activity.py imports sugar.presence.presenceservice, then that will need to import telepathy anyway and that will make no difference at all.

Only moving imports to methods or funcs that execute *after* the activity has been brought up (the user sees it as launched and functional) will make a difference.

in reply to: ↑ 25   Changed 5 years ago by bernie

Replying to gdesmott:

When using the new sharing API, activity should only use some constants from the telepathy module. Will that make any difference if instead of importing telepathy and use these constants as "telepathy.foo", we'll import them using "from telepathy import foo, bar" (I have no clue how Python import actually works) ?

I'm afraid the "from foo import bar "syntax just changes visibility, but doesn't save any processing. The semantics for module writers is that code at global scope gets executed only once, the first time the module gets imported.

in reply to: ↑ 26 ; follow-up: ↓ 30   Changed 5 years ago by bernie

Replying to tomeu:

Nice to see that we agree at last. Now we need to know which modules will make a difference when moved somewhere else.

The only ones I've observed being outrageously slow were gtk and numpy. I've been told that telepathy and dbus are also

I used a very sophisticated profiler. Here's the source code, released under the BerniePublicLicenseV3: 

time for i in `seq 1 10`; do python -c 'import gtk'; done

Use it responsibly, and never cross the beams!

in reply to: ↑ 29   Changed 5 years ago by bernie

Replying to bernie:

The only ones I've observed being outrageously slow were gtk and numpy. I've been told that telepathy and dbus are also

horribly slow? I was missing the inspiration.

I'm testing on my PPC@1GHz laptop... results should scale almost evenly on the XO: 

bernie@daneel:~$ time for i in `seq 1 10`; do python -c 'import numpy'; done
real	0m5.572s
user	0m4.186s
sys	0m1.196s

bernie@daneel:~$ time for i in `seq 1 10`; do python -c 'import gtk'; done
real	0m5.176s
user	0m2.540s
sys	0m1.127s

bernie@daneel:~$ time for i in `seq 1 10`; do python -c 'import telepathy'; done
real	0m4.058s
user	0m2.517s
sys	0m1.209s

bernie@daneel:~$ time for i in `seq 1 10`; do python -c 'import dbus'; done
real	0m1.754s
user	0m0.914s
sys	0m0.762s

bernie@daneel:~$ time for i in `seq 1 10`; do python -c 'import cairo'; done
real	0m1.433s
user	0m0.747s
sys	0m0.551s

bernie@daneel:~$ time for i in `seq 1 10`; do python -c 'import sys'; done
real	0m1.148s
user	0m0.612s
sys	0m0.442s

bernie@daneel:~$ time for i in `seq 1 10`; do python -c 'pass'; done
real	0m0.683s
user	0m0.394s
sys	0m0.251s

  Changed 5 years ago by jg

  • milestone changed from Retriage, Please! to Update.2

  Changed 5 years ago by mtd

  • cc mtd added

FWIW, some timing data along the most recent example's lines: 

trac_5228_tests.sh v:1.0
             total       used       free     shared    buffers     cached
Mem:        237844     229740       8104          0          0      95240
-/+ buffers/cache:     134500     103344
Swap:            0          0          0
PQ2D10
C2
update.1 690

--------
numpy...

real    0m39.927s
user    0m36.560s
sys     0m1.110s
--------
gtk...

real    0m7.027s
user    0m6.020s
sys     0m0.560s
--------
telepathy...

real    0m13.262s
user    0m11.830s
sys     0m0.770s
--------
dbus...

real    0m2.638s
user    0m2.320s
sys     0m0.300s
--------
cairo...

real    0m1.298s
user    0m1.070s
sys     0m0.230s
--------
sys...

real    0m1.059s
user    0m0.870s
sys     0m0.180s
--------
baseline (just pass)...

real    0m1.402s
user    0m0.940s
sys     0m0.150s

Script: 

#!/bin/bash
echo "trac_5228_tests.sh v:1.0"
free
for f in /ofw/ec-name /ofw/model /boot/olpc_build ; do
    echo `cat $f`
done
echo
for c in numpy gtk telepathy dbus cairo sys ; do
    echo "--------" ;
    echo $c... ;
    time for i in `seq 1 10`; do python -c "import $c" ; done
done
echo "--------" ;
echo "baseline (just pass)..."
time for i in `seq 1 10`; do python -c "pass" ; done

  Changed 5 years ago by tomeu

Attached a file listing all modules (161!) imported by activities at startup.

Changed 5 years ago by tomeu

  Changed 5 years ago by tomeu

#6471 and #6472 track two ways of reducing the amount of work we do before the activity starts up.

  Changed 5 years ago by tomeu

"How Import Does Its Thing (#2)": http://us.pycon.org/2008/conference/schedule/event/12/

  Changed 5 years ago by tomeu

Where is time going in the faster branch: 

94.26% create_activity_instance
    78.97% pippy_app.Chat.__init__
        57.69% activity.Chat.__init__
            50.77% datastore.write
             3.66% presenceservice.get_instance
        16.56% ActivityToolbox.__init__
            15.99% ActivityToolbar.__init__
                13.02% ComboBox.append_item
                     8.06% gtk.IconTheme.lookup_icon
    15.30% Window.show()

  Changed 5 years ago by tomeu

  • keywords performance, 9.1.0:? added; performance removed
  • milestone changed from Update.2 (8.2.0) to Retriage, Please!

  Changed 5 years ago by tomeu

  • milestone changed from Retriage, Please! to 9.1.0

  Changed 5 years ago by mtd

  • next_action set to never set

Here are some new import timing results - the real time comes first, and the times are for ten runs, so just divide by ten for the average import time, in seconds...: 

trac_5228_tests.sh v:1.3
             total       used       free     shared    buffers     cached
Mem:        237760     223040      14720          0          0      36328
-/+ buffers/cache:     186712      51048
Swap:            0          0          0
PQ2D13
C2
joyride 2105
Tests can take over two minutes on a C2 machine, so be patient...
--------
1.135,0.920,0.200,baseline python overhead
1.151,0.940,0.170,os
1.156,0.980,0.150,sys
1.197,0.930,0.250,time
1.409,1.130,0.250,tempfile
1.450,1.160,0.270,hashlib
1.453,0.990,0.180,traceback
1.489,1.170,0.280,gobject
1.559,1.180,0.250,cairo
1.867,1.460,0.320,pango
1.950,1.680,0.240,sugar.datastore
1.963,1.600,0.330,sugar.graphics
1.966,1.560,0.320,gettext
2.042,1.510,0.260,atk
2.091,1.540,0.390,sugar.presence
2.110,1.740,0.320,logging
2.211,1.670,0.270,sugar
2.239,1.810,0.390,pangocairo
2.344,1.500,0.290,json
2.814,2.410,0.310,dbus
2.984,2.550,0.370,sugar.util
4.142,3.030,0.620,sugar.profile
6.441,5.740,0.490,dbus.service
6.970,6.020,0.650,gtk
7.705,6.520,0.660,sugar.activity.activityservice
8.162,6.800,0.650,sugar.wm
8.203,7.000,0.700,sugar._sugarext
8.213,6.810,0.920,sugar.session
9.737,8.390,0.720,telepathy
10.264,8.460,1.080,sugar.graphics.icon
10.276,8.550,1.080,sugar.graphics.window
14.181,11.870,1.120,sugar.graphics.toolcombobox
14.336,12.090,1.190,sugar.graphics.toolbox
15.861,13.440,1.380,sugar.graphics.alert
17.021,14.430,1.270,sugar.graphics.toolbutton
40.122,36.740,0.910,numpy
--------
Sugar activity.py used modules:
1.192,0.850,0.310,traceback
1.404,1.090,0.250,tempfile
1.408,0.920,0.220,os
1.486,1.160,0.270,gobject
1.554,1.230,0.210,hashlib
1.814,1.510,0.260,json
1.942,1.650,0.260,sugar.datastore
1.957,1.590,0.300,gettext
1.958,1.590,0.310,sugar
2.017,1.690,0.270,sugar.graphics
2.109,1.720,0.320,logging
2.597,1.640,0.330,sugar.presence
2.982,2.510,0.410,sugar.util
3.760,3.090,0.590,sugar.profile
6.703,5.850,0.460,dbus.service
7.627,6.500,0.710,sugar.activity.activityservice
8.174,6.850,0.840,sugar._sugarext
8.229,6.830,0.740,sugar.wm
8.682,6.940,0.910,sugar.session
10.257,8.590,1.060,sugar.graphics.window
11.019,8.540,1.140,sugar.graphics.icon
14.180,11.840,1.160,sugar.graphics.toolcombobox
14.244,12.170,0.970,sugar.graphics.toolbox
15.549,13.320,1.530,sugar.graphics.alert
16.424,14.360,1.280,sugar.graphics.toolbutton
--------

...generated by this script (well, I sorted the timings by hand :)): 

#!/bin/bash
echo "trac_5228_tests.sh v:1.3"

export TIMEFORMAT=%R,%U,%S

free

for f in /ofw/ec-name /ofw/model /boot/olpc_build ; do
    echo `cat $f`
done

echo "Tests can take over two minutes on a C2 machine, so be patient..."
echo "--------" ;

data=$( (time for i in `seq 1 10`; do python -c "pass" ; done) 2>&1 )
# yes, I mean to do this twice
data=$( (time for i in `seq 1 10`; do python -c "pass" ; done) 2>&1 )
echo ${data},baseline python overhead

for module in time dbus cairo pango atk pangocairo numpy gtk telepathy sys sugar gettext logging os tempfile hashlib traceback gobject dbus.service json sugar.util sugar.presence sugar.activity.activityservice sugar.graphics sugar.graphics.window sugar.graphics.toolbox sugar.graphics.toolbutton sugar.graphics.toolcombobox sugar.graphics.alert sugar.graphics.icon sugar.datastore sugar.session sugar._sugarext sugar.profile sugar.wm ; do
    data=$( (time for i in `seq 1 10`; do python -c "import $module" ; done) 2>&1 )
    echo ${data},${module}
done
echo "--------" ;
echo "Sugar activity.py used modules:" 
for module in sugar gettext logging os tempfile hashlib traceback gobject dbus.service json sugar.util sugar.presence sugar.activity.activityservice sugar.graphics sugar.graphics.window sugar.graphics.toolbox sugar.graphics.toolbutton sugar.graphics.toolcombobox sugar.graphics.alert sugar.graphics.icon sugar.datastore sugar.session sugar._sugarext sugar.profile sugar.wm ; do
    data=$( (time for i in `seq 1 10`; do python -c "import $module" ; done) 2>&1 )
    echo ${data},${module}
done
echo "--------" ;
Note: See TracTickets for help on using tickets.