Doświadczam dziwnego, ale poważnego problemu z uruchomieniem kilku (około 15) instancji aplikacji internetowych Java EE-ish (Hibernate 4 + Spring + Quartz + JSF + Facelets + Richfaces) na Tomcat 7 / Java 7.

System działa dobrze, ale po znacznie różnym czasie wszystkie instancje aplikacji w tym samym czasie nagle cierpią z powodu rosnących czasów odpowiedzi. Zasadniczo aplikacja nadal działa, ale czasy odpowiedzi są około trzy razy wyższe.

Są to dwa diagramy wyświetlające czas odpowiedzi dwóch krótkich przepływów pracy / akcji (zaloguj się, wyświetl listę seminariów, ajax-odśwież tę listę, wyloguj się; dolna linia to tylko czas żądania odświeżenia ajax) dwóch przykładowych instancji aplikacji:

Jak widać, obie instancje aplikacji „eksplodują” dokładnie w tym samym czasie i pozostają wolne. Po ponownym uruchomieniu serwera wszystko wraca do normy. Wszystkie wystąpienia aplikacji „eksplodują” jednocześnie.

Przechowujemy dane sesji do bazy danych i używamy tego do grupowania. Sprawdziliśmy rozmiar i liczbę sesji, a oba są raczej niskie (co oznacza, że ​​na innych serwerach z innymi aplikacjami czasami mamy większe i więcej sesji). Drugi Tomcat w klastrze zazwyczaj pozostaje szybki przez kilka godzin, a po tym losowym okresie czasu również „umiera”. Sprawdziliśmy rozmiary sterty za pomocą jconsole, a główna sterta pozostaje w rozmiarze od 2,5 do 1 GB, pula połączeń db jest zasadniczo pełna darmowych połączeń, a także pul wątków. Maksymalna wielkość sterty to 5 GB, dostępna jest również duża przestrzeń na perm. Obciążenie nie jest szczególnie wysokie; główne obciążenie procesora wynosi około 5%. Serwer nie zamienia się. Nie jest to również problem ze sprzętem, ponieważ dodatkowo wdrożyliśmy aplikacje na maszynie wirtualnej, gdzie problemy pozostają takie same.

Nie wiem już, gdzie szukać, nie mam pomysłów. Czy ktoś ma pomysł, gdzie szukać?

2013-02-21 Aktualizacja: nowe dane!

Dodałem do aplikacji jeszcze dwa ślady czasowe. Jeśli chodzi o pomiar: system monitorowania wywołuje serwlet, który wykonuje dwa zadania, mierzy czas wykonania dla każdego na serwerze i zapisuje czas potrzebny na odpowiedź. Te wartości są rejestrowane przez system monitorowania.

Mam kilka ciekawych nowych faktów: gorące ponowne uruchomienie aplikacji powoduje, że ta pojedyncza instancja na obecnym Tomcacie staje się szokująca. Wydaje się, że wpływa to również na wydajność obliczania surowego procesora (patrz poniżej). Ta eksplozja kontekstu indywidualnego różni się od eksplozji kontekstu ogólnego, która zachodzi losowo.

Teraz dla niektórych danych:

Najpierw poszczególne linie:

Jasnoniebieski to całkowity czas wykonania małego przepływu pracy (szczegóły patrz powyżej), mierzony na kliencieCzerwony jest „częścią” jasnoniebieskiego koloru i jest to czas potrzebny na wykonanie specjalnego kroku tego przepływu pracy, mierzonego na kliencieCiemnoniebieski jest mierzony w aplikacji i polega na odczytaniu listy obiektów z bazy danych poprzez Hibernate i iteracji na tej liście, pobieraniu leniwych kolekcji i leniwych obiektów.Green to mały benchmark procesora wykorzystujący operacje zmiennoprzecinkowe i całkowite. O ile nie widzę podziału obiektu, więc nie ma śmieci.

