Kalendar start dauert sehr lange nach Upgrade >= 16.1

[fhe3-hilt]

Hallo,

nachdem wir eGroupware (comunity edition) auf 16.1 upgedatet haben und mittleirweile 17.1 in letzter Version einsetzen, daurt der Start bei der Anmeldung sehr lange (je nach User 20 Sekungen bis 10 Minuten). Die Zeit verbringt die Anwendung Kalender in folgende SQL Queries in der Datenbank:

Blockquote

| 10331387 | egroupware16 | 172.19.0.182:46785 | egroupware16 | Query | 53 | Sending data | (SELECT egw_cal_repeats.recur_type,range_end AS recur_enddate,egw_cal_repeats.recur_interval,egw_cal_repeats.recur_data,egw_cal.cal_id,cal_start,cal_end,egw_cal_user.cal_recur_date FROM (SELECT * FROM egw_cal WHERE cal_deleted IS NULL AND (range_end IS NULL OR range_end>1516834800)) egw_cal JOIN egw_cal_dates ON egw_cal.cal_id=egw_cal_dates.cal_id JOIN egw_cal_user ON egw_cal.cal_id=egw_cal_user.cal_id LEFT JOIN egw_cal_repeats ON egw_cal.cal_id=egw_cal_repeats.cal_id LEFT JOIN egw_cal_user rejected_by_user ON egw_cal.cal_id=rejected_by_user.cal_id AND rejected_by_user.cal_user_type=‘u’ AND rejected_by_user.cal_user_id=‘8’ AND (recur_type IS NULL AND rejected_by_user.cal_recur_date=0 OR cal_start=rejected_by_user.cal_recur_date) WHERE cal_deleted IS NULL AND egw_cal_user.cal_status NOT IN (‘R’,‘X’,‘E’) AND 1516834800 < cal_end AND (rejected_by_user.cal_status IS NULL OR rejected_by_user.cal_status NOT IN (‘R’,‘X’)) AND egw_cal_user.cal_user_type=‘u’ AND egw_cal_user.cal_user_id IN (‘8’,’-1’,’-4’,’-1021’,’-1013’,’-11’,’-1001’,’-1040’) AND recur_type IS NULL AND egw_cal_user.cal_recur_date=0)
UNION
(SELECT egw_cal_repeats.recur_type,range_end AS recur_enddate,egw_cal_repeats.recur_interval,egw_cal_repeats.recur_data,egw_cal.cal_id,cal_start,cal_end,egw_cal_user.cal_recur_date FROM (SELECT * FROM egw_cal WHERE cal_deleted IS NULL AND (range_end IS NULL OR range_end>1516834800)) egw_cal JOIN egw_cal_dates ON egw_cal.cal_id=egw_cal_dates.cal_id JOIN egw_cal_user ON egw_cal.cal_id=egw_cal_user.cal_id LEFT JOIN egw_cal_repeats ON egw_cal.cal_id=egw_cal_repeats.cal_id LEFT JOIN egw_cal_user rejected_by_user ON egw_cal.cal_id=rejected_by_user.cal_id AND rejected_by_user.cal_user_type=‘u’ AND rejected_by_user.cal_user_id=‘8’ AND (recur_type IS NULL AND rejected_by_user.cal_recur_date=0 OR cal_start=rejected_by_user.cal_recur_date) WHERE cal_deleted IS NULL AND egw_cal_user.cal_status NOT IN (‘R’,‘X’,‘E’) AND 1516834800 < cal_end AND (rejected_by_user.cal_status IS NULL OR rejected_by_user.cal_status NOT IN (‘R’,‘X’)) AND egw_cal_user.cal_user_type=‘u’ AND egw_cal_user.cal_user_id IN (‘8’,’-1’,’-4’,’-1021’,’-1013’,’-11’,’-1001’,’-1040’) AND egw_cal_user.cal_recur_date=cal_start) | 0.000 |

Blockquote

