Zabbix - Openfire monitoring

Po dłuższym okresie użytkowania aplikacji Openfire, okazało się że serwer na którym jest uruchomiona miewa mocne zadyszki procesora i na maszynie wirtualnej powoduje zamieszanie. Aplikacji sam nie pisałem. Dostałem do obejrzenia tzw. "Czarną skrzynkę".

Od jakiegoś czasu próbuje zbierać takie historyjki. Nawiązując więc do wcześniejszego http://kczerw.blogspot.com/2014/01/zabbix-daje-rade.html postaram się pokazać nieco szczegółów tylko pod kątem Openfire i Zabbix.

System aktualnie był monitorowany tylko na poziomie Linux. Nieregularnie, ale zazwyczaj w godzinach porannych, można było obserwować duże obciążenie procesora. Przypadkiem po zalogowaniu do konsoli ssh udało się złapać że to jest proces openfire.

Po zalogowaniu do konsoli administracyjnej Openfire nie zastałem zbyt wiele. Wersja prehistoryczna 3.6.4. w oryginale nie miała statystyk. Jedyne co było widać do objawy na postawie systemu Linux.
Pierwsze co zrobiłem to rozszerzyłem statystyki o monitorowanie socketów.
Z tych gniazdek wyszła pierwsza relacja która pokazała, że jest wyjątkowo dużo połączeń ESTABILISHED. Zaskoczyło mnie to, że jest ich znacznie więcej niż samych userów.

Openfire Linux socket

Postanowiłem poszukać źródeł do Openfire. W przypadku tej wersji nie było łatwo... w końcu to prawie zabytek. Udało się! Nawet takie starocie mają na serwerze. 

http://download.igniterealtime.org/openfire/openfire_3_6_4.tar.gz
http://download.igniterealtime.org/openfire/openfire_src_3_6_4.zip

Zabrałem się za oglądanie źródeł dla openfire.

W pierwszej kolejności dla tej wersji skompilowałem wszystko co się dało. Teraz już miałem to co ważne - pluginy do monitorowania.
Nie pozostało nic jak przymierzyć się do uruchomienia dodatkowych elementów które pokazują statystyki tego co się dzieje w środku. Po krótkich poszukiwaniach okazało się, że dodatkowe informacje można uzyskać na podstawie pluginów. Całkiem ciekawy okazał się plugin "Monitoring Service".

Czysta instalacja Openfire (bez dodatkowych pluginów) nie pokazuje zbyt wiele co się daje w aplikacji.
Wykonane modyfikacje dotyczyły pluginów do autoryzacji i grup. W największym skrócie powodowały, że struktura firmy w postaci wydziałów (zapisana w bazie) jest odwzorowana na grupy w Openfire. Po rewizji kodu pluginu okazuje się, że również zmienia się sposób informowania o widoczności. W ramach firmy przyjęto, że każda osoba widzi nawzajem zmiany statusu w komunikatorze.

Po wykonaniu wywiadu i przejrzeniu bazy dowiedziałem się że mamy około 400 userów, ale w praktyce korzysta około 200 osób.

I na tym skończyła się moja wiedza, reszty mogłem się domyślać, ale nie potrafiłem tego potwierdzić.
Moja hipoteza już na wstępie zakłada, że przyczyna dużego obciążenia procesora jest związana z podłączaniem (logowaniem) nowych operatorów. W dużej mierze można to było potwierdzić. Po wykonaniu restartu openfire zjawisko się również mocno nasilało.

Linux CPU Usage

Linux CPU Usage no iddle

Linux network traffic

Linux CPU Load

Kontakt z autorem pluginów niewiele dał. Ogólnie aplikacja jest w porządku działa - trzeba dać mocniejszą maszynę. Taka argumentacja mnie specjalnie nie przekonała, a co jak dodamy 100 userów?

Postanowiłem podłączyć do aplikacji monitor Java. Generalnie do aplikacji Java gdzie mogę to pcham zapcat-a. Jest znacznie prostszy we współpracy z zabbix niż natywny connector JMX w zabbix.
Openfire korzysta z Tanuki wrapper. Nie mam prostego sposobu na wpięcie się do tego wrapera aby wystartować proces zapcat-a. Tu można to prościej załatwić. Zapcat ma plugin który można wgrać do openfire.

Obserwowałem obrazki z monitora Linuxa i ze smutkiem spowodowany bezsilnością. Prawie pewne że kolejny dzień rano znów przypali się procesor w wirtualce.

Co do monitorowania Java nie można mieć zastrzeżeń. Ilość zjadanej pamięci jest spora ale nie dramatyczna. Nie widać też jakiś jawnych wycieków.

Spróbowałem podglądać wątki przy pomocy jconsole oraz jvisualvm. Niestety rezultaty nie były zbyt odkrywcze. Nawet załączenie monitorowania wywoływanych metod nie rzuciło światła na to co jest przyczyną obciążenia. Próbowałem wykorzystać sampler aby sprawdzić która z metod jest najbardziej kosztowana.

jvisualm openfire sampler snapshot

jvisualm openfire sampler

Ciągle rosła wartość czasu przetwarzania NamePreservingRunnable.run(). Po sprawdzeniu kodu tej klasy okazuje się, że to tylko wraper do uruchomienia wątku (na podstawie tego czegoś nie wiadomo co ten wątek robi).

