Page MenuHomePhorge
Create Task
Maniphest T1988

wallace fails to check if resource reservation requests conflicts with any of resource events
Closed, WontfixPublic
Actions

Description

I've been observing wallace allocating 100% of CPU. After doing some debuging it looks like the problem occurs when wallace tries to determine if there is any conflicts between resource events and reservation conflict.

2016-11-22 14:37:42,102 pykolab.wallace DEBUG [20846]: iTip event conflict checked for 145 on shared/Resources/Besprechungsraum 2-42-F1@domain
2016-11-22 14:37:42,102 pykolab.wallace DEBUG [20846]: Fetching message UID '146' from folder 'shared/Resources/Besprechungsraum 2-42-F1@domain'
2016-11-22 14:37:42,150 pykolab.wallace DEBUG [20846]: * Comparing events 2016-11-24 13:30:00+01:00/2016-11-24 14:30:00+01:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,151 pykolab.wallace DEBUG [20846]: iTip event conflict checked for 146 on shared/Resources/Besprechungsraum 2-42-F1@domain
2016-11-22 14:37:42,151 pykolab.wallace DEBUG [20846]: Fetching message UID '147' from folder 'shared/Resources/Besprechungsraum 2-42-F1@domain'
2016-11-22 14:37:42,196 pykolab.wallace DEBUG [20846]: * Comparing events 2016-11-10 14:30:00+01:00/2016-11-10 15:30:00+01:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,196 pykolab.wallace DEBUG [20846]: iTip event conflict checked for 147 on shared/Resources/Besprechungsraum 2-42-F1@domain
2016-11-22 14:37:42,197 pykolab.wallace DEBUG [20846]: Fetching message UID '148' from folder 'shared/Resources/Besprechungsraum 2-42-F1@domain'
2016-11-22 14:37:42,220 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-12 10:00:00+02:00/2016-09-12 11:00:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,240 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-19 10:00:00+02:00/2016-09-19 11:00:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,259 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,276 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,291 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,306 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,320 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,334 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,347 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,360 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,372 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,385 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,398 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00
2016-11-22 14:37:42,410 pykolab.wallace DEBUG [20846]: * Comparing events 2016-09-26 09:00:00+02:00/2016-09-26 09:30:00+02:00 with 2016-11-29 11:00:00+01:00/2016-11-29 12:00:00+01:00

and the last line goes forever. It looks like event conflict checking gets into endless loop. The logs I pasted here I got by uncommenting line ~176, in pykolab/itip/__init__.py, def check_event_conflict(kolab_event, itip_event): method.

The most relevant part of the offending message (148 (or 2564)) has this content (most relevant).

<components>
  <vevent>
    <properties>
      <uid>
        <text>3C93514BA89A1BCC38DA740341DF8D74-EBE2BB8E57A31106</text>
      </uid>
      <created>
        <date-time>2016-09-05T14:33:12Z</date-time>
      </created>
      <dtstamp>
        <date-time>2016-09-05T14:33:11Z</date-time>
      </dtstamp>
      <sequence>
        <integer>0</integer>
      </sequence>
      <class>
        <text>PUBLIC</text>
      </class>
      <dtstart>
        <parameters>
          <tzid>
            <text>/kolab.org/Europe/Berlin</text>
          </tzid>
        </parameters>
        <date-time>2016-09-12T10:00:00</date-time>
      </dtstart>
      <dtend>
        <parameters>
          <tzid>
            <text>/kolab.org/Europe/Berlin</text>
          </tzid>
        </parameters>
        <date-time>2016-09-12T11:00:00</date-time>
      </dtend>
      <rrule>
        <recur>
          <freq>WEEKLY</freq>
          <byday>MO</byday>
        </recur>
      </rrule>
      <summary>
        <text>Enterprise Meeting</text>
      </summary>