Eckdaten:
eGroupware: 17.1.20180118 installiert als Debian Paket
user gesamt: 25
OS: Debian Jessie
PHP7
DB: MariaDB 10.1 auf separatem Host

Haben Sie ein Tipp wie man das beheben könnte? Mit ‘EXPLAIN’ haben wir versucht rauszufinden ob es in der MySQL sinvoll mit index gelöst werden könnte, aber nichts gefunden.

Viele Grüße,

Dimitrij

[StefanU]

Hallo Dimitrij.

16.1 upgedatet haben und mittleirweile 17.1 in letzter Version einsetzen, daurt der Start bei der Anmeldung sehr lange (je nach User 20 Sekungen bis 10 Minuten)

Das heißt das Problem bestand bereits in eurer 16.1 uns somit bereits länger?
Das ist auf keinen Fall ein grundsätzliches Problem. Ich schaffe 3 Sekunden bei einer Monatsansicht mit ca. 100 Terminen und Ressourcen.

Warum habt ihr die DB auf einem einem anderen Host?
Dauert das auch zu lang wenn ihr (definitiv) nur den persönlichen (Monats)Kalender aufruft? Also sozusagen die Minimal-Ansicht?

Ich würde das einmal mit einer frischen Installation gegenprüfen:
debian 9.3 minimal
repo-installation mit nginx/FPM (apt install nginx php-fpm egroupware-epl)
(gzip in nginx aktivieren, http/2 aktivieren (ssl notwendig))
EGw-DB-Sicherung aus der Produktiv-Installation in das Test-System (Setup) hochladen und zurückspielen.

Das ist nicht viel Aufwand. Mal schauen was dabei heraus kommt…

Gruß
Stefan

[fhe3-hilt]

Hallo Stefan,
danke, ich werde es versuchen. Das Problem ist ja das es nur bei Login und nach jahrelangen Nutzung auftritt mit doch einigen Terminen. Ist mein erstmal eingeloggt, ist wieder alles flott. Ich vermute eine Art von Cache befüllung bei der Erstellung der Session. Die Queries habe ich gesendet.
Was die Faage “warum eigene Datenbank” angeht, so bevorzugen wir in allen unseren Projekten Trennung der Komponenten. Jetzt ja mit micro services wird es noch strickter gemacht.

Dimitrij

[RalfBecker]

Nach meiner Erfahrung ist ein separater Datenbank Server bestenfalls gleich schnell. Wenn Du willst kannst Du den natürlich in einem Container laufen lassen …

Viel wichtiger ist das MySQL/MariaDB für InnoDB getuned ist, sprich als Minimum mal ein ordentlich großer Buffer Pool (innodb_buffer_pool_size=1G) eingestellt ist, sprich 1-2GB für eine größere Installation.
Zum weiteren tunen kann man dann https://github.com/major/MySQLTuner-perl verwenden. Wichtig ist das die DB einen Tag unter Last laufen sollte, bevor man aussagekräftige Ergebnisse bekommt.

Ralf

[fhe3-hilt]

Mariadb auf dem Server ist komplett ausgetuned und läuft mit 10G innodb_buffer_pool_size bei 15G an Daten. Das ist an sich nicht das Problem. Auch mysqltuner.pl zeigt nur paar Kleinigkeiten. Es ist die Art der Query, die abgesetzt wird (s. oben). Die dauert einfach langer auf einer Installation was paar Jahre alt ist. Leider auch Explain zeigt nciht genau wie man das auf DB optimieren sollte.

Dimitrij

[RalfBecker]

Ein anderer Faktor ist das Javascript das im Browser abläuft, da hatten wir auch schon mal den Fall, dass ein relativ alter Computer mit einem nicht aktuellen Browser sehr lange brauchte. Kannst Du mal herausfinden, ob mit aktueller Hardware und einem Chrome der Login ähnlich lange braucht.
Am besten dazu noch auf der Login Seite die Entwicklerwerkzeuge aufmachen und auf den Network Tab wechseln. Dort am besten nach XHR und Doc filtern. Beim Login solltest Du dann sehen können, wie lange die einzelnen Anfragen an den Server dauern und ob das Problem server-seitig oder client-seitig liegt.
Wir führen solche Untersuchungen natürlich auch im Rahmen eines Support Budgets durch.
Ralf