Znaczna aktywność bazy danych w tym momencie skłoniła mnie do sprawdzenia ilości wywołań metod związanych z operacjami na bazie danych autoryzacji. Zrobiłem to w prosty sposób grepując loga.
Moje podejrzenia się potwierdziły. Ilość operacji była ogromna. Najbardziej dawał popalić plugin dostarczający informację o userach. Rekordowa była metoda

public class XXXUserProvider implements  UserProvider... {
 public Collection<String> getUsernames() {
 ...

Bardzo mnie to zastanawiało dlaczego operacje na bazie obciążają procesor. Normalnie to nie do pomyślenia, przecież wtedy procesor czeka na dostarczenie danych, to baza co najwyżej mogła być obciążona (ale to zupełnie inny system w tym wypadku iSeries), jednak baza dawała radę. Zatem to niekoniecznie jest przyczyną całego problemu.

Trochę światła się pojawiło po zainstalowaniu pluginu "Monitoring Service"
Pokazuje on 3 ważne parametry:

• liczba userów, 
• aktywne konwersacje, 
• liczba pakietów na minutę

Liczba pakietów które się pojawiają po restarcie Openfire sporo daje do myślenia. Z dużym prawdopodobieństwem można powiedzieć, że są to pakiety z informacją o widoczności. 

Przy założeniu że 1 klient jest źródłem powiadomienia do wszystkich innych mamy 1 -> 200 a klientów jest 200 - wiec mamy 200 * 200 co daje 40 000 pakietów. A ponieważ nie jest to tylko ten pakiet wiec rachunek w miarę się zgadza. Model który został przyjęty przy definiowaniu widoczności jest na pewno kosztowny przy masowej zmianie widoczności operatorów. 

Oglądając wykresy statystyk openfire na bierząco nie miałem jakiś specjalnych zastrzeżeń. Gdy chciałem sprawdzić stan który był wczoraj, albo kilka dni wcześnie było kiepsko. Dane zostały uśrednione. 

Plugin "Monitoring Service" w tej wersji trochę mnie zawiódł. Niestety nie podłącza danych które zbiera do JMX. Pozostaje na początek zatem tylko konsola admina do oglądania tego co się dzieje.

Obejrzałem również wartości dla cache Openfire. Tu po chwili obserwacji okazało się że wartość cache dla "Roster" zdecydowanie była zbyt mała. Zwiększyłem ją. I tu pojawił się skok. Liczba wywołań metody  getUsernames() dla UserProvider-a kolosalnie spadła. To mnie przekonało o znaczeniu cache. Niemniej jednak nie spowodowało to zmniejszenia zużycia procesora w jakiś znaczący sposób. Podobnie miała się sprawa w przypadku cache "VCard"

Ponieważ chciałem mieć te elementy w jednym słusznym miejscu zabrałem się do przeróbki pluginu zabbix dla Openfire. Postanowiłem dodać do JMX elementy które są widoczne w konsoli administracyjnej Openfire po dodaniu pluginu "Monitoring".

Przyjąłem sobie założenie aby nie zepsuć aktualnego pluginu. Czyli jeżeli nie ma zainstalowanego pluginu "Monitoring" to po prostu nie mam drzewka ze statystyka w JMX.

Do w/w elementów można się dostać w wykorzystując wymienione poniżej klasy:

XMPPServer xmppServer = XMPPServer.getInstance();
org.jivesoftware.openfire.plugin.MonitoringPlugin
org.jivesoftware.openfire.archive.ConversationManager
org.jivesoftware.openfire.reporting.stats.StatsViewer
org.jivesoftware.openfire.reporting.graph.GraphEngine
org.jivesoftware.openfire.reporting.stats.StatsAction

Postaram się udostępnić zmodyfikowane źródła pluginu zapcat-openfire oraz template dla Zabbix.

Rezultat jest wystarczający. W drzewku JMX pojawiają się pozycje openfire/session/cache oraz openfire/session/stats

openfire-zabbix plugin JMX tree (cache)

openfire-zabbix plugin JMX tree (stats)

Teraz już wystarczy przygotować template dla Zabbix.

openfire-zapcat zabbix cache roster

openfire-zapcat zabbix cache routing-user-session

openfire-zapcat zabbix cache vcard

openfire-zapcat zabbix conversation

openfire-zapcat zabbix pocket-count

openfire-zapcat zabbix server-bytes

openfire-zapcat zabbix session

Teraz może pora pochwalić się czy udało się zmienić tą maszynę z piekarnika z powrotem w normalnie pracujący system. Okazało się że przyczyną jest trywialny problem. Na dysku znajdował się katalog, który zawierał 500 000 plików. Dostęp do tego katalogu (inicjowany przez zupełnie inną aplikację) pochłaniał takie zasoby procesora. Ale skutek uboczny również przymulał openfire.
W takim modelu powiadamiania jaki mamy wybrany nie da się pewnie zrealizować tego bez obciążenia procesora. Można wykonać dokładniejszą eksploracje mechanizmu komunikacji Openfire.

W tym jednak przypadku ja postawiłem sobie za cel tylko zrobienie statystyk w Zabbix dla Openfire.