Teraz dla poszczególnych etapów eksplozji: Zaznaczyłem każdy obraz trzema czarnymi kropkami. Pierwsza z nich to „mała” eksplozja w mniej więcej jednej instancji aplikacji - w Inst1 przeskakuje (szczególnie widoczna w czerwonej linii), podczas gdy Inst2 poniżej mniej więcej pozostaje spokojny.

Po tej małej eksplozji następuje „wielki wybuch” i wszystkie instancje aplikacji na Tomcat eksplodują (druga kropka). Zauważ, że ta eksplozja wpływa na wszystkie operacje wysokiego poziomu (przetwarzanie żądań, dostęp do bazy danych), alenie benchmark procesora. Pozostaje niski w obu systemach.

Następnie ponownie wdrożyłem inst1 na gorąco, dotykając pliku context.xml. Jak powiedziałem wcześniej, ten przypadek przechodzi z eksplodowanego do całkowicie zdestabilizowanego teraz (jasnoniebieska linia jest poza wykresem - jest to około 18 sekund). Zauważ, jak a) to ponowne rozmieszczenie w ogóle nie wpływa na Inst2 ib) w jaki sposób surowy dostęp do bazy danych Inst1 również nie ma wpływu - ale jak nagle procesorwydaje się być wolniejszy!. To szalone, mówię.

Aktualizacja aktualizacji Słuchacz zapobiegania wyciekom Tomcat nie jęczy o przestarzałych wątkach lub wątkach, gdy aplikacja nie jest wdrożona. Oczywiście wydaje się, że jest jakiś problem z oczyszczaniem (co, jak zakładam, nie jest bezpośrednio związany z Wielkim Wybuchem), ale Tomcat nie ma dla mnie aluzji.

2013-02-25 Aktualizacja: Środowisko aplikacji i harmonogram kwarcowy

Środowisko aplikacji nie jest zbyt skomplikowane. Oprócz komponentów sieciowych (o których nie wiem wystarczająco dużo) jest zasadniczo jeden serwer aplikacji (Linux) i dwa serwery baz danych (MySQL 5 i MSSQL 2008). Główne obciążenie jest na serwerze MSSQL, drugie służy jedynie jako miejsce do przechowywania sesji.

Serwer aplikacji uruchamia Apache jako system równoważenia obciążenia między dwoma serwerami Tomcats. Mamy więc dwie maszyny JVM działające na tym samym sprzęcie (dwa Tomcatinstancje). Używamy tej konfiguracji, aby nie zbilansować obciążenia, ponieważ serwer aplikacji jest w stanie uruchomić aplikację w porządku (co robił przez lata), ale aby umożliwić aktualizacje małych aplikacji bez przestojów. Ta aplikacja internetowa jest wdrażana jako osobnakonteksty dla różnych klientów, około 15 kontekstów na serwer Tomcat. (Wydaje mi się, że pomieszałem „instancje” i „konteksty” w moim poście - tutaj w biurze są często używane jako synonimy i zazwyczaj magicznie wiemy, o czym mówi kolega. Źle, naprawdę mi przykro.)

Aby lepiej wyjaśnić sytuację: diagramy, które zamieściłem, pokazują czasy odpowiedzi dwóch różnych kontekstów tej samej aplikacji na tej samej maszynie JVM. Wielki Wybuch wpływa na wszystkie konteksty na jednej maszynie JVM, ale nie dzieje się na drugim (kolejność, w jakiej eksplodują Tomkaty, jest losowa btw). Po hot-redeploymentu jeden kontekst na jednej instancji Tomcat staje się szalony (ze wszystkimi zabawnymi efektami ubocznymi, jak pozornie wolniejszy procesor w tym kontekście).

Całkowite obciążenie systemu jest raczej niskie. Jest to wewnętrzne oprogramowanie związane z działalnością biznesową, w którym uczestniczy jednocześnie około 30 aktywnych użytkowników. Żądania specyficzne dla aplikacji (dotknięcia serwera) wynoszą obecnie około 130 na minutę. Liczba pojedynczych żądań jest niska, ale same żądania często wymagają kilkuset selekcji do bazy danych, więc są raczej drogie. Ale zazwyczaj wszystko jest do przyjęcia. Aplikacja nie tworzy również dużych nieskończonych pamięci podręcznych - niektóre dane wyszukiwania są buforowane, ale tylko przez krótki czas.

