[sugar] Need guidance from a Pygtk guru

[Pierre Métras]

Hello,

I've learnt Python and Pygtk writing the Clock activity
(http://wiki.laptop.org/go/Clock_activity) and I'm now adding a new feature
to write the time in full letters to help children learn how to write and read 
it. The clock has different display modes and the default one is to use a SVG
background. I encounter a strange behavior and I don't know where to look at
to correct it.

The display of the clock activity is composed of a gtk.VBox with a custom
ClockFace widget at the top, and a gtk.Label where I write the current time.
The user can decide to hide/show the written time with an icon in the
toolbar.

When the Label is not displayed, the XO has enough power to update the
ClockFace widget in less than 1 second, which is nice and what you would
expect from a clock with a hand for seconds.

But when the user selects to show the time and the code show() the gtk.Label,
the ClockFace widget takes more than 1 second to refresh. The whole activity
becomes unresponsive and it is even difficult to move the mouse to close it.
Gtk timer event every seconds can't follow up...

I've tracked the problem to these lines:

           if radius != self._cache_radius:
                f = open("clock.svg", "rb")
                svg_data = f.read()
                f.close()

                loader = gtk.gdk.PixbufLoader("svg")
                loader.set_size(int(2 * radius), int(2 * radius))
                loader.write(svg_data)
                loader.close()

                self._cache_pixbuf = loader.get_pixbuf()
                self._cache_radius = radius

            pixbuf = self._cache_pixbuf       # 1.1
            ct = gtk.gdk.CairoContext(context)
            t12=datetime.now() # PME
            ct.set_source_pixbuf(pixbuf, x - radius, y - radius)  # 1.2

            t13=datetime.now() # PME
            context.paint()          # 1.3
            t14=datetime.now()
            print "PME %s 1.2->1.3=%ss 1.3->1.4=%ss" % (t14, t13-t12, t14-13)
            context.stroke()

Without the gtk.Label displayed, a typical log trace is:

PME 2008-10-04 13:01:15.031723 +update_cb
PME 2008-10-04 13:01:15.033482 +draw
PME 2008-10-04 13:01:15.348868 1.2->1.3=0:00:00.231589s
1.3->1.4=0:00:00.083030s
PME 2008-10-04 13:01:15.354891 -draw
PME 2008-10-04 13:01:15.355902 -update_cb

The whole ClockFace update takes 0.32s.
ct.set_source_pixbuf call lasts 0.23s and context.paint one 0.08s.


Whenever the gtk.Label is shown, the pattern is totally different. Here is a
not so extreme log (I've kept only the significant lines):

PME 2008-10-04 10:48:42.025741 1.2->1.3=0:00:00.354320s
1.3->1.4=0:00:01.146650s
PME 2008-10-04 10:48:43.539496 1.2->1.3=0:00:00.307176s
1.3->1.4=0:00:01.196331s
PME 2008-10-04 10:48:45.074410 1.2->1.3=0:00:00.297737s
1.3->1.4=0:00:01.212910s
PME 2008-10-04 10:48:46.573627 1.2->1.3=0:00:00.311503s
1.3->1.4=0:00:01.176982s
PME 2008-10-04 10:48:48.091777 1.2->1.3=0:00:00.364210s
1.3->1.4=0:00:01.143602s
PME 2008-10-04 10:48:49.595859 1.2->1.3=0:00:00.342134s
1.3->1.4=0:00:01.151180s
PME 2008-10-04 10:48:51.082667 1.2->1.3=0:00:00.270270s
1.3->1.4=0:00:01.205943s

Now, ct.set_source_pixbuf call lasts 0.1s more and context.paint 1.1s. I've
even samples where the context.paint() call lasts 2.5 seconds!

As I've said, this strange behavior seems to occur only when the ClockFace
widget paints SVG. In the other display modes, the painting is drawn in the
code. I've seen it in 8.2-761 and still in candidate-767.

I've spent the last few days triying to find a reason for it, reading Gtk and
Pygtk docs, upgrading my XO to various releases and trying alternatives in
the code, without success. Has someone some ideas of what's happening and how
I could solve it?

Thanks
-- Pierre Métras