[fhe3-hilt]

ich denke die Clients verschlimmern die Sache nur, muss es aber genauer untersuchen. Was support angeht, so vergleichen wir derzeit alle Angebote und deswegen könnsn nicht im Moment auf Support unterschreiben.

Dimitrij

[fhe3-hilt]

Die Query ist in Teilen nicht optimiert und macht einfach ein Tablescan:

explain extended (SELECT egw_cal_repeats.recur_type,range_end AS recur_enddate,egw_cal_repeats.recur_interval,egw_cal_repeats.recur_data,egw_cal.cal_id,cal_start,cal_end,egw_cal_user.cal_recur_date FROM (SELECT * FROM egw_cal WHERE cal_deleted IS NULL AND (range_end IS NULL OR range_end>1516834800)) egw_cal JOIN egw_cal_dates ON egw_cal.cal_id=egw_cal_dates.cal_id JOIN egw_cal_user ON egw_cal.cal_id=egw_cal_user.cal_id LEFT JOIN egw_cal_repeats ON egw_cal.cal_id=egw_cal_repeats.cal_id LEFT JOIN egw_cal_user rejected_by_user ON egw_cal.cal_id=rejected_by_user.cal_id AND rejected_by_user.cal_user_type=‘u’ AND rejected_by_user.cal_user_id=‘8’ AND (recur_type IS NULL AND rejected_by_user.cal_recur_date=0 OR cal_start=rejected_by_user.cal_recur_date) WHERE cal_deleted IS NULL AND egw_cal_user.cal_status NOT IN (‘R’,‘X’,‘E’) AND 1516834800 < cal_end AND (rejected_by_user.cal_status IS NULL OR rejected_by_user.cal_status NOT IN (‘R’,‘X’)) AND egw_cal_user.cal_user_type=‘u’ AND egw_cal_user.cal_user_id IN (‘8’,’-1’,’-4’,’-1021’,’-1013’,’-11’,’-1001’,’-1040’) AND recur_type IS NULL AND egw_cal_user.cal_recur_date=0) UNION (SELECT egw_cal_repeats.recur_type,range_end AS recur_enddate,egw_cal_repeats.recur_interval,egw_cal_repeats.recur_data,egw_cal.cal_id,cal_start,cal_end,egw_cal_user.cal_recur_date FROM (SELECT * FROM egw_cal WHERE cal_deleted IS NULL AND (range_end IS NULL OR range_end>1516834800)) egw_cal JOIN egw_cal_dates ON egw_cal.cal_id=egw_cal_dates.cal_id JOIN egw_cal_user ON egw_cal.cal_id=egw_cal_user.cal_id LEFT JOIN egw_cal_repeats ON egw_cal.cal_id=egw_cal_repeats.cal_id LEFT JOIN egw_cal_user rejected_by_user ON egw_cal.cal_id=rejected_by_user.cal_id AND rejected_by_user.cal_user_type=‘u’ AND rejected_by_user.cal_user_id=‘8’ AND (recur_type IS NULL AND rejected_by_user.cal_recur_date=0 OR cal_start=rejected_by_user.cal_recur_date) WHERE cal_deleted IS NULL AND egw_cal_user.cal_status NOT IN (‘R’,‘X’,‘E’) AND 1516834800 < cal_end AND (rejected_by_user.cal_status IS NULL OR rejected_by_user.cal_status NOT IN (‘R’,‘X’)) AND egw_cal_user.cal_user_type=‘u’ AND egw_cal_user.cal_user_id IN (‘8’,’-1’,’-4’,’-1021’,’-1013’,’-11’,’-1001’,’-1040’) AND egw_cal_user.cal_recur_date=cal_start);
±-----±-------------±-----------------±-------±--------------------------------------------------------±-----------------------------------±--------±--------------------------------------------------------------------------±-----±---------±-----------------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
±-----±-------------±-----------------±-------±--------------------------------------------------------±-----------------------------------±--------±--------------------------------------------------------------------------±-----±---------±-----------------------------------+
| 1 | PRIMARY | egw_cal | ALL | PRIMARY,egw_cal_deleted | NULL | NULL | NULL | 3467 | 88.06 | Using where |
| 1 | PRIMARY | egw_cal_repeats | eq_ref | PRIMARY | PRIMARY | 4 | egroupware16.egw_cal.cal_id | 1 | 100.00 | Using where; Not exists |
| 1 | PRIMARY | egw_cal_user | ref | egw_cal_user_id_recur_date_type_id,egw_cal_user_type_id | egw_cal_user_id_recur_date_type_id | 15 | egroupware16.egw_cal.cal_id,const,const | 1 | 100.00 | Using index condition; Using where |
| 1 | PRIMARY | egw_cal_dates | ref | PRIMARY,egw_cal_dates_end | PRIMARY | 4 | egroupware16.egw_cal.cal_id | 10 | 100.00 | Using where |
| 1 | PRIMARY | rejected_by_user | ref | egw_cal_user_id_recur_date_type_id,egw_cal_user_type_id | egw_cal_user_id_recur_date_type_id | 4 | egroupware16.egw_cal.cal_id | 21 | 100.00 | Using where |
| 3 | UNION | egw_cal_user | range | egw_cal_user_id_recur_date_type_id,egw_cal_user_type_id | egw_cal_user_type_id | 37 | NULL | 9368 | 100.00 | Using index condition; Using where |
| 3 | UNION | egw_cal | eq_ref | PRIMARY,egw_cal_deleted | PRIMARY | 4 | egroupware16.egw_cal_user.cal_id | 1 | 100.00 | Using where |
| 3 | UNION | egw_cal_repeats | eq_ref | PRIMARY | PRIMARY | 4 | egroupware16.egw_cal_user.cal_id | 1 | 100.00 | |
| 3 | UNION | egw_cal_dates | eq_ref | PRIMARY,egw_cal_dates_end,egw_cal_dates_start | PRIMARY | 12 | egroupware16.egw_cal_user.cal_id,egroupware16.egw_cal_user.cal_recur_date | 1 | 100.00 | Using where |
| 3 | UNION | rejected_by_user | ref | egw_cal_user_id_recur_date_type_id,egw_cal_user_type_id | egw_cal_user_id_recur_date_type_id | 4 | egroupware16.egw_cal_user.cal_id | 21 | 100.00 | Using where |
| NULL | UNION RESULT | <union1,3> | ALL | NULL | NULL | NULL | NULL | NULL | NULL | |
±-----±-------------±-----------------±-------±--------------------------------------------------------±-----------------------------------±--------±--------------------------------------------------------------------------±-----±---------±-----------------------------------+
11 rows in set, 1 warning (0.00 sec)