Powyżej napisałem, że serwery, na których może działać aplikacja przez kilka lat. Wiem, że najlepszym sposobem znalezienia problemu byłoby ustalenie dokładnie, kiedy coś poszło nie tak po raz pierwszy i zobaczenie, co się zmieniło w tym przedziale czasowym (w samej aplikacji, powiązanych bibliotekach lub infrastrukturze), jednak problemem jest że nie wiemy, kiedy pojawiły się problemy. Nazwijmy to suboptymalnym (w sensie nieobecności) monitorowaniem aplikacji ...: - /

Wykluczyliśmy niektóre aspekty, ale aplikacja została zaktualizowana kilka razy w ciągu ostatnich miesięcy i dlatego np. nie można po prostu wdrożyć starszej wersji. Największą aktualizacją, która nie była zmianą funkcji, była zmiana z JSP na Facelets. Ale nadal „coś” musi być przyczyną wszystkich problemów, ale nie mam pojęcia, dlaczego na przykład Facelets powinny wpływać na czasy zapytań w czystym DB.

Kwarc

Jeśli chodzi o harmonogram Quartz: w sumie jest 8 zadań. Większość z nich działa tylko raz dziennie i ma do czynienia z synchronizacją dużych ilości danych (absolutnie nie „dużą” jak w „dużych danych dużych”; to tylko więcej niż przeciętny użytkownik widzi w swojej zwykłej codziennej pracy). Jednak te prace oczywiście przebiegają w nocy, a problemy pojawiają się w ciągu dnia. Pomijam tutaj szczegółową listę ofert pracy (jeśli jest to korzystne, mogę oczywiście podać więcej szczegółów). Kod źródłowy miejsc pracy nie został zmieniony w ciągu ostatnich miesięcy. Sprawdziłem już, czy eksplozje pokrywają się z zadaniami - jednak wyniki są w najlepszym razie niejednoznaczne. Powiedziałbym, że nie są wyrównane, ale ponieważ istnieje kilka zadań, które działają co minutę, nie mogę jeszcze tego wykluczyć. Moim zdaniem praca ciągła, która działa co minutę, jest dość niska, zazwyczaj sprawdzają, czy dane są dostępne (w różnych źródłach, DB, systemach zewnętrznych, kontach e-mail), a jeśli tak, zapisz je do bazy danych lub przepchnij do innego systemu .

Jednak obecnie umożliwiam rejestrowanie pojedynczego wykonania zadania, dzięki czemu mogę dokładnie zobaczyć znacznik czasu rozpoczęcia i zakończenia każdego pojedynczego zadania. Być może zapewnia to lepszy wgląd.

2013-02-28 Aktualizacja: Fazy i czas JSF

Ręcznie dodałem do aplikacji detektor phae JSF. Wykonałem przykładowe wywołanie (odświeżanie ajax) i to jest to, co mam (po lewej: normalna działająca instancja Tomcat, po prawej: instancja Tomcat po Big Bang - liczby zostały pobrane prawie jednocześnie z obu Tomcatów i są w milisekundach):

RESTORE_VIEW: 17 vs 46APPLY_REQUEST_VALUES: 170 vs 486PROCESS_VALIDATIONS: 78 vs 321UPDATE_MODEL_VALUES: 75 vs 307RENDER_RESPONSE: 1059 vs 4162

