[Kolab-devel] High CPU load and disk access

[Jeroen van Meeuwen (Kolab Systems)]

On 2013-01-23 12:16, Stefan Froehlich wrote:
> On 23/01/2013 10:02 PM, Jeroen van Meeuwen (Kolab Systems) wrote:
>> I think what we want to learn is what the kolab daemon is doing;
>> 
>>     # service kolab-server stop
>>     # kolabd -d 9 2>&1 | tee kolabd.log
>> 
>> Let this run for a few seconds/minutes, until you see exactly the 
>> same
>> symptoms (prolonged, continuous CPU and Disk I/O that shouldn't 
>> really
>> occur because nothing else is happening), and abort the kolabd -d 9 
>> run.
>> 
>> kolabd.log should now contain a step-by-step description of what's
>> going on. You can examine this file yourself and see if something
>> obvious pops out, or strip out the sensitive information and ship it
>> over to me (in private).
>> 
> Hi Jeroen,
> 
> the CPU load happens instantly after starting kolab-server or your
> kolabd -d 9 ...
> 

There's "always" a bit of CPU load as the daemon starts its initial 
synchronization.

What it does is as follows:

- From /var/lib/kolab/<domain>.db, a sqlite3 database, it gets the 
latest 'last_change' in order to see what it knows was the last change 
in the LDAP tree it had a successful run for. In the log file you 
provided me with, I recognize this is a modifytimestamp of some time 
today, 20130123.

- It uses that timestamp to create a persistent search, attempting to 
only get an initial result set of "recent" changes (i.e. the search 
includes modifytimestamp>=latest_known_change).

- It is very likely it will find some entries, and the daemon will 
therefore loop through a couple of entries - causing the initial CPU 
load.

- While it is looping through the entries, it will apply the quota 
policy, it will apply the recipient policy, potentially resulting in a 
list of modifications to be applied to the entry. Each of such 
modifications will (naturally) apply an additional change notification 
from LDAP to the daemon.

- After a while, it should find itself idling, as no further changes in 
the LDAP tree cause the daemon to react upon them.

> I cannot see anything obvious despite the fact that it seems to check
> something with only the first user out of my two user setup. So here
> you are.
> 

Well, here's the cause:

Look at the lines that mention "modify_ext" - you'll recognize that 
most if not all of the modify_ext are being executed against the same 
LDAP object.

When I look at what is being modified exactly, I reckon I see the same 
list of values for the same attribute sorted in different ways.

Kind regards,

Jeroen van Meeuwen

-- 
Systems Architect, Kolab Systems AG

e: vanmeeuwen at kolabsys.com
m: +44 74 2516 3817
w: http://www.kolabsys.com

pgp: 9342 BF08