[RalfBecker]

Das ist schon klar, meine Frage war jetzt herauszufinden ob es diese Query ist, oder etwas anderes z.B. die Geschwindigkeit des Browsers oder etwas das sonst noch server-seitig abläuft.
(Die Query ist leider nicht einfach optimierbar, solange wir die komplexe ACL unterstützen, die wir aktuell habe. Wir waren da schon öfters auch mit MariaDB/SkySQL Konsulting dran.)
Wie lange brauch die Query denn, wenn Du sie über mysql oder phpMyAdmin direkt ausführst?

[fhe3-hilt]

Direkt auf MySQL Konsole braucht diese Query:

6226 rows in set (1 min 5.79 sec)

Dimitrij

[fhe3-hilt]

Die meiste zeit geht in 'sending data’
SHOW PROFILE;
Vorformatierter TextVorformatierter Text±---------------------±----------+
| Status | Duration |
±---------------------±----------+
| starting | 0.000199 |
| checking permissions | 0.000010 |
| checking permissions | 0.000006 |
| checking permissions | 0.000006 |
| checking permissions | 0.000006 |
| checking permissions | 0.000006 |
| checking permissions | 0.000006 |
| checking permissions | 0.000006 |
| checking permissions | 0.000006 |
| checking permissions | 0.000006 |
| checking permissions | 0.000007 |
| Opening tables | 0.000041 |
| After opening tables | 0.000011 |
| System lock | 0.000012 |
| Table lock | 0.000295 |
| optimizing | 0.000062 |
| statistics | 0.000259 |
| preparing | 0.000073 |
| optimizing | 0.000053 |
| statistics | 0.000209 |
| preparing | 0.000092 |
| executing | 0.000009 |
| Sending data | 0.009916 |
| executing | 0.000011 |
| Sending data | 64.398748 |
| optimizing | 0.000035 |
| statistics | 0.000026 |
| preparing | 0.000019 |
| executing | 0.000012 |
| Sending data | 0.004165 |
| removing tmp table | 0.000146 |
| Sending data | 0.000015 |
| query end | 0.000017 |
| closing tables | 0.000018 |
| removing tmp table | 0.000008 |
| closing tables | 0.000007 |
| removing tmp table | 0.000008 |
| closing tables | 0.000009 |
| Unlocking tables | 0.000049 |
| freeing items | 0.000047 |
| updating status | 0.000024 |
| logging slow query | 0.000088 |
| cleaning up | 0.000032 |
±---------------------±----------+
43 rows in set (0.00 sec)

