View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0005943SOGoBackend Calendarpublic2024-03-19 10:322024-12-17 17:49
Reportereugenesu Assigned Tosebastien  
PriorityhighSeveritycrashReproducibilityalways
Status feedbackResolutionopen 
Product Version5.10.0 
Summary0005943: Excessive memory usage when creating a recurring event
Description

When creating a recurring event (for example, every day for a year), excessively high memory utilization occurs (often gigabytes when processing one event).
Example from logs:

''Mar 18 12:09:34 sogod [6200]: <0x0x60533f454b80[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Mar 18 12:09:34 sogod [6200]: <0x0x60533f454b80[SOGoCache]> Using host(s) '10.20.30.1:11211' as server(s)
Mar 18 12:09:34 sogod [6200]: 10.20.30.1 "PROPFIND /SOGo/dav/gu_use_te_10%40domain.local/Calendar/personal/ HTTP/1.1" 401 0/164 0.372 - - 5M - 14
Mar 18 12:09:35 sogod [6200]: <0x0x60533f5ead10[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Mar 18 12:09:35 sogod [6200]: <0x0x60533f5ead10[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Mar 18 12:09:35 sogod [6200]: <0x0x60533f5ead10[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
Mar 18 12:09:35 sogod [6200]: 10.20.30.1 "PROPFIND /SOGo/dav/gu_use_te_10%40domain.local/Calendar/personal/ HTTP/1.1" 207 379/164 0.434 - - 3M - 16
Mar 18 12:09:35 sogod [6200]: 10.20.30.1 "PROPFIND /SOGo/dav/gu_use_te_10@domain.local HTTP/1.1" 207 400/159 0.002 - - 0 - 15
Mar 18 12:09:35 sogod [6200]: 10.20.30.1 "PROPFIND /SOGo/dav/gu_use_te_10%40domain.local/Calendar/ HTTP/1.1" 207 417/170 0.006 1692 75% 916K - 15
Mar 18 12:09:42 sogod [6200]: 10.20.30.1 "PUT /SOGo/dav/gu_use_te_10%40domain.local/Calendar/personal/3d53588a-e507-11ee-9d4e-080027707a36.ics HTTP/1.1" 201 0/1964 7.657 - - 427M - 16
Mar 18 12:09:42 sogod [6200]: |SOGo| terminating app, vMem size limit (384 MB) has been reached (currently 531 MB)
2024-03-18 12:09:42.859 sogod[6199:6199] INFO(-[NGActiveSocket isAlive]) poll(): fd=8 revents=0x0011)
Mar 18 12:09:42 sogod [6199]: <0x0x60533f1e7550[WOWatchDogChild]> child 6200 exited
Mar 18 12:09:42 sogod [6199]: <0x0x60533f13e990[WOWatchDog]> child spawned with pid 6220''

With each new repeating event on the same day, memory consumption increases exponentially.

''Mar 18 13:43:02 sogod [6822]: <0x0x5de27721e270[SOGoCache]> Cache cleanup interval set every 300.000000 seconds
Mar 18 13:43:02 sogod [6822]: <0x0x5de27721e270[SOGoCache]> Using host(s) '10.20.30.1:11211' as server(s)
Mar 18 13:43:02 sogod [6822]: 10.20.30.1 "PROPFIND /SOGo/dav/gu_use_te_10%40domain.local/Calendar/personal/ HTTP/1.1" 401 0/164 0.047 - - 3M - 14
Mar 18 13:43:02 sogod [6822]: <0x0x5de2772b1950[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table
Mar 18 13:43:02 sogod [6822]: <0x0x5de2772b1950[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table
Mar 18 13:43:02 sogod [6822]: <0x0x5de2772b1950[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table
Mar 18 13:43:02 sogod [6822]: 10.20.30.1 "PROPFIND /SOGo/dav/gu_use_te_10%40domain.local/Calendar/personal/ HTTP/1.1" 207 379/164 0.107 - - 3M - 16
Mar 18 13:43:02 sogod [6822]: 10.20.30.1 "PROPFIND /SOGo/dav/gu_use_te_10@domain.local HTTP/1.1" 207 400/159 0.002 - - 0 - 15
Mar 18 13:43:02 sogod [6822]: 10.20.30.1 "PROPFIND /SOGo/dav/gu_use_te_10%40domain.local/Calendar/ HTTP/1.1" 207 417/170 0.005 1692 75% 0 - 15
Mar 18 13:43:10 sogod [6822]: [ERROR] <0x5de2a94ec4c0[SOGoAppointmentObject]:4b84846c-e514-11ee-9d4e-080027707a36.ics> Did not find folder of content object.
Mar 18 13:43:10 sogod [6822]: [ERROR] <0x5de2a94a4b30[SOGoAppointmentObject]:4b84846c-e514-11ee-9d4e-080027707a36.ics> Did not find folder of content object.
Mar 18 13:43:10 sogod [6822]: [ERROR] <0x5de2a98533c0[SOGoAppointmentObject]:4b84846c-e514-11ee-9d4e-080027707a36.ics> Did not find folder of content object.
Mar 18 13:43:10 sogod [6822]: [ERROR] <0x5de2a98713d0[SOGoAppointmentObject]:4b84846c-e514-11ee-9d4e-080027707a36.ics> Did not find folder of content object.
Mar 18 13:43:14 sogod [6822]: 10.20.30.1 "PUT /SOGo/dav/gu_use_te_10%40domain.local/Calendar/personal/4b84846c-e514-11ee-9d4e-080027707a36.ics HTTP/1.1" 201 0/1964 11.992 - - 938M - 16
Mar 18 13:43:14 sogod [6822]: |SOGo| terminating app, vMem size limit (384 MB) has been reached (currently 1035 MB)
2024-03-18 13:43:14.478 sogod[6460:6460] INFO(-[NGActiveSocket isAlive]) poll(): fd=9 revents=0x0011)
Mar 18 13:43:14 sogod [6460]: <0x0x5de27701e0f0[WOWatchDogChild]> child 6822 exited
Mar 18 13:43:14 sogod [6460]: <0x0x5de276f07a20[WOWatchDog]> child spawned with pid 6840''

Presumably, memory consumption occurs when processing a response to a query to the database.

''SELECT b.c_content,a.c_partmails,a.c_partstates,a.c_isopaque,a.c_status,a.c_cycleinfo,a.c_orgmail,b.c_name,a.c_uid,a.c_startdate,a.c_enddate,a.c_isallday FROM sogo_quick_appointment a, sogo_store b WHERE (a.c_folder_id = 6 AND b.c_folder_id = 6) AND ((c_component = 'vevent') AND ((c_startdate IS NULL) OR (c_startdate <= 1742280851)) AND ((c_cycleenddate IS NULL) OR (c_cycleenddate >= 1710743653)) AND (c_iscycle = 1)) AND a.c_name = b.c_name AND (c_deleted != 1 OR c_deleted IS NULL)''

Increasing the memory limit for workers (SxVMemLimit) does not solve the problem.

Steps To Reproduce
  • Create a recurring event with 3-5 recipients on one SOGo server.
  • Add 4-6 more similar events on the same days, but with different times (intersection in time is not necessary). An event validity period of 1 year is sufficient.
  • After creating 5-6 (or more) repeating events, SOGo WatchDog kills the process due to high memory utilization.
Additional Information

Example ICS.

''BEGIN:VCALENDAR
VERSION:2.0
BEGIN:VTIMEZONE
TZID:Europe/Moscow
LAST-MODIFIED:20240220T101645Z
X-LIC-LOCATION:Europe/Moscow
BEGIN:STANDARD
TZNAME:MSK
TZOFFSETFROM:+0300
TZOFFSETTO:+0300
DTSTART:19700101T000000
END:STANDARD
END:VTIMEZONE
BEGIN:VEVENT
SUMMARY:Memory leak recurrent appointment
DTSTART;TZID=Europe/Moscow:20240318T143525
DTEND;TZID=Europe/Moscow:20240318T145525
DTSTAMP;TZID=Europe/Moscow:20240318T140525
UID:6c0388f2-e517-11ee-9d4e-080027707a36
RRULE:FREQ=DAILY;UNTIL=20250112T143525
ATTENDEE;PARTSTAT=NEEDS-ACTION;CN=Test User;RSVP=TRUE;ROLE=REQ-PARTICIPANT
:MAILTO:gu_use_te_01@domain.local
ATTENDEE;PARTSTAT=NEEDS-ACTION;CN=Test User 02;RSVP=TRUE;ROLE=REQ-PARTICIP
ANT:MAILTO:gu_use_te_02@domain.local
ATTENDEE;PARTSTAT=NEEDS-ACTION;CN=Test User 03;RSVP=TRUE;ROLE=REQ-PARTICIP
ANT:MAILTO:gu_use_te_03@domain.local
ATTENDEE;PARTSTAT=NEEDS-ACTION;CN=Test User 04;RSVP=TRUE;ROLE=REQ-PARTICIP
ANT:MAILTO:gu_use_te_04@domain.local
ATTENDEE;PARTSTAT=NEEDS-ACTION;CN=Test User 05;RSVP=TRUE;ROLE=REQ-PARTICIP
ANT:MAILTO:gu_use_te_05@domain.local
ATTENDEE;PARTSTAT=NEEDS-ACTION;CN=Test User 06;RSVP=TRUE;ROLE=REQ-PARTICIP
ANT:MAILTO:gu_use_te_06@domain.local
ATTENDEE;PARTSTAT=NEEDS-ACTION;CN=Test User 07;RSVP=TRUE;ROLE=REQ-PARTICIP
ANT:MAILTO:gu_use_te_07@domain.local
ATTENDEE;PARTSTAT=NEEDS-ACTION;CN=Test User 08;RSVP=TRUE;ROLE=REQ-PARTICIP
ANT:MAILTO:gu_use_te_08@domain.local
ATTENDEE;PARTSTAT=NEEDS-ACTION;CN=Test User 09;RSVP=TRUE;ROLE=REQ-PARTICIP
ANT:MAILTO:gu_use_te_09@domain.local
CREATED;TZID=Europe/Moscow:20240318T140525
DESCRIPTION:Memory leak recurrent appointment
LAST-MODIFIED;TZID=Europe/Moscow:20240318T140525
PRODID:-//My test Script//RU
TRANSP:OPAQUE
ORGANIZER;CN=Gu Use Te:mailto:gu_use_te_10@domain.local
CLASS:PUBLIC
END:VEVENT
END:VCALENDAR''

Tagsappointment, calendar, possible memory leak

Activities

sebastien

sebastien

2024-12-17 17:49

administrator   ~0018019

Try with latest nightly some memory fix has been commited.

Issue History

Date Modified Username Field Change
2024-03-19 10:32 eugenesu New Issue
2024-03-19 10:32 eugenesu Tag Attached: appointment
2024-03-19 10:32 eugenesu Tag Attached: calendar
2024-03-19 10:32 eugenesu Tag Attached: possible memory leak
2024-12-17 17:49 sebastien Note Added: 0018019
2024-12-17 17:49 sebastien Assigned To => sebastien
2024-12-17 17:49 sebastien Status new => feedback