Re: [sugar] rendering test
On Tue, 2008-09-30 at 21:30 +0200, Bernie Innocenti wrote: Michel Dänzer wrote: On Sun, 2008-09-28 at 18:46 +0200, Bernie Innocenti wrote: Tomeu Vizoso wrote: On Sun, Sep 28, 2008 at 12:46 PM, Riccardo Lucchese [EMAIL PROTECTED] wrote: On Sun, 2008-09-28 at 12:43 +0200, Riccardo Lucchese wrote: * build 703, xorg driver = amd, redraws = 200 - pixbuf: 98.63s 96.96s 96.58s 97.14s 99.21s * build 703, xorg driver = fbdev, redraws = 200 - pixbuf: 55.81s 55.40s 55.22s 55.50s 55.63s * build 2489, xorg driver = amd, redraws = 200 - pixbuf: 84.21s 84.81s 81.94s 81.79s 85.29s * build 2489, xorg driver = fbdev, redraws = 200 - pixbuf: 62.83s 62.81s 62.81s 62.66s 63.14s - joyride regressed sensibly at rendering with cairo since 703 - rendering pixbufs is extremely slow on the xo - server side surfaces are awesome ;) and btw why is fbdev faster than the geode driver at rendering pixbufs ? My performance tests with X 1.3 and 1.4 had shown that turning on EXA makes many operations slower. It's hard to tell why, but it might have to do with loosing XShmPut() (MIT shared memory), EXA does support XShmPutImage(), just not SHM pixmaps. I was remembering the code. As a result of ee7c684f21d, the PutImage hook in ShmFuncs is no longer being used. Shall I commit a cleanup? Also note that the fbdev driver by default uses a shadow framebuffer in system RAM and only updates the visible screen contents at regular intervals. It might be fairer to compare with Option ShadowFB off, at least assuming the amd driver provides other desirable features the fbdev driver can't provide. Riccardo, could you try that? weird, testing with the ShadowFb option off slightly speeds up the test ;P avg time on 5 tries: ~57.5s (it was 62.83s) riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: [sugar] rendering test
On Mon, 2008-09-29 at 09:08 -0600, Jordan Crouse wrote: On 28/09/08 18:46 +0200, Bernie Innocenti wrote: Tomeu Vizoso wrote: Ooops. cc'ing to some other people/list in the hope someone more knowledgeable than me will comment. Thanks. Please Cc me on posts like these to make sure I don't miss them. No, it doesn't bother me to receive 0.001% more mail. I've also Cc'd the Xorg list in case someone can give us more insight. On Sun, Sep 28, 2008 at 12:46 PM, Riccardo Lucchese [EMAIL PROTECTED] wrote: On Sun, 2008-09-28 at 12:43 +0200, Riccardo Lucchese wrote: * build 703, xorg driver = amd, redraws = 200 - pixbuf: 98.63s 96.96s 96.58s 97.14s 99.21s * build 703, xorg driver = fbdev, redraws = 200 - pixbuf: 55.81s 55.40s 55.22s 55.50s 55.63s * build 2489, xorg driver = amd, redraws = 200 - pixbuf: 84.21s 84.81s 81.94s 81.79s 85.29s * build 2489, xorg driver = fbdev, redraws = 200 - pixbuf: 62.83s 62.81s 62.81s 62.66s 63.14s - joyride regressed sensibly at rendering with cairo since 703 - rendering pixbufs is extremely slow on the xo - server side surfaces are awesome ;) and btw why is fbdev faster than the geode driver at rendering pixbufs ? Was fbdev running with EXA or XAA? (does fbdev even support EXA?) My performance tests with X 1.3 and 1.4 had shown that turning on EXA makes many operations slower. It's hard to tell why, but it might have to do with loosing XShmPut() (MIT shared memory), excessive migration of pixmaps to the framebuffer, and so on. X 1.5 was supposed to have a much better EXA, at least judging from the stream of patches landed on the tree. Indeed - migration is probably what is hurting us the most here. We would probably have to do a more in-depth analysis of what is actually happening in the engine, but the general rule of thumb is that it is very very very very very bad to read from the video memory. Timings with X 1.5 (I picked up the most recent package I could find on koji for fc9) don't change at all. riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: [sugar] rendering test
On Sun, 2008-09-28 at 18:46 +0200, Bernie Innocenti wrote: - joyride regressed sensibly at rendering with cairo since 703 - rendering pixbufs is extremely slow on the xo - server side surfaces are awesome ;) and btw why is fbdev faster than the geode driver at rendering pixbufs ? Was fbdev running with EXA or XAA? (does fbdev even support EXA?) http://www.x.org/wiki/ExaStatus lists fbdev in the `Probably unsuitable for EXA support' section; so, I guess XAA. My performance tests with X 1.3 and 1.4 had shown that turning on EXA makes many operations slower. It's hard to tell why, but it might have to do with loosing XShmPut() (MIT shared memory), excessive migration of pixmaps to the framebuffer, and so on. X 1.5 was supposed to have a much better EXA, at least judging from the stream of patches landed on the tree. I'd be very interested in seeing the output of oprofile while running your benchmark on X 1.4 and X 1.5. Please, remember to install the debuginfo packages for the X server, libcairo, and the geode driver. I haven't tried to run oprofile on the xo yet (it is on my todo list). If I remember well, ExaDoMoveOutPixmap (or a function with a similar name) and memcpy were always on top of sysprof profiles in rendering tests. riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Stability and Memory Pressure in 8.2
On Wed, 2008-09-10 at 09:15 +0200, Marco Pesenti Gritti wrote: On Wed, Sep 10, 2008 at 4:29 AM, Gary C Martin [EMAIL PROTECTED] wrote: OK, news is not great on the Activity front... SUMMARY: 759 vs 711 each Activity instance in 759 consumes an average of 1Mb more memory than the same Activity running in 711, with Write-57 reportedly taking significantly more than that (perhaps ~7Mb). Is top and/or ps memory usage calculated in the same way between these builds? Could make collecting real data pretty painful. Unfortunately not, there has been changes in the kernel. My understanding is that private memory will be the same, while calculation of shared memory has changed. Riccardo has a new kernel somewhere with instructions on how to install it on 711. That should make the memory usage comparable. Marco I used this newer kernel (as it accounts also for pss) for measurements with ps_mem on build 703: http://dev.laptop.org/~rlucchese/utils/703/kernel-2.6.25-20080501.3.olpc.231c7b715f4a8d0.i586.rpm It can be installed on the xo with: $ rpm -ivh kernel-rpm $ cp -a /boot/* /versions/boot/current/boot/ You will also have to update the ram disk image; you can follow the instructions at the bottom of http://wiki.laptop.org/go/Kernel_Building You may also want to try this patched ps_mem (shows pids and doesn't group entries by process name): http://dev.laptop.org/~rlucchese/utils/ps_mem.py riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Stability and Memory Pressure in 8.2
Paul, On Wed, 2008-09-10 at 08:18 -0400, [EMAIL PROTECTED] wrote: tomeu wrote: On Wed, Sep 10, 2008 at 2:05 PM, James Cameron [EMAIL PROTECTED] wrote: Has anyone got an idea of how to measure the heap by usage? Not from outside python, but from inside we are using heapy: http://guppy-pe.sourceforge.net/ i started down that path yesterday afternoon, and realized that it wasn't clear to me how i needed to invoke it. it seems to want to be imported before you start the rest of your program, which sort of forces you into interactive mode. is that your understanding? i had been hoping to be able to attach to the sugar shell process, in the way one might do with gdb. perhaps that's not possible. There is kick-start tutorial on how to use heapy's remote monitor at the 56th page of http://guppy-pe.sourceforge.net/heapy-thesis.pdf For the shell I use to put `import guppy.heapy.RM' before any other import statement in main.py. riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Stability and Memory Pressure in 8.2
On Tue, 2008-09-09 at 00:10 -0400, Michael Stone wrote: Dear devel@, Kim, Greg, and I have concluded that the instability we experience under memory-pressure in 8.2-759 and similar is the single hard issue that we wish to _attempt_ to address before releasing 8.2 on current timeframes. (We recognize that there are several other issues marked as blocking the release but we are confident that they will be resolved satisfactorily or are, in a few cases, beyond help.) Since most other aspects of the release seem to be running smoothly, Kim asked me to take a more direct role in organizing our efforts produce a release which avoids memory pressure when possible and which is better-behaved when it strikes. To that end, I would like to ask for your assistance with the following questions and tasks: * We need to determine why we encounter low-memory and out-of-memory situations more frequently than in previous releases. - This means that we need to measure how our memory consumption profile has changed since our previous releases. (cscott observes that we were unable to attack the F-9 image size issues until we were able to quantify the effect of changes we had made or were considering making. Consequently, he suggests that we will be unable to attack our current space consumption problems until we are able to generate good numbers (and displays).) - We need to think carefully about (or measure) whether our memory-consumption patterns have changed. I am particularly skeptical of our widespread use of tmpfsen since the pages consumed by files stored on tmpfsen are permanently dirty (and are perhaps accounted for differently than pages mapped into process' address spaces?) - We need to check the configuration of applications like Browse which have configurable caching behavior. (Search for cache or capacity in about:config; check for important compile-time configuration flags.) - We need to test in a variety of different network configurations in order to determine to what extent the network/presence environment affects memory consumption. * We need to check carefully for memory-leaks. Three mechanisms which occur to me include: 1) running the system for a period of time, then scanning for anomalies either manually or in some automated fashion from userland, kernel-land, or OFW (via SysRq or SMM). 2) setting rlimits various processes and noting what dies 3) using debugging tools like the python garbage collection module, guppy/heapy, gdb+macros, valgrind, efence, purify, etc. looking for trouble. * We need to find out why the oom-killer is not killing things fast enough. Based on our results, we might consider configuring /proc/$pid/oom_adj to preferentially kill some processes (e.g., the foreground [or background?] activities.) * We need to determine whether the oom-killer is killing the right processes. (sysctl's vm.oom_dump_tasks can be set to 1 in order to get more verbosity from the oom-killer when it fires). * We ought to ponder whether there are any additional dirty hacks we can experiment with in order to reduce memory consumption; for example, running the Shell and Journal (and DS?) in one process or making use of the compressed-caching code published on this list some months ago. * Random other stuff to think about: - rlimits, cgroups, and the memory resource controller - the warnings in the ramfs and tmpfs code about the deadlocks that tmpfsen can generate under low- or no-memory conditions. - whether our kernel overcommits when allocation requests are made? - whether we can get Browse to behave intelligently when it receives BadAlloc errors from X? - how to run bootchart on the XO - how to generate decent statistics and graphics (preferably in an automated fashion) concerning memory usage as part of our test suite - system-tap's kmalloc2.stp example In conclusion, more to come once I have some actual data; _please_ feel free to assist in collecting it! (though be aware that I may 'volunteer' you if I need your help. (That means you, Tomeu, Riccardo, Deepak, ...)). Regards, Michael There are some (trivial) tools (you may be interested in) I've written and used besides others to attack/study this issues: * picker [1] For me it was handier to use then bootchart; will also show per process mem usage. * imports timings and alloc statistics [2] Patch to python that prints timings and mem usage diffs for every imported module. Original timings patch is from Tomeu. * python-allocstatsmodule [3] Inspired by [2] but can be used inside python scripts to collect stats on heap usage
Re: Almost 50% less free memory in joyride-2302 compared with Update.1 (708)
On Sat, 2008-08-23 at 21:31 +1000, James Cameron wrote: On Sat, Aug 23, 2008 at 12:01:07PM +0200, Marco Pesenti Gritti wrote: On Fri, Aug 22, 2008 at 1:47 PM, James Cameron [EMAIL PROTECTED] wrote: ... Btw it's a shame that the python processes are grouped all together. I wonder if we can fix ps_mem to show them separately, with the full command. I agree. The attached patch makes ps_mem show the process cmdline instead of its name; it doesn't account for the /proc/[pid]/cmdline particular format but output it's well readable. riccardo --- ps_mem.orig 2008-07-22 08:00:58.0 +0200 +++ ps_mem 2008-08-25 10:01:35.0 +0200 @@ -117,14 +117,16 @@ return (Private, Shared) def getCmdName(pid): -cmd = file(/proc/%d/status % pid).readline()[6:-1] -exe = os.path.basename(os.path.realpath(/proc/%d/exe % pid)) -if exe.startswith(cmd): -cmd=exe #show non truncated version -#Note because we show the non truncated name -#one can have separated programs as follows: -#584.0 KiB + 1.0 MiB = 1.6 MiBmozilla-thunder (exe - bash) -# 56.0 MiB + 22.2 MiB = 78.2 MiBmozilla-thunderbird-bin +cmd = file(/proc/%d/cmdline % pid).readline()[:60] +if not len(cmd): +cmd = file(/proc/%d/status % pid).readline()[6:-1] +exe = os.path.basename(os.path.realpath(/proc/%d/exe % pid)) +if exe.startswith(cmd): +cmd=exe #show non truncated version +#Note because we show the non truncated name +#one can have separated programs as follows: +#584.0 KiB + 1.0 MiB = 1.6 MiBmozilla-thunder (exe - bash) +# 56.0 MiB + 22.2 MiB = 78.2 MiBmozilla-thunderbird-bin return cmd cmds={} ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Rainbow cpu load when launching an activity?
Hi Gary On Fri, 2008-08-15 at 23:18 +0100, Gary C Martin wrote: Hi Michael, On 15 Aug 2008, at 21:58, Michael Stone wrote: On Fri, Aug 15, 2008 at 07:31:28PM +0100, Gary C Martin wrote: I was curious to see (when testing in joyride-2301) that rainbow (python /usr/sbin/rainbow-daemon) seems to be the process that's eating the most CPU cycles during an activity launch. Well, rainbow does a little bit of work in order to make a new user, then it hands over control to the activity. Since we know that activity launching is already slow (hence the need for the module preloading hack), it's not very surprising to me to that you see it chewing CPU when launching activities. Feel free to profile, though; I'd certainly like to know it if I'm doing something truly idiotic. (Or if people are using rainbow in environments significantly different from my own.) Thanks, OK. I'm not exactly fully clued up on profiling such internals but I'll look at instrumenting interesting points of your rainbow source code on a running XO, and seeing if I have something useful to report. Please don't let that put off anyone else more qualified from looking. Processes spawned by rainbow get their cmdline copied over from rainbow's one. So I think what you are seeing is that the *launched activity* is taking more cpu time than the journal and the shell. The following graph shows browse startup (pid 3612): http://dev.laptop.org/~rlucchese/temp__browse_warm.svg riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Journal activity profiling
On Wed, 2008-08-13 at 18:02 +0200, Tomeu Vizoso wrote: On Wed, Aug 13, 2008 at 5:20 PM, riccardo [EMAIL PROTECTED] wrote: On Wed, 2008-08-13 at 12:13 +0200, Tomeu Vizoso wrote: On Tue, Aug 12, 2008 at 12:10 PM, riccardo [EMAIL PROTECTED] wrote: ... I find interesting to note that 28.5% of the total time goes to `get_date' of Journal.activity/misc.py because of the ngettext overhead. Perhaps translations could be cached ? Totally, but caching should already happen inside python's gettext: http://svn.python.org/view/python/tags/r251/Lib/gettext.py?rev=54864view=markup If that isn't working for any reason, we would need to cache it locally in sugar.util. Can you check it is slow in Spanish as well? You may have found a very nice low hanging fruit ;) I can see similar percentages with spanish (perù) translations ;) Note that only the comboboxes entries get translated, the timestamp gets always shown in english. Ouch, that's bad. What I think it's going on is that missing translations are not cached, so any missing translation will go all the way down again and again. We need to check why we are not picking up the translations. Can you enter a ticket for 8.2.0 and make it a blocker? Would be nice if you can already tell where's the problem - and a patch would be awesome ;) Translations seem to be cached to me; I think the point is that for every translation gettext.py searches new mo files. riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Journal activity profiling
On Wed, 2008-08-13 at 13:11 +0200, riccardo wrote: On Wed, 2008-08-13 at 12:13 +0200, Tomeu Vizoso wrote: On Tue, Aug 12, 2008 at 12:10 PM, riccardo [EMAIL PROTECTED] wrote: ... Yeah, we should be much smarter about that. Right now, we cache three screens worth of DS entries so we reduce the frequency with which we call the DS. But we redraw the whole screen at every scroll. Do you have any idea for redrawing less often? what do you mean ? mm the listview seems reasonably fast at drawing its entries, why so much defference ? thanks riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Datastore profiling
On Wed, 2008-08-13 at 11:41 +0200, Tomeu Vizoso wrote: ... It is updating the what combobox in the toolbar, see SearchToolbar.refresh_filters(). This of course could be optimized in the same way that the list view update is, by only refreshing once the journal comes visible again. To check if this is worth doing, I'd do manually the user action you are trying to make faster with and without refresh_filters() being called and would check if there's a significant difference. Commenting the call to refresh_filters() makes the journal take only around 3% of the cpu. ... We already have a cache for svg icons, but in this case s.g.combobox is using a gtk.CellRendererPixbuf which doesn't use s.g.icon. We should probably do our CellRenderer that uses s.g.icon, this would give us colored icons, badges, etc. Good catch! yeah, most of the time in refresh_filters() goes to icons rendering. Thanks, Tomeu ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Journal activity profiling
Hi! Testcase: Fill the journal with hundreds of entries and automate the GtkScrollWindow in the journal to scroll one entry at time on a timeout. Build: joyride-2281 + Macro investigation of cpu usage A picker graph taken during the test can be found at: http://dev.laptop.org/~rlucchese/journal_scrolling/journal_scrolling.picker.svg (http://dev.laptop.org/~rlucchese/journal_scrolling/journal_scrolling.picker) The following tab shows cpu usage of the 4 processes that took more cpu time during the sampling time: ($ grapher -c4 -n -r cpu -i journal_scrolling.picker) tot% ps% cmdline --- 68.2python /usr/bin/sugar-activity journalactivity... 88.6 20.4/usr/bin/X :0 -fp built-ins -wr ... 94.3 5.7 picker 99.5 5.2 python /usr/bin/datastore-service From the interactions with X it seems the journal activity spends a sensible amount of time redrawing its entries. The test runs slower when the journal has more entries than when it's almost empty, why is it ? + cProfile statistics (KCG format) for the journal activity: http://dev.laptop.org/~rlucchese/journal_scrolling/journal_scrolling.cProfile functions ordered by self-time: 17.2 gtk.main() 16.5 cairo.Context.paint() 4.find in gettext.py 3.9 set._jobject of Journal.activity/collapsedentry.py::228 2.9 built-in method do_size_allocate 2.9 _expand_lang gettext.py 2.8 join in posixpath.py 2.6 posix.stat() 2.1 _update_color of Journal.activity/collapsedentry.py 1.7 normalize in locale. py 1.6 exists in posix.path.py 1.5 set._jobject of Journal.activity/collapsedentry.py::323 -- 59.8% I find interesting to note that 28.5% of the total time goes to `get_date' of Journal.activity/misc.py because of the ngettext overhead. Perhaps translations could be cached ? + Sysprof statistics: http://dev.laptop.org/~rlucchese/journal_scrolling/journal_scrolling.sysprof Not very interesting this time. Thanks, riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Datastore profiling
On Sat, 2008-08-09 at 15:30 +0200, riccardo wrote: Hi, Testcase: Fill the datastore with `many small' objects. Build: 2266 ... + Sysprof statistics: http://dev.laptop.org/~rlucchese/datastore_fill/small_files__b2000.sysprof I can't see anything relevant for libxapian and it's bindings (xapian dbg packages were installed) Quite a bit of time goes to librsvg functions rendering svg icons to GtkPixbufs. Attaching strace to the journal activity and grepping open on its output gives: ... open(/usr/share/icons/sugar/scalable/mimetypes/text-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/image-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/audio-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/video-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/text-uri-list.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/text-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/image-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/audio-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/video-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 ... Does this come from sugar.mime or any sugar component ? If yes, would it be possible to share one icon-cache between all sugar modules ? I repeated the test to get cProfile statistics for the journal activity: http://dev.laptop.org/~rlucchese/datastore_fill/cProfile_journal_while_filling_ds 98.4% of the total time goes to __data_store_created_cb. Perhaps this function could only set a flag and delay data retrieval (from the DS) to the next time the journal's window is shown? Riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Datastore profiling
Hi, Testcase: Fill the datastore with `many small' objects. Build: 2266 The test was automated with the script at: http://dev.laptop.org/~rlucchese/datastore_fill/fill_ds For this test only the _TEST_SMALL_FILES flag was set in `fill_ds' and the following cmdline was used: $ fill_ds -s sources/ -b 2000 The `sources' dir I used can be found at: http://dev.laptop.org/~rlucchese/datastore_fill/sources/ Before running the script all entries in the datastore were deleted. + Macro investigation of cpu usage A picker graph taken during the test can be found at: http://dev.laptop.org/~rlucchese/datastore_fill/small_files__b2000.picker.svg (http://dev.laptop.org/~rlucchese/datastore_fill/small_files__b2000.picker) The following tab shows cpu usage of the 3 processes that took more cpu time during the sampling time: ($ grapher -c2 -n -r cpu -i small_files__b2000.picker) tot% ps% cmdline --- 55.0python /usr/bin/datastore-service 86.7 31.7python /usr/bin/sugar-activity journalactivity.JournalActivity - During the test the `favorites view' was shown and I think I was told the journal shouldn't take cpu time to update itself in this case. What is it doing than ? + Test log http://dev.laptop.org/~rlucchese/datastore_fill/small_files__b2000.log It took 123+ seconds to fill the datastore with 484 files (total size 20041624 bytes; files pushed to the datastore where text_s.txt, text_s.odt and img_s.jpg from the sources dir linked above). The 123s value is very stable when repeating the test. + cProfile statistics (KCG format) for the datastore: http://dev.laptop.org/~rlucchese/datastore_fill/small_files__b2000.cProfile * functions ordered by self-time: 23.8 posix.write 16.8 send_message of _dbus_bindings.Connection 9.6 _database_gen_allterms_iter of xapian.py 4.2 flush of secore/indexerconnection.py 2.6 add of secore/indexerconnection.py 2.3 cPickle.dumps 2.perform of secore/fieldactions.py 1.7 _act_index_freetext of secore/fieldactions.py 1.6 index of datastore/xapianindex.py 64.6% I/O performance and dbus are predominant in results. As I said, I'm not sure the journal should be so `active' during the test; in the case it would be more interesting to repeat the test after a fix. + Sysprof statistics: http://dev.laptop.org/~rlucchese/datastore_fill/small_files__b2000.sysprof I can't see anything relevant for libxapian and it's bindings (xapian dbg packages were installed) Quite a bit of time goes to librsvg functions rendering svg icons to GtkPixbufs. Attaching strace to the journal activity and grepping open on its output gives: ... open(/usr/share/icons/sugar/scalable/mimetypes/text-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/image-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/audio-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/video-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/text-uri-list.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/text-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/image-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/audio-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 open(/usr/share/icons/sugar/scalable/mimetypes/video-x-generic.svg, O_RDONLY|O_LARGEFILE) = 11 ... Does this come from sugar.mime or any sugar component ? If yes, would it be possible to share one icon-cache between all sugar modules ? Thanks, riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: sugar start-up profiling
On Thu, 2008-07-31 at 17:27 +0100, Tomeu Vizoso wrote: On Tue, Jul 29, 2008 at 3:15 PM, riccardo [EMAIL PROTECTED] wrote: Problem: sugar starts up slowly on the xo Tests were ran on an xo after a clean joyride-2181 install plus sucrose's activities. A graph of the ending part of the boot process can be found at: http://dev.laptop.org/~rlucchese/boot/boot.stats.svg (http://dev.laptop.org/~rlucchese/boot/boot.stats) It was obtained by running: $ picker -t 75 -o /tmp/boot.stats $ grapher -i boot.stats -c10 The sampling period begins in `start()' in haldaemon's init script and lasts 75 seconds. The following tab shows cpu usage of the 10 processes that took more cpu time during the sampling time: $ grapher -i boot.stats -c13 -r cpu tot% ps% cmdline --- 27.7/bin/sh /usr/bin/sugar 44.6 16.8jffs2_gcd_mtd0 51.7 7.1 /usr/bin/env python /usr/bin/sugar-activity journal... 56.2 4.5 python /usr/bin/datastore-service 60.6 4.4 picker -t75 -o /tmp/boot.stats 64.3 3.8 python /usr/sbin/rainbow-daemon --daemon 68.0 3.6 xinit /usr/bin/olpc-session -- /usr/bin/X -fp built-ins... 71.3 3.3 /bin/sh /usr/bin/olpc-session 74.1 2.8 python /usr/bin/sugar-shell-service 76.9 2.8 python /usr/bin/sugar-presence-service 79.7 2.8 python /usr/sbin/rainbow-daemon --daemon 81.2 1.5 hald 82.6 1.4 ohmd Renicing jffs2_gcd_mtd0 to 19 in haldaemon's init script slightly speeds-up the last part of the boot: $ cat /home/olpc/.boot_time.prev (clean joyride) 56.27 $ cat /home/olpc/.boot_time 54.14 Note however that when renicing jffs2_gcd_mtd0, boot timings `became less deterministic, sometimes being slower than the `clean install' case. Stopwatch timings (from boot loader to fully redrawn shell): clean install : 1m34.0s renice trick : 1m30.2s +[0. to 4.5 sec] Would it be possible to make DS, sugar-presence-service and sugar-shell-service system services and thus decoupling them from the shell's start-up? Don't think so, as they look to me as quite tied to the user session. What we should do (for 9.1.0) with the sugar-shell-service and the journal is to run them inside the shell process, saving memory and startup time. And we certainly shouldn't block when activating any services, they should be started asynchronously. The DS seems to me a good candidate for being decoupled from the shell's startup. A script was run that cat'ed all files (5700+) that sugar tries to open on boot. (http://dev.laptop.org/~rlucchese/boot/cat_sugar_startup_files) $ time sh cat_sugar_startup_files real 0m16.9s user 0m1.0s sys 0m12.2s Timings vary a lot when repeating the test (+-~30%). `top' shows that the remaining time goes to io-wait. Why don't those files get cached when repeating the test ? Interesting, anybody with kernel knowledge could comment on this? cProfile statistics (KCG format) for sugar-shell (start-up only): http://dev.laptop.org/~rlucchese/boot/cProfile-shell Functions ordered by self-time (%): 32.2 gtk.main() 19.6 send_message_with_reply_and_block of dbus 12.8 block of dbus.lowlevel.PendingCall 7.3 grab of sugar._sugarext.KeyGrabber 3._add_weight of sugar/shell/view/home/grid.py 2.7 render_cairo of rsvg.Handle 1.12 __getitem__ of sugar/shell/view/home/grid.py --- 78.7 % Perhaps some dbus calls can be made asynchronous; this is taking 30+% of start-up time. Yup. Mostly service activation, see above. It's curious that `grab` takes so much time: I don't see anything obvious looking at the code. Yeah, we should look at it, could be quite tasty low hanging fruit (7%). Note that the layout for the favorite's view was set to the ring type; why is the shell computing weights in this case? I guess that's for the mesh and friends view? Oh, right! +1 for changing the algorithm. High level tasks/functions ordered by total-time: 67.3 gtk.main() 33.6 __init__ of sugar/view/Shell.py 16.8 _start_journal_idle of sugar/view/Shell.py 11.6 __init__ shell/view/keyhandler.py 7.5 add sugar/shell/view/home/spreadlayout.py Note that 45% of Shell.__init__ and the 89% of _start_journal_idle went to blocking dbus calls. Just service activation, right? The datastore service and the journal will be profiled in separate sessions. Cool, that will be interesting as well. Nice job, in case startup time becomes a priority, we know now where to look at. Thanks, Tomeu riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: sugar start-up profiling
On Fri, 2008-08-01 at 10:41 -0400, Eben Eliason wrote: On Fri, Aug 1, 2008 at 10:29 AM, Erik Garrison [EMAIL PROTECTED] wrote: On Fri, Aug 01, 2008 at 10:19:50AM -0400, Eben Eliason wrote: Another potentially interesting solution is a pseudo-spring algorithm, by which we detect some numbers of neighbors (O(n)) and then we push those neighbors away with some force vector, the magnitude of which is weighted based on the size of the nodes, and the direction of which is calculated as the angle between them. This solution doesn't, in theory, yield results that are as good as the other options (since it pushes away at a fixed angle, instead of towards nearby positions with ow weights), but it should be really quick. I'm sure there are other options, or combinations of these, that we could explore as well. Could we be positioning icons on the basis of prior usage patterns? By this I mean that icons are spring'ed toward the XO icon with a force vector related to their recent usage patterns. Additionally, activities which are started at similar times could be spring'ed together. I'm envisioning a learning layout algorithm to distinguish the most-used activites. This layout necessitates the collection of usage data which could also be shared with our developers. This is a good point, and I have to say yes and no at the same time. I think your solution (I could be wrong!) is somewhat biased toward the particular case of the Home view, but this algo needs to work on the Groups and neighborhood views too. Perhaps there are some (non-historical) ways to compare data in those views, but I'm not sure. In any case, there is another variable I would like to propose, which is a suggested distance from the center of the screen -- or, if you'd like, a spring of a particular k value between the center of the screen and the object. My particular use case is that of search. I'd like to see a bunch of search results slide onto the screen (and non-results slide off), and I'd like it even more if the most relevant matches moved closest to the center. This is essential for scalability in the Groups and Neighborhood views. I could also see this working to bring frequently used activities to the center of the screen, and less frequently used ones to the edge (thought that interferes with free placement). I also see it making for an intuitive activity search in the favorites view. Even though only favorites are shown on screen by default, anytime a search is entered, the non-favorites (which, I propose, lay beyond the screen edges) which match can slide in, and non-matching favorites slide off, presenting this weighted view of matches. Clearing the entry, of course, returns the view to its natural state, with only favorites showing. What about doing collision detection with Box2D (fast, well maintained etc..) ? This would enable any of the layout discussed here (and funny animations when new icons are dropped in the layout ;). - Eben Erik riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
sugar start-up profiling
25.74 python /usr/bin/sugar-presence-service .. 81.2 2.8 53.86 21.13 python /usr/bin/sugar-shell-service .. 85.7 4.5 58.89 16.10 python /usr/bin/datastore-service .. 92.8 7.1 62.86 12.13 usr/bin/env python /usr/... (journal) Accurate shell's start-up timings were taken by instrumentation: ---first launch (normal boot)--- /usr/bin/sugar : (1217317352.992) -- 0. entering main() in shell/main.py: (1217317368.162) -- 15.2 before entering gtk's mainloop shell/main.py: (1217317375.464) -- 22.5 ---second launch (ctrl+alt+erase)--- /usr/bin/sugar : (1217317725.747) -- 0. entering main() in shell/main.py: (1217317734.939) -- 9.2 before entering gtk's mainloop shell/main.py: (1217317741.023) -- 15.3 The datastore service and the journal will be profiled in separate sessions. Thanks, riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Report on `views with many icons' profiling
On Tue, 2008-07-22 at 11:54 +0200, Tomeu Vizoso wrote: I think one can say that there's only one high-level operation: the call to _set_view in HomeBox.py; what happens as a consequence(/`parallel effect') is the firing of expose events and thus all the time that cProfile assigns to cairo and that sysprof shows in geode_drv.so. Expose is just the rendering of the cairo surface into the window. Do you know what proportion of the total time is expose? If I get it right the do_expose_event functions are taking 13.% of total time. While the function which is spending more time in cairo is do_paint_below_children of sugar/graphics/icon.py (27.6%). One thing I noted particularly is that 77% of the time of _set_view time goes to enable_xo_palette in sugar/view/home/favoritesview.py. It seems to me this last function is creating a new palette at every call (re-doing quite a bit of work scattered on various packages). I guess this can be done just once ? Yeah, _MyIcon.enable_palette() should just set a flag _palette_enabled to True. Then we should have a create_palette() method that creates the palette lazily when it is needed. Do you think this is worth doing in this release? Example: http://dev.laptop.org/git?p=sugar;a=commitdiff;h=960d90da474bb090c3905692e672301dab4cd515 For the ring layout case, all the rest looks ok to me or not worth optimizing. Can you please try to assess the impact to the user of any slowness we may have in there? --ring layout -- Perhaps we should ask the kids if they notice too much delay. I don't think so, this `transition' is much faster than those to other views. --freeform layout-- No need to ask ;) What about the mesh view? Have you seen any slowness there? You may need to connect to a jabber server in order to see enough icons. The mesh and group views use the same layout algo than the freeform view. Which are in your opinion the next steps we should take? - see if all the time in enable_xo_palette can be spared Think so, yeah. Good one. - use box2d for the freeform layout; I guess that any naive algorithm *handling* collision detection would perform worse than box2d and any non naive one (really handling collisions) isn't worth the time. Interesting, the current layout is a partial implementation of an algo devised by Eben. Would be good if he explained what the goals are on this regard and see which changes can be done that improve performance. I have some experience from when I was porting ODE to use ATLAS functions; it really is difficult to handle collision detection fastly. Thanks, Tomeu riccardo On Thu, Jul 17, 2008 at 7:43 PM, riccardo [EMAIL PROTECTED] wrote: Hi, Problem: slow switching between views with many icons Test-case: the test consist of switching between the favorites view and the list view. Test were ran once with the ring layout in the favorite view and once with the freeform layout; the xo had 25 activities installed all checked as `favorite'. The action of switching was automated with a timer with period 130ms when the ring layout was selected and 170ms in the case of the freeform layout (as the minimum values permitting complete redraw of the views). Note that there is a noticeable delay when switching to the favorites views when the selected layout is freeform. --- RING layout --- The following tab. and fig. show cpu time usage of the processes taking more cpu time while running the test: (tot% us+sy) - (partial% us+sy) : cmdline - 63.6 : python /usr/bin/sugar-shell 91.2- 27.5 : /usr/bin/X :0 -fp built-ins... 99.5- 8.2 : picker -t30 http://dev.laptop.org/~rlucchese/views/favorites_ring-list/picker.stats.svg (http://dev.laptop.org/~rlucchese/views/favorites_ring-list/picker.stats ) They were obtained by running: $ picker -t30 $ grapher -c3 --- FREEFORM layout --- (tot% us+sy) - (partial% us+sy) : cmdline - 82. : python /usr/bin/sugar-shell 91.6- 9.5 : /usr/bin/X :0 -fp built-ins... 99.4- 7.7 : picker -t30 http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/picker.stats.svg (http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/picker.stats ) ! sugar-shell is taking 20% more cpu time than in the ring layout case. cProfile statistics (KCacheGrind format) for sugar-shell: --- RING layout --- http://dev.laptop.org/~rlucchese/views/favorites_ring-list/cProfile-shell Ordering by function's self-time: % func name 35.6 : cairo.Context.paint 3.9: gtk.Container.add 2. : sugar.graphics.palette.do_paint_below_children 1.9: __setitem__ sugar.util -- 57% Well
automated tests
Hi, Is there already a facility for automated tests ? (tinderbox + some-X-tool ?) If yes - how does it works ? - what kind of situations can it handle ? When redoing a tests it's a bit of a nightmare to keep track of all changed files, or patch some of them opportunely to run the `old' test. Was this issue already addressed ? thanks, Riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: automated tests
On Tue, 2008-07-22 at 17:20 +0200, riccardo wrote: Hi, Is there already a facility for automated tests ? (tinderbox + some-X-tool ?) If yes - how does it works ? - what kind of situations can it handle ? When redoing a tests it's a bit of a nightmare to keep track of all changed files, or patch some of them opportunely to run the `old' test. Was this issue already addressed ? Sorry, here I meant if there is already a tool in use that helps with the previous point. thanks ! riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Report on `switching between activities and the journal'
Hi, Problem: switching between activities and the journal is slow Test-case: the test consist of starting Write and switching between it and the journal for a sensible amount of time. All tests were run on a xo; the journal had 50 entries. Switching was automated by calling shell.activate_next_activity() every ~730ms (as the minimum value at which both activities could get completely redrawn). Real transition timings differ from the timer's period value of 730ms. The `switch' journal - write takes an average of 735ms while the transition write - journal takes values from 1 to 2 seconds. During the test, activate_next_activity() in Shell.py was called 695 times. cpu usage data gathered with Picker (pid 2564 is the Write activity): tot% ps% cmdline --- 34.6 python /usr/bin/sugar-activity journalactivity ... 57.1 22.6 python /usr/sbin/rainbow-daemon --daemon ... [Write] 77.9 20.8 python /usr/bin/datastore-service 85.0 7.2 python /usr/bin/sugar-shell 91.5 6.5 /usr/bin/X :0 -fp built-ins -wr -auth ... 97.1 5.6 picker (http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/picker.stats) http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/picker.stats.svg They were obtained by running: $ picker $ grapher -c6 -r cpu The 22.6% took by Write is due to the activity saving and loading its state (taking screnshots, reading/writing files..) regardless it change or not (http://lists.laptop.org/pipermail/devel/2008-July/016722.html). The shell is taking the 7% of cpu-time; isn't it too much for this task? cProfile statistics (KCacheGrind format) for the journal: http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/cProfile-journalactivity The journal spends 69.4% of it's time in __refresh_idle_cb in listview.py. Ordering by function self-time: 29.7 : send_message_with_reply_and_block of dbus 15.7 : gtk.main() 10.9 : __init__ in activities/Journal.activity/palettes.py (2211 calls) 3.7 : cairo.Context.paint() 3.3 : __init__ sugar/graphics/palette.py Asynchronous dbus calls ? Perhaps icons and palettes could be cached ? cProfile statistics (KCacheGrind format) for Write: http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/cProfile-write Similar results were already commented at http://lists.laptop.org/pipermail/devel/2008-July/016722.html for a similar task. cProfile statistics (KCacheGrind format) for the datastore-service aren't much interesting this time (a separate test case should be designed for it): http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/cProfile-datastore cProfile statistics (KCacheGrind format) for sugar-shell: http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/cProfile-shell 51.3% of time in the shell is going to send_message_with_reply_and_block of dbus. I guess this is because of the calls to the activities's services; maybe some of them can be made asynchronous ? Other functions showing particularly up by self-time are: 20.8 : gtk.main() 4.1 : __init_ in sugar/graphics/icon.py (1509 calls) 2.9 : wnck.Window.activate() 2.1 : __init_ in sugar/graphics/palette.py (859 calls) Perhaps icons and palettes could be cached ? sysprof statistics: http://dev.laptop.org/~rlucchese/ActivitiesSwitching/journal-write/sysprof.data Similar results were already commented at http://lists.laptop.org/pipermail/devel/2008-July/016722.html for a similar task. Only one more thing I note particularly: 1. Python is spending a lot of time in the kernel. Too much reading/writing to the nand ? thanks, riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Report on `views with many icons' profiling
On Sat, 2008-07-19 at 11:49 +0200, Tomeu Vizoso wrote: This is really awesome, congrats. thanks ! I would like to know how much time takes every switch (including the redraw), is that 130ms and 170ms? Looks like it should be more to me. for the ring layout: favorite's view - list view : avg 0.15 sec list view - favorite's view : avg 0.15 sec for the freeform layout: favorite's view - list view : avg 0.16 sec list view - favorite's view : avg 0.85 sec In fact the 170ms value can be lowered but it makes very difficult to see whether both views are always redrawn or if sometimes one of the two is jumped (in the case of the freeform layout the screen is gray blank most of the time). Also, would like to see as well a top-down analysis, which are the top 3-5 high level operations that take most CPU? Are they executed more often than what would be strictly needed? I see in kcachegrind that _views_switch_...() was called 2481 times, this means that your script switched that many times? Yes, 2481 is the number of times the views were switched. I think one can say that there's only one high-level operation: the call to _set_view in HomeBox.py; what happens as a consequence(/`parallel effect') is the firing of expose events and thus all the time that cProfile assigns to cairo and that sysprof shows in geode_drv.so. One thing I noted particularly is that 77% of the time of _set_view time goes to enable_xo_palette in sugar/view/home/favoritesview.py. It seems to me this last function is creating a new palette at every call (re-doing quite a bit of work scattered on various packages). I guess this can be done just once ? For the ring layout case, all the rest looks ok to me or not worth optimizing. Can you please try to assess the impact to the user of any slowness we may have in there? --ring layout -- Perhaps we should ask the kids if they notice too much delay. I don't think so, this `transition' is much faster than those to other views. --freeform layout-- No need to ask ;) Which are in your opinion the next steps we should take? - see if all the time in enable_xo_palette can be spared - use box2d for the freeform layout; I guess that any naive algorithm *handling* collision detection would perform worse than box2d and any non naive one (really handling collisions) isn't worth the time. Thanks, Tomeu [Sorry about the late replies] :) thanks, riccardo On Thu, Jul 17, 2008 at 7:43 PM, riccardo [EMAIL PROTECTED] wrote: Hi, Problem: slow switching between views with many icons Test-case: the test consist of switching between the favorites view and the list view. Test were ran once with the ring layout in the favorite view and once with the freeform layout; the xo had 25 activities installed all checked as `favorite'. The action of switching was automated with a timer with period 130ms when the ring layout was selected and 170ms in the case of the freeform layout (as the minimum values permitting complete redraw of the views). Note that there is a noticeable delay when switching to the favorites views when the selected layout is freeform. --- RING layout --- The following tab. and fig. show cpu time usage of the processes taking more cpu time while running the test: (tot% us+sy) - (partial% us+sy) : cmdline - 63.6 : python /usr/bin/sugar-shell 91.2- 27.5 : /usr/bin/X :0 -fp built-ins... 99.5- 8.2 : picker -t30 http://dev.laptop.org/~rlucchese/views/favorites_ring-list/picker.stats.svg (http://dev.laptop.org/~rlucchese/views/favorites_ring-list/picker.stats ) They were obtained by running: $ picker -t30 $ grapher -c3 --- FREEFORM layout --- (tot% us+sy) - (partial% us+sy) : cmdline - 82. : python /usr/bin/sugar-shell 91.6- 9.5 : /usr/bin/X :0 -fp built-ins... 99.4- 7.7 : picker -t30 http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/picker.stats.svg (http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/picker.stats ) ! sugar-shell is taking 20% more cpu time than in the ring layout case. cProfile statistics (KCacheGrind format) for sugar-shell: --- RING layout --- http://dev.laptop.org/~rlucchese/views/favorites_ring-list/cProfile-shell Ordering by function's self-time: % func name 35.6 : cairo.Context.paint 3.9: gtk.Container.add 2. : sugar.graphics.palette.do_paint_below_children 1.9: __setitem__ sugar.util -- 57% Well, this isn't unexpected. But it's interesting when looking at sysprof results (below). --- FREEFORM layout --- http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/cProfile-shell Ordering by function's self-time: % func name 21.6 : _add_weight in sugar/shell/view/home/grid.py 21.5
Re: Report on `activities switching' profiling
On Wed, 2008-07-16 at 11:17 -0400, Eben Eliason wrote: On Wed, Jul 16, 2008 at 11:04 AM, riccardo [EMAIL PROTECTED] wrote: (so that it never ends up in the journal) every 1100. The 1100ms value was chosen after some testing as the minimum value (or very near to it) at which both activities are able to completely redraw their windows on switching without artifacts. If you could, it would also be useful to test out the quick tab behavior. While it's true that after a short delay (I forget the exact number of ms) the activities redraw their windows, the behavior is supposed to prevent this redraw as long as the tabbing events happen quickly enough, so that the redraw doesn't add latency when attempting to bypass several activities in a row. I'm not sure if this is actually working properly on the XOs. Sure, I let you know when I have some results. I guess some time can be gained by not doing the conversion Drawable - GdkPixbuf (sugar._sugarext.Preview.get_pixbuf) and perform the scaling and conversion directly on the first buffer. But IMHO the real problem is: ! Activities save their state and take previews continuously regardless of whether their state changed or not Yeah, this would indeed be a problem. This ticket -- http://dev.laptop.org/ticket/4365 -- deals with it to some extent, and a patch is present there, but it's been ignored for some time now. - Eben riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Report on `views with many icons' profiling
Hi, Problem: slow switching between views with many icons Test-case: the test consist of switching between the favorites view and the list view. Test were ran once with the ring layout in the favorite view and once with the freeform layout; the xo had 25 activities installed all checked as `favorite'. The action of switching was automated with a timer with period 130ms when the ring layout was selected and 170ms in the case of the freeform layout (as the minimum values permitting complete redraw of the views). Note that there is a noticeable delay when switching to the favorites views when the selected layout is freeform. --- RING layout --- The following tab. and fig. show cpu time usage of the processes taking more cpu time while running the test: (tot% us+sy) - (partial% us+sy) : cmdline - 63.6 : python /usr/bin/sugar-shell 91.2- 27.5 : /usr/bin/X :0 -fp built-ins... 99.5- 8.2 : picker -t30 http://dev.laptop.org/~rlucchese/views/favorites_ring-list/picker.stats.svg (http://dev.laptop.org/~rlucchese/views/favorites_ring-list/picker.stats ) They were obtained by running: $ picker -t30 $ grapher -c3 --- FREEFORM layout --- (tot% us+sy) - (partial% us+sy) : cmdline - 82. : python /usr/bin/sugar-shell 91.6- 9.5 : /usr/bin/X :0 -fp built-ins... 99.4- 7.7 : picker -t30 http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/picker.stats.svg (http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/picker.stats ) ! sugar-shell is taking 20% more cpu time than in the ring layout case. cProfile statistics (KCacheGrind format) for sugar-shell: --- RING layout --- http://dev.laptop.org/~rlucchese/views/favorites_ring-list/cProfile-shell Ordering by function's self-time: % func name 35.6 : cairo.Context.paint 3.9: gtk.Container.add 2. : sugar.graphics.palette.do_paint_below_children 1.9: __setitem__ sugar.util -- 57% Well, this isn't unexpected. But it's interesting when looking at sysprof results (below). --- FREEFORM layout --- http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/cProfile-shell Ordering by function's self-time: % func name 21.6 : _add_weight in sugar/shell/view/home/grid.py 21.5 : _remove_weight in sugar/shell/view/home/grid.py 10.6 : cairo.Context.paint 8.1: __setitem__ sugar.util 5.7: _compute_weight in sugar/shell/view/home/grid.py -- 57.5% ! Box2D would perform better ;) Sysprof results. Well, in sysprof there are many nested levels, so it is much more clear to just look at it. --- RING layout --- http://dev.laptop.org/~rlucchese/views/favorites_ring-list/sysprof.data - most of self-time is spent in the kernel and in X/X-modules. - time spent in the kernel is due to python and X, respectively 60%-40%. - time spent `in X' goes mostly to the geode driver, and then, to Xorg itself and the libexa module. --- FREEFORM layout --- http://dev.laptop.org/~rlucchese/views/favorites_freeform-list/sysprof.data Notes for the ring layout are valid also here. There are two (new) entries in this case and they are taking more time than the X geode module: python's numpy/core/multiarray.so and numpy/core/umath.so. This is in relation with the algorithm used in the freeform layout to avoid icons collisions. thanks, riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Re: Faster Launch of Activities
On Tue, 2008-07-15 at 11:47 +0200, riccardo wrote: On Tue, 2008-07-15 at 05:01 -0400, Greg Smith wrote: description? It would be useful to see a comparison of build 656 v 703 v 708 v latest joyride. That's a lot so just 703 (last release image) vs latest Joyride would the top priority. I'm not instrumenting the code but using a stopwatch so timings are a bit rough. The test: - reboot the machine - wait that jfss2_gcd_mtd0 finishes hogging the cpu (around 50 secs from when the shell is displayed) - go to the listview (*) - for every activity (one at time), from the drop menu-start and take the time until the full window redrawn - do it again from point (*) if you want to see the difference between first startup and 'warm' startup I also use to gather stats with Picker while doing the test, to see what processes are taking more cpu time; it also helps to catch conditions where activities are fully redrawn at time x but really are fully loaded at x+20sec (easy to see in etoys and browse). Are both first and second launch timings needed ? Michael, What is the latest version of Joyride that people should be testing? I re-read your status e-mail July 12 and didn't see it in there: http://lists.laptop.org/pipermail/devel/2008-July/016457.html I didn't click on all the links so let me know if I missed it somewhere. Could anybody confirm the following points please ? - builds numbers - if it's ok to take those timings as explained above thanks, riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
How to make files uploaded at d.l.o accessible for downloads by anybody ?
Hi, I'd like to have some files I uploaded at d.l.o accessible for downloads for anybody so that I can include links to them in reports send to the ml. How to do it ? ;) thanks, riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Report on `activities switching' profiling
Hi, Problem: switching between activities is noticeably too slow. Test-case: the test consist of starting Chat and Write and switching between them for a sensible amount of time. All tests were run on a xo. Switching was automated by patching sugar-shell to call shell.activate_next_activity() or shell.activate_previous_activity() (so that it never ends up in the journal) every 1100. The 1100ms value was chosen after some testing as the minimum value (or very near to it) at which both activities are able to completely redraw their windows on switching without artifacts. The following tab. and fig. show cpu time usage of the five processes taking more cpu time while running the test (the first two processes are chat and write). (tot% us+sy) - (partial% us+sy) : cmdline 28.9 - 28.9 : python /usr/sbin/rainbow-daemon --daemon 54.7 - 25.8 : python /usr/sbin/rainbow-daemon --daemon 66.5 - 11.7 : /usr/bin/X :0 -fp built-ins -wr -auth /home/olpc/.serverauth.1861 76.9 - 10.3 : python /usr/bin/datastore-service 85.3 - 8.4 : python /usr/bin/sugar-shell http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/stats.picker.p84.svg (http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/stats.picker) They were obtained by running: $ picker -t30 -f10 $ grapher -c5 ! 55% of cpu time goes to the activities, to do what? The two following files are cProfile statistics formatted to be viewed with KCacheGrind for the chat and write activity: http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/cProfile-chat http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/cProfile-write Ordering by function's self-time we have for chat: part% func name 17.3 : gtk.gdk.Pixbuf.scale_simple 13.6 : sugar._sugarext.Preview.get_pixbuf 10.4 : gtk.gdk.Pixbuf.save 6. : sugar._sugarext.Preview.take_screenshot -- 47.3% Values are almost the same for write. I guess some time can be gained by not doing the conversion Drawable - GdkPixbuf (sugar._sugarext.Preview.get_pixbuf) and perform the scaling and conversion directly on the first buffer. But IMHO the real problem is: ! Activities save their state and take previews continuously regardless of whether their state changed or not Next, cProfile statistics for the shell: http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/cProfile-shell Ordering by function self-time we have: part% func name 14.5 : set_message_with_reply_and_block of dbus 6.1 : cycle 6 2.58 : __init__ of sugar/graphics/palette.py cycle 6 1.65 : cairo.context.paint I don't understand what cycle 6 refers to (it appears also in the third entry); maybe Tomeu knows ? ;) Btw the shell is taking only the 8.4% of the total cpu time. There also cProfile statistics for the DS and the Journal but they are not very interesting this time: http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/cProfile-datastore http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/cProfile-journal The last tool we used is sysprof: http://dev.laptop.org/~rlucchese/ActivitiesSwitching/chat-write/stats.sysprof What it shows is somehow more difficult to comment on; I think is much more clear to just look at sysprof. Much time is spent in __PangoFontset_class_init-__do_global_ctors_aux; is this libpango or the python-pango bindings being 'reloaded' at every switch ? Next, `notable' thing is a memcpy in the xorg libfb module; all the screenshots ? libcairo doesn't seem to show up particularly. Did I miss something interesting in these tests ? Thanks, riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: How to make files uploaded at d.l.o accessible for downloads by anybody ?
On Wed, 2008-07-16 at 20:21 +0530, Sayamindu Dasgupta wrote: On Wed, Jul 16, 2008 at 8:19 PM, riccardo [EMAIL PROTECTED] wrote: Hi, I'd like to have some files I uploaded at d.l.o accessible for downloads for anybody so that I can include links to them in reports send to the ml. How to do it ? ;) thanks, riccardo Put the files in $HOME/public_html -hth- Sayamindu Thanks ! ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Faster Launch of Activities
On Mon, 2008-07-14 at 13:48 -0400, Chris Ball wrote: Hi, Let's get it on the roadmap for 9.1, when we've got time to actually make the fixes required and test them properly (unless someone really believes that speeding up sugar is a 4 line patch). I'd like to see an activity startup time comparison (just taken with a stopwatch) between 650, joyride before the new sugar shell but after rainbow prelaunch was added, and latest joyride. We should do this before we ship 8.2, and in future we should try to publish changes to activity startup time alongside patches that touch activity launch. I was planning on doing this measurement myself, but it's not getting to the top of my stack. Could I persuade someone else to volunteer? I already have them for one of the latest joyrides. For my work I normally take first start-up and second launch timings. I haven't yet checked whether rainbow is now started after X in the latest joyride or if this is coming soon in the next builds. Would make sense for you to have the same timings taken also after restarting rainbow ? I'm not familiar with builds changelogs since 650; let me know from which of them you'd like these timings. riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Re: Faster Launch of Activities
On Tue, 2008-07-15 at 05:01 -0400, Greg Smith wrote: description? It would be useful to see a comparison of build 656 v 703 v 708 v latest joyride. That's a lot so just 703 (last release image) vs latest Joyride would the top priority. I'm not instrumenting the code but using a stopwatch so timings are a bit rough. The test: - reboot the machine - wait that jfss2_gcd_mtd0 finishes hogging the cpu (around 50 secs from when the shell is displayed) - go to the listview (*) - for every activity (one at time), from the drop menu-start and take the time until the full window redrawn - do it again from point (*) if you want to see the difference between first startup and 'warm' startup I also use to gather stats with Picker while doing the test, to see what processes are taking more cpu time; it also helps to catch conditions where activities are fully redrawn at time x but really are fully loaded at x+20sec (easy to see in etoys and browse). Are both first and second launch timings needed ? Michael, What is the latest version of Joyride that people should be testing? I re-read your status e-mail July 12 and didn't see it in there: http://lists.laptop.org/pipermail/devel/2008-July/016457.html I didn't click on all the links so let me know if I missed it somewhere. thanks, riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Introduction to `picker' and git link
On Wed, Jul 9, 2008 at 11:05 AM, Tomeu Vizoso [EMAIL PROTECTED] wrote: On Wed, Jul 9, 2008 at 12:07 AM, Michael Stone [EMAIL PROTECTED] wrote: Perhaps you could modify the display so that each track is prominently labeled with the full arguments to the process? Yes, I'm curious to see the same graph with the process name as well as the full command. I pushed the fixes to the git tree. In fact cmdline texts already had to be there but I wasn't accounting for the bogus format of /proc/x/cmdline. Here is a new example boot trace (I lost the .picker file I used yesterday): wget http://www.bodhidharma.info/out.grapher.svg This was obtained with $ picker -t120 -f10 (again from sshd's init script) $ grapher -p80 I'm going to rearrange cmdline texts to make them easier to read ;) Thanks, riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
[project account request]
1. Project name :Picker 2. Existing website, if any : 3. One-line description :Lightweight system and processes statistics (cpu/mem/io) gatherer. 4. Longer description :Gathers system and processes statistics from /proc :and graphs them to pretty figures. : :It is useful to catch interactions between processes and study : cpu/mem/io usage of long running processes 5. URLs of similar projects :http://www.bootchart.org/ 6. Committer list Please list the maintainer (lead developer) as the first entry. Only list developers who need to be given accounts so that they can commit to your project's code repository, or push their own. There is no need to list non-committer developers. Username Full name SSH2 key URLE-mail - -- #1 riccardo Riccardo Lucchese riccardo.lucchese gmail.com #2 #3 ... If any developers don't have their SSH2 keys on the web, please attach them to the application e-mail. 7. Preferred development model [ ] Central tree. Every developer can push his changes directly to the project's git tree. This is the standard model that will be familiar to CVS and Subversion users, and that tends to work well for most projects. [X] Maintainer-owned tree. Every developer creates his own git tree, or multiple git trees. He periodically asks the maintainer to look at one or more of these trees, and merge changes into the maintainer-owned, main tree. This is the model used by the Linux kernel, and is well-suited to projects wishing to maintain a tighter control on code entering the main tree. If you choose the maintainer-owned tree model, but wish to set up some shared trees where all of your project's committers can commit directly, as might be the case with a discussion tree, or a tree for an individual feature, you may send us such a request by e-mail, and we will set up the tree for you. 8. Set up a project mailing list: [ ] Yes, named after our project name [ ] Yes, named __ [X] No When your project is just getting off the ground, we suggest you eschew a separate mailing list and instead keep discussion about your project on the main OLPC development list. This will give you more input and potentially attract more developers to your project; when the volume of messages related to your project reaches some critical mass, we can trivially create a separate mailing list for you. If you need multiple lists, let us know. We discourage having many mailing lists for smaller projects, as this tends to stunt the growth of your project community. You can always add more lists later. 9. Commit notifications [ ] Notification of commits to the main tree should be e-mailed to the list we chose to create above [ ] A separate mailing list, projectname-git, should be created for commit notifications [X] No commit notifications, please 10. Shell accounts As a general rule, we don't provide shell accounts to developers unless there's a demonstrated need. If you have one, please explain here, and list the usernames of the committers above needing shell access. I'd like being able to create personal git trees 11. Translation [X] Set up the laptop.org Pootle server to allow translation commits to be made [ ] Translation arrangements have already been made at ___ 12. Notes/comments: This project is part of my work as an intern at OLPC. Thanks, riccardo id_rsa.pub Description: Binary data ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: Project name: Picker is set up
Hi, There was a mistake on assigning the project. Thanks, riccardo On Tue, Jul 8, 2008 at 5:32 PM, Henry Edward Hardy [EMAIL PROTECTED] wrote: Tue, 8 Jul 2008 13:13:42 +0200, Riccardo Lucchese [EMAIL PROTECTED] wrote: 1. Project name: Picker Done. Your tree is here: git+ssh://[EMAIL PROTECTED]/git/activities/picker Please follow instructions here for importing your project: http://wiki.laptop.org/go/Importing_your_project Let us know if you have any problems with your tree. Happy hacking. Cheers, -- Henry Edward Hardy [EMAIL PROTECTED] ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Introduction to `picker' and git link
Hi, as part of my intern work on profiling sugar, I've written a little application for gathering system and per process statistic from /proc called. It may reveal itself useful in catching interferences between processes or when profiling cpu/mem usage of long running processes. In fact there are two executables, picker and grapher. For my purposes picker is run on the xo and grapher on a pc to output pretty figures from the statistics blob generated by the first. An example figure can be found at: (it's quite big; better not to open it in a browser) wget http://www.bodhidharma.info/out.grapher.svg This figure shows the xo boot (starting from start() in sshd's init script) and lasts for 120sec (the sampling rate is 10Hz); the figure was generated by only showing the processes with higher cpu-time and that took up to 75% of the total cpu-time taken by all processes running on the xo for the `picking' time. In the future grapher may be extended to show more info, and maybe integrate timed sugar debug logs. Git tree is at: git+ssh://[EMAIL PROTECTED]/git/activities/picker Both executables take the -h option. Questions, hints, requests or bug reports .. I appreciate them all ;) Thanks, riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
intern project on profiling sugar
Hi I'm riccardo lucchese (rl) and will be an intern at olpc for the next ten weeks. My initial proposal for the internship was working on profiling sugar. i.e. why is activities startup so long ? ;) Right now I'm working on a tool for gathering cpu/mem/io statistics on the xo that produces pretty figures like bootchart does (http://www.bootchart.org/images/bootchart.png); the problem with bootchart was that it is quite heavyweight at decent sampling frequencies. This tool will be used for profiling activities startup and other actions suffering of long delaying. It is almost finished. With the same goal I'm writing a script that extracts perfs timings from data logged by sugar components so that it will be possible to run automated `regression' tests in the future. These tools will be used with other common profiling tools like the embedded python profiler, sysprof and oprofile. I was told that some of you have already specifically worked on this; that would be great if you could share your gotchas ;) I appreciate any hints on features those tools should have and any comments on this work! Thanks ! riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel
Re: intern project on profiling sugar
On Fri, Jul 4, 2008 at 11:04 AM, Martin Dengler [EMAIL PROTECTED] wrote: On Fri, Jul 04, 2008 at 08:56:34AM +0200, Riccardo Lucchese wrote: Hi I'm riccardo lucchese (rl) and will be an intern at olpc for the next ten weeks. My initial proposal for the internship was working on profiling sugar. i.e. why is activities startup so long ? ;) [...] I was told that some of you have already specifically worked on this; that would be great if you could share your gotchas ;) http://dev.laptop.org/ticket/5228 http://dev.laptop.org/ticket/5452 http://dev.laptop.org/ticket/4349 http://dev.laptop.org/ticket/7212 yeah, exactly ;) Martin Thanks ! riccardo ___ Devel mailing list Devel@lists.laptop.org http://lists.laptop.org/listinfo/devel