[RalfBecker]

In welche Kalender Ansicht startet Ihr da?

Ich sehe in der Query nur ein Anfangsdatum vom 24.01.2018 aber kein Enddatum, das sollte bei normalen Ansichten nicht vorkommen und sorgt natürlich dafür, das sehr viele Daten, in dem Fall ~6.000 Termine übertragen werden.

[fhe3-hilt]

Wie kann das begrenzt werden? ich frage den Kollegen was für Ansich gestartet wird.

[fhe3-hilt]

Wir starten alle normal Ansich mit Woche. Im Moment lädt der Kalender bei einem Kollegen gar nicht mehr und läufr in 504-er Error.
Irgendwas was wir an PHP tunen könnten? Die MySQL Query ist in 1 min durch, aber die Resultate werden wohl von der Groupware nicht verarbeitet (steht in ‘sending data’)

[fhe3-hilt]

Noch eine Frage zu dem Ansicht. Wir haben nichts speziellen eingestellt im Bezug auf wieviele Termine (Enddatum) angezeigt werden sollen. Haben wir eine Einstellung übersehen?
Dimitrij

[fhe3-hilt]

Ich glaube es sind die Serientermine (wir haben einige davon), die das Problem verursachen. Die werden meinst ohne Enddatum angelegt, also auch alle geladen. Kann das irgendwie begrenzt werden?

Dimitrij

[RalfBecker]

Serientermine ohne Enddatum müssen für alle Ansichten/Zeiträume geladen werden. Da führt leider kein Weg dran vorbei, außer nicht zu viele davon anzulegen

Es gibt eine Konfiguration die etwas andere SQL Abfrage, erzeugt, mit manchmal besser - manchmal schlechterer Laufzeit:
Admin >> Anwendungen >> Kalender >> Konfiguration der Anwendung
Sollen spezielle Bereichs-Ansichten verwendet werden, um Kalenderabfragen zu optimieren?
Der Default ist Ja, Du kannst das mal auf Nein umstellen und Dich neu einloggen.

[fhe3-hilt]

Wegen Optimierung, die war bei uns an. Hab ausgemacht und nichts nennenwertes gesehen.
Was Serientermine angeht, so ist das definitiv die Ursache. Vielleicht schafft ihr es irgendwann mal in einem Release so zu optiieren, das es besser wird. Oder die Logik der 14-er Version nehmen. Die war noch Ok