Odświeżanie ajax należy do formularza wyszukiwania i jego wyniku wyszukiwania. Istnieje również inne opóźnienie między najwyższym żądaniem filtra aplikacji, a przepływem w sieci zaczyna działać: jestFlowExecutionListenerAdapter który mierzy czas potrzebny w pewnych fazach przepływu sieci. Ten słuchacz zgłasza 1405 ms dla „Wysłanego żądania” (o ile wiem, że jest to pierwsze zdarzenie przepływu internetowego) z całkowitej liczby 1632 ms dla kompletnego żądania na niezniszczonym Tomcatu, dlatego szacuję około 200 ms narzutu.
Jednak w przypadku eksplodowanego serwera Tomcat raportuje 5332 ms dla przesłanego żądania (co oznacza, że ​​wszystkie fazy JSF mają miejsce w ciągu tych 5 sekund) z całkowitego czasu trwania żądania wynoszącego 7105 ms, dzięki czemu jesteśmy w stanie zaspokoić prawie 2 sekundy na wszystko, co zostało przesłane poza żądanie przepływu internetowego .
Poniżej filtru pomiarowego łańcuch filtrów zawiera aorg.ajax4jsf.webapp.BaseFilter, a następnie nazywany jest serwlet Spring.

2013-06-05 Aktualizacja: Wszystko, co działo się w ostatnich tygodniach

Niewielka i dość późna aktualizacja ... wydajność aplikacji jest wciąż do niczego, a zachowanie pozostaje nieregularne. Profilowanie nie pomogło jeszcze zbyt wiele, po prostu wygenerowało ogromną ilość danych, które trudno jest rozdzielić. (Spróbuj zagłębić się w dane dotyczące wydajności lub profiluj system produkcyjny ... westchnienie) Przeprowadziliśmy kilka testów (wyrywając niektóre części oprogramowania, wycofując inne aplikacje itp.) I faktycznie wprowadziliśmy pewne ulepszenia, które wpływają na całą aplikację. Domyślny tryb koloruEntityManager jestAUTO a podczas wyświetlania renderuje się wiele pobrań i selekcji, w tym zawsze sprawdza, czy konieczne jest spłukiwanie.
Zbudowaliśmy więc detektor fazy JSF, który ustawia tryb opróżnianiaCOMMIT podczasRENDER_RESPONSE. Poprawiło to ogólną wydajnośćdużo i wydaje się, że nieco złagodził problemy.

Jednak nasze monitorowanie aplikacji pozwala uzyskać całkowicie szalone wyniki i wydajność w niektórych kontekstach niektórych instancji tomcat. Jak akcja, która powinna zakończyć się w czasie krótszym niż jedna sekunda (a to faktycznie robi to po wdrożeniu), a to trwa dłużej niż cztery sekundy. (Te liczby są obsługiwane przez ręczne pomiary w przeglądarkach, więc to nie monitorowanie powoduje problemy).

Zobacz poniższy obrazek, na przykład:

Ten diagram pokazuje dwie instancje tomcatów działających w tym samym kontekście (co oznacza ten sam db, tę samą konfigurację, ten sam jar). Ponownie niebieska linia to czas, jaki zajmują czyste operacje odczytu DB (pobierz listę jednostek, iteruj nad nimi, leniwie pobieraj kolekcje i powiązane dane). Turkusowy i czerwony wiersz są mierzone przez renderowanie kilku widoków i wykonanie odświeżania ajax, odpowiednio. Dane renderowane przez dwa żądania w kolorze turkusowym i czerwonym są w większości takie same jak w przypadku niebieskiej linii.

Teraz około 0700 na instancji 1 (po prawej) następuje ogromny wzrost czasu czystego DB, który wydaje się mieć wpływ na rzeczywisty czas odpowiedzi renderowania, ale tylko na tomcat 1. Tomcat 0 jest w dużej mierze niezmieniony, więc nie może być spowodowany przez DB serwer lub sieć z obydwoma kociołkami działającymi na tym samym fizycznym sprzęcie. To musi być problem z oprogramowaniem w domenie Java.

Podczas moich ostatnich testów odkryłem coś interesującego: wszystkie odpowiedzi zawierają nagłówek „X-Powered-By: JSF / 1.2, JSF / 1.2”. Niektóre (odpowiedzi przekierowania wygenerowane przez WebFlow) mają nawet „JSF / 1.2” trzy razy.
Wyśledziłem części kodu, które ustawiają te nagłówki i przy pierwszym ustawieniu tego nagłówka powoduje to ten stos:

