Evolution Data Server Under Sysprof

June 4, 2008

My gsoc task is to speed up calendar part of e-d-s. These days I have been using  evo calendar extensively. My aim was to identify the most serious bottlenecks by sysprof.

Here are the results of my 5 minute session. The tests were carried out on big calendars, which I received from Federico.

Sysprof analysis of evolution data server

Several things should be noticed:

  • Almost all system time is divided between Evo and Firefox
  • About 30% of system time was spent in Evolution, 15% in e-d-s.
  • I was using only file backend (e-d-s time was spent in e_cal_backend_file_start_query 14%)

Analysis:

  • Almost all e-d-s time was spent in e_cal_backend_start_query – 14%. This method is called by e-d-s clients (Evolution, clocks…) and does complete sweep  through the calendar. Clients want to get back calendar objects filtered by some expression (sexp).
  • For every calendar object, test against the expression is carried out (e_cal_backend_sexp_match_comp – 11%),  generating all recurrences.  Usually, the evaluation of expression leads to test, if event occurs in some time range (func_occur_in_time_range – 6%). The second very often used function seems to be  e_cal_backend_sexp_func_make_time – 3.9%. Both  these functions sooner or later call function icaltime_as_timet_with_zone, in which is spent 3.60% and 3.13% – summing up to about 6.7% of system time. In fact, these functions are usually called together, because the typical test is “occur-in-time-range? (make-time \”ISO_DATE_STR\”) (make-time \”ISO_DATE_STR\”)”. The expression  make-time “ISO_DATE_STR” leads to calling e_cal_backend_sexp_func_make_time, which converts date from iso string to time_t value. Expression occur-in-time-range leads to calling func_occur_in_time_range.
  • When constructing expression “occur-in-time-range? (make-time \”ISO_DATE_STR\”) (make-time \”ISO_DATE_STR\”)”, time_t value is converted to the string. Later, when evaluating expression, string is converted to time_t (by make-time).

Time spent in converting time formatsTime spent in converting time formats

Conclusions:

  • In e-d-s we spent about 15% of system time, and almost 7% was spent in icaltime_as_timet_with_zone. The function is called to find out, if calendar event occurs in some time range.  There is a lot of time conversion from time_t to string and back.  The rest was spent by sweeping through the calendar objects and generating recurrences.
Advertisements

2 Responses to “Evolution Data Server Under Sysprof”

  1. Dave Richards said

    I can give you some monster calendars for testing. Please hit me up on #evolution on the IRC. My account is dave_largo.

  2. r said

    So is icaltime_as_timet_with_zone too slow or called too many times?
    I was profiling some Java code the other day and it said that most time was spent in MyObject.compareTo(). Fairly difficult to make that function much faster, but it was possible to stop it being called O(n^2) times. Looking forward to next post.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: