IIIF unter Last
last modified on Jul 08, 2019
Was ist passiert?
Am 24. und 25.10.2018 meldete das Monitoring (nagios) vermehrt Ausfälle bei digilib/rest/iiif. Ursache ist ein Massenabzug der Daten, der parallelisiert abläuft und die bekannten Probleme mit memory leaks seitens digilib zum Vorschein bringt. Der abfragende Prozess bekommt weniger als die Hälfte der Anfragen mit 200 beantwortet.
Bekannt war zu diesem Zeitpunkt, dass digilib einen Speicherüberlauf provoziert, möglicherweise durch nicht vollst. verarbeitete Anfragen, die dann vom Proxy schon mit Timeout beantwortet wurden. Als Gegenmaßnahme wurde alle 12h ein Neustart veranlasst, der zu keinen Ausfällen führte, da zwei parallel laufende digilib-Prozesse zu unterschiedlichen Zeiten (gegenläufig) einen Neustart erfahren haben.
Übersicht Quelle erweitern
root@textgrid-esx2:/var/log/nginx# cd /var/log/nginx; echo -e "FILE\tdigilib\t200\t500\t502\t504"; for FILE in access.log.2018-*.gz; do echo -e "${FILE}\t$(zcat $FILE | grep "digilib" | wc -l)\t$(zcat $FILE | grep "digilib" | grep -e "\s200\s" | wc -l)\t$(zcat $FILE | grep "digilib" | grep -e "\s500\s" | wc -l)\t$(zcat $FILE | grep "digilib" | grep -e "\s502\s" | wc -l)\t$(zcat $FILE | grep "digilib" | grep -e "\s504\s" | wc -l)"; done;
FILE digilib 200 500 502 504
access.log.2018-07-28.gz 759 755 0 0 0
access.log.2018-07-29.gz 1381 1378 0 0 0
access.log.2018-07-30.gz 410 410 0 0 0
access.log.2018-07-31.gz 468 438 0 0 0
access.log.2018-08-01.gz 383 376 0 0 0
access.log.2018-08-02.gz 1456 1450 0 0 0
access.log.2018-08-03.gz 2780 2771 1 0 0
access.log.2018-08-04.gz 1006 1001 1 0 0
access.log.2018-08-05.gz 2323 2317 0 0 0
access.log.2018-08-06.gz 1832 1831 0 0 0
access.log.2018-08-07.gz 3097 2935 0 0 0
access.log.2018-08-08.gz 1733 1723 0 0 0
access.log.2018-08-09.gz 2752 2742 0 0 0
access.log.2018-08-10.gz 4403 4394 1 0 0
access.log.2018-08-11.gz 1866 1858 1 0 0
access.log.2018-08-12.gz 1329 1282 36 0 0
access.log.2018-08-13.gz 2659 2656 0 0 0
access.log.2018-08-14.gz 3380 3310 0 0 0
access.log.2018-08-15.gz 5492 5483 0 0 0
access.log.2018-08-16.gz 4441 4424 0 0 0
access.log.2018-08-17.gz 3719 3709 0 0 0
access.log.2018-08-18.gz 4794 4787 0 0 0
access.log.2018-08-19.gz 1286 1283 0 0 0
access.log.2018-08-20.gz 1920 1918 0 0 0
access.log.2018-08-21.gz 2700 2074 0 0 0
access.log.2018-08-22.gz 3297 3291 0 0 0
access.log.2018-08-23.gz 3631 3194 0 0 0
access.log.2018-08-24.gz 3953 3939 4 0 0
access.log.2018-08-25.gz 4473 4044 0 0 0
access.log.2018-08-26.gz 1225 1221 0 0 0
access.log.2018-08-27.gz 1937 1936 0 0 0
access.log.2018-08-28.gz 2002 1986 0 0 0
access.log.2018-08-29.gz 2209 2204 0 0 0
access.log.2018-08-30.gz 2634 2629 0 0 0
access.log.2018-08-31.gz 1437 1421 0 1 0
access.log.2018-09-01.gz 3071 2813 0 0 0
access.log.2018-09-02.gz 1021 1016 0 0 0
access.log.2018-09-03.gz 1276 1274 0 0 0
access.log.2018-09-05.gz 7860 7817 0 0 0
access.log.2018-09-06.gz 6409 6280 0 0 0
access.log.2018-09-07.gz 4204 3758 0 0 0
access.log.2018-09-08.gz 2227 2212 0 0 0
access.log.2018-09-09.gz 3097 2686 0 0 0
access.log.2018-09-10.gz 621 610 0 0 0
access.log.2018-09-11.gz 8863 8449 0 0 0
access.log.2018-09-12.gz 3010 2768 0 0 0
access.log.2018-09-13.gz 7973 6184 1472 57 193
access.log.2018-09-14.gz 7272 7232 0 0 0
access.log.2018-09-15.gz 5213 5185 0 0 0
access.log.2018-09-16.gz 4891 4836 20 0 0
access.log.2018-09-17.gz 4340 4316 1 0 0
access.log.2018-09-18.gz 7331 7305 0 0 0
access.log.2018-09-19.gz 6634 6571 6 0 0
access.log.2018-09-20.gz 5229 5159 0 0 0
access.log.2018-09-21.gz 9112 9096 0 0 0
access.log.2018-09-22.gz 8706 8680 0 0 0
access.log.2018-09-23.gz 6051 6048 0 0 0
access.log.2018-09-24.gz 5835 5829 0 0 0
access.log.2018-09-25.gz 4742 4656 0 0 0
access.log.2018-09-26.gz 4832 4827 0 0 0
access.log.2018-09-27.gz 8045 7760 0 0 0
access.log.2018-09-28.gz 6267 6252 0 0 0
access.log.2018-09-29.gz 6306 5971 0 0 0
access.log.2018-09-30.gz 4234 4164 2 0 0
access.log.2018-10-01.gz 3855 3779 0 0 0
access.log.2018-10-02.gz 7045 6635 0 0 0
access.log.2018-10-03.gz 4800 4770 0 0 0
access.log.2018-10-04.gz 2627 2618 0 0 0
access.log.2018-10-05.gz 3938 3917 0 0 0
access.log.2018-10-06.gz 3054 3032 0 0 0
access.log.2018-10-07.gz 3815 3811 0 0 0
access.log.2018-10-08.gz 2675 2671 0 0 0
access.log.2018-10-09.gz 2978 2953 1 0 0
access.log.2018-10-10.gz 3947 3932 0 0 0
access.log.2018-10-11.gz 3247 3229 0 0 0
access.log.2018-10-12.gz 4826 4545 0 0 0
access.log.2018-10-13.gz 4810 4808 0 0 0
access.log.2018-10-14.gz 4670 4667 0 0 0
access.log.2018-10-15.gz 5326 5263 6 0 0
access.log.2018-10-16.gz 7283 6848 0 0 0
access.log.2018-10-17.gz 4357 4263 0 0 0
access.log.2018-10-18.gz 7965 7500 87 0 0
access.log.2018-10-19.gz 9616 8709 841 0 0
access.log.2018-10-20.gz 6798 5942 41 0 0
access.log.2018-10-21.gz 3005 3004 0 0 0
access.log.2018-10-22.gz 3593 3573 0 0 0
access.log.2018-10-23.gz 7100 7001 0 0 0
access.log.2018-10-24.gz 5705 5155 303 0 0
access.log.2018-10-25.gz 12719 6273 5800 125 201
Sofortmaßnahmen
- digilib wird stündlich neu gestartet (steht im puppet-code, Ubbo Veentjer)
- siehe https://puppetserver.gwdg.de:11798/report/textgrid-esx2.gwdg.de/08dc1292c653b8dc7180b5c0ace0a3619e6ade53
- darauf hin ging die Anz. an Fehlern deutlich zurück. Nach 12:07 (Serverzeit) gab es noch 13 Meldungen mit HTTP 500.
- kurzfristig wird ein Szenario für Lasttest entwickelt (ca. 1 Woche, Mathias Göbel)
Weiteres Vorgehen/Empfehlung
digilib entweder
- verbessern,
- ersetzen oder
- alles abschalten.