can present full payload of the event upon request.
Removing the message from resource makes wallace work again (after restart it doesn't take 100% of CPU anymore).
pykolab 0.7.30-0~kolab1
wallace 0.7.30-0~kolab1

Details

Ticket Type
Task

Revisions and Commits

rP pykolab
AbandonedD308 T1988: Fix performance issue in check_event_conflict()

Related Objects

Event Timeline

adomaitis created this task.Nov 22 2016, 2:10 PM
adomaitis added a project: PyKolab.
machniak subscribed.Nov 24 2016, 12:14 PM

It is not infinite. It is just so extremally slow... For two weekly recurring events it does around 10 * 50 * 10 * 50 iterations. And every iteration calls getLastOccurrence(), getOccurenceEndDate(), etc. on EventCal (from kolab.calendaring). Looks like these are slow.

There's already "# TODO: compare recurrence rules directly (e.g. matching time slot or weekday or monthday)" in the code. I suppose another solution would be to collect all occurrences of both events in one (optimized) run and then compare them. Or limit the inner loop to only relevant date period.

adomaitis added a comment.Nov 24 2016, 12:25 PM
In T1988#30665, @machniak wrote:

It is not infinite. It is just so extremally slow... For two weekly recurring events it does around 10 * 50 * 10 * 50 iterations. And every iteration calls getLastOccurrence(), getOccurenceEndDate(), etc. on EventCal (from kolab.calendaring). Looks like these are slow.

Could be, just leaving wallace running at 100% CPU for few days and don't get a result looks like infinite.

There's already "# TODO: compare recurrence rules directly (e.g. matching time slot or weekday or monthday)" in the code. I suppose another solution would be to collect all occurrences of both events in one (optimized) run and then compare them. Or limit the inner loop to only relevant date period.

I'm not sure what is the best. I would vote for a solution which is easiest and could be implemented ASAP, and leave another TODO if it could be done better code review iteration.

machniak added a revision: D308: T1988: Fix performance issue in check_event_conflict().Nov 24 2016, 1:12 PM
machniak added a comment.Nov 24 2016, 1:14 PM

D308 is a little bit hacky (and may not find all conflicts), but works. And the old method wasn't perfect anyway.

vanmeeuwen subscribed.Dec 2 2016, 10:42 AM

D308 isn't the proper solution to these symptoms.

vanmeeuwen mentioned this in rP3337283f0784: No conflict needs to be detected if the incoming iTip is a transparent event….Dec 2 2016, 2:14 PM
vanmeeuwen mentioned this in rPaf4cdb83103f: If neither the existing kolab event nor the incoming iTip event have any….
vanmeeuwen mentioned this in rP0970d410e9e8: Vastly improve the speed of conflict detection between recurring events (with….
vanmeeuwen mentioned this in rPfb25a9cd4ad2: No conflict needs to be detected if the incoming iTip is a transparent event….
vanmeeuwen mentioned this in rP86fec9648fc4: If neither the existing kolab event nor the incoming iTip event have any….
vanmeeuwen mentioned this in rP893fcf1d2d65: Vastly improve the speed of conflict detection between recurring events (with….
vanmeeuwen closed this task as Resolved.Dec 2 2016, 2:17 PM
vanmeeuwen claimed this task.
vanmeeuwen moved this task from Backlog to Done on the PyKolab board.

Resolved per the aforementioned commits.

vanmeeuwen mentioned this in T1525: Postfix LDAP timed out on clean centos7 installation.Dec 2 2016, 2:18 PM
machniak reopened this task as Open.Dec 3 2016, 12:23 PM

@vanmeeuwen, The issue is fixed, but two tests fail now:

======================================================================
FAIL: test_002_check_event_conflict
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 134, in maybeDeferred
    result = f(*args, **kw)
  File "/usr/lib64/python2.7/site-packages/twisted/internet/utils.py", line 191, in runWithWarningsSuppressed
    result = f(*a, **kw)
  File "/root/pykolab/tests/unit/test-011-itip.py", line 450, in test_002_check_event_conflict
    self.assertTrue(itip.check_event_conflict(event3, itip_event), "Conflict in two recurring events")
  File "/usr/lib64/python2.7/site-packages/twisted/trial/unittest.py", line 224, in failUnless
    raise self.failureException(msg)
FailTest: Conflict in two recurring events

======================================================================
FAIL: test_002_check_event_conflict_single
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/twisted/internet/defer.py", line 134, in maybeDeferred
    result = f(*args, **kw)
  File "/usr/lib64/python2.7/site-packages/twisted/internet/utils.py", line 191, in runWithWarningsSuppressed
    result = f(*a, **kw)
  File "/root/pykolab/tests/unit/test-011-itip.py", line 499, in test_002_check_event_conflict_single
    self.assertTrue(itip.check_event_conflict(event, itip_event), "Conflicting dates (exception)")
  File "/usr/lib64/python2.7/site-packages/twisted/trial/unittest.py", line 224, in failUnless
    raise self.failureException(msg)
FailTest: Conflicting dates (exception)
----------------------------------------------------------------------
pasik subscribed.Nov 25 2017, 1:33 PM
machniak moved this task from Done to Backlog on the PyKolab board.Jul 27 2018, 6:54 AM
vanmeeuwen closed this task as Wontfix.Mar 22 2019, 11:26 AM

It doesn't seem like there's any actual errors in reality.

Diffusion mentioned this in rPa5579210e750: Ensure that we have not reintroduced the performance problem of T1988.Aug 29 2022, 11:23 AM