... at org.ajax4jsf.webapp.FilterServletResponseWrapper.addHeader(FilterServletResponseWrapper.java:384)
at com.sun.faces.context.ExternalContextImpl.<init>(ExternalContextImpl.java:131)
at com.sun.faces.context.FacesContextFactoryImpl.getFacesContext(FacesContextFactoryImpl.java:108)
at org.springframework.faces.webflow.FlowFacesContext.newInstance(FlowFacesContext.java:81)
at org.springframework.faces.webflow.FlowFacesContextLifecycleListener.requestSubmitted(FlowFacesContextLifecycleListener.java:37)
at org.springframework.webflow.engine.impl.FlowExecutionListeners.fireRequestSubmitted(FlowExecutionListeners.java:89)
at org.springframework.webflow.engine.impl.FlowExecutionImpl.resume(FlowExecutionImpl.java:255)
at org.springframework.webflow.executor.FlowExecutorImpl.resumeExecution(FlowExecutorImpl.java:169)
at org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.handle(FlowHandlerAdapter.java:183)
at org.springframework.webflow.mvc.servlet.FlowController.handleRequest(FlowController.java:174)
at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:925)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:920)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:827)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:641)
... several thousands ;) more

Za drugim razem ten nagłówek jest ustawiany przez

at org.ajax4jsf.webapp.FilterServletResponseWrapper.addHeader(FilterServletResponseWrapper.java:384)   
at com.sun.faces.context.ExternalContextImpl.<init>(ExternalContextImpl.java:131)   
at com.sun.faces.context.FacesContextFactoryImpl.getFacesContext(FacesContextFactoryImpl.java:108)   
at org.springframework.faces.webflow.FacesContextHelper.getFacesContext(FacesContextHelper.java:46)   
at org.springframework.faces.richfaces.RichFacesAjaxHandler.isAjaxRequestInternal(RichFacesAjaxHandler.java:55)   
at org.springframework.js.ajax.AbstractAjaxHandler.isAjaxRequest(AbstractAjaxHandler.java:19)   
at org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.createServletExternalContext(FlowHandlerAdapter.java:216)   
at org.springframework.webflow.mvc.servlet.FlowHandlerAdapter.handle(FlowHandlerAdapter.java:182)   
at org.springframework.webflow.mvc.servlet.FlowController.handleRequest(FlowController.java:174)   
at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:48)   
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:925)   
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)   
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:920)   
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:827)   
at javax.servlet.http.HttpServlet.service(HttpServlet.java:641)

Nie mam pojęcia, czy może to wskazywać na problem, ale nie zauważyłem tego w przypadku innych aplikacji działających na żadnym z naszych serwerów, więc może to również dostarczyć pewnych wskazówek. Naprawdę nie mam pojęcia, co robi ten kod ramowy (wprawdzie jeszcze tego nie zanurkowałem) ... może ktoś ma pomysł? A może wpadłem w ślepy zaułek?

dodatek

Mój kod testowy procesora składa się z pętli, która oblicza Math.tan i używa wartości wyniku do modyfikowania niektórych pól w instancji serwletu (nie jest tam zmienna / zsynchronizowana), a po drugie wykonuje kilka surowych obliczeń całkowitoliczbowych. Wiem, że to nie jest wyrafinowane, ale ... wydaje się, że coś pokazuje na listach przebojów, ale nie jestem pewien, co to pokazuje. Wykonuję aktualizacje pola, aby zapobiec optymalizacji przez HotSpot całego mojego cennego kodu;)

    long time2 = System.nanoTime();
    for (int i = 0; i < 5000000; i++) {
        double tan = Math.tan(i);
        if (tan < 0) {
            this.l1++;
        } else {
            this.l2++;
        }
    }

    for (int i = 1; i < 7500; i++) {
        int n = i;
        while (n != 1) {
            this.steps++;
            if (n % 2 == 0) {
                n /= 2;
            } else {
                n = n * 3 + 1;
            }
        }
    }
    // This execution time is written to the client.
    time2 = System.nanoTime() - time2;