Datastore profiling

[riccardo]

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 20000000

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__b20000000.picker.svg
(http://dev.laptop.org/~rlucchese/datastore_fill/small_files__b20000000.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__b20000000.picker)
  
 tot%	ps%	cmdline
 -----------------------
   	55.0	python /usr/bin/datastore-service
 86.7	31.7	python /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__b20000000.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__b20000000.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__b20000000.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