Wolna aplikacja, częste zawieszanie się JVM z konfiguracjami jednoprocesorowymi i Java 12+

23

Mamy aplikację kliencką (ponad 10 lat rozwoju). Jego JDK został ostatnio zaktualizowany z OpenJDK 11 do OpenJDK 14. W przypadku systemu Windows 10 z pojedynczym procesorem (hiperwątkowanie wyłączone) (oraz w maszynach VirtualBox z tylko jednym dostępnym procesorem) aplikacja uruchamia się dość wolno w porównaniu z Javą 11. Co więcej, przez większość czasu używa 100% procesora. Możemy również odtworzyć problem z ustawieniem powinowactwa procesora tylko na jeden procesor ( c:\windows\system32\cmd.exe /C start /affinity 1 ...).

Niektóre pomiary po uruchomieniu aplikacji i wykonaniu zapytania przy minimalnej ręcznej interakcji w mojej maszynie VirtualBox:

  • OpenJDK 11.0.2: 36 sekund
  • OpenJDK 13.0.2: ~ 1,5 minuty
  • OpenJDK 13.0.2 z -XX:-UseBiasedLocking: 46 sekundami
  • OpenJDK 13.0.2 z -XX:-ThreadLocalHandshakes: 40 sekund
  • OpenJDK 14: 5-6 minut
  • OpenJDK 14 z -XX:-UseBiasedLocking: 3-3,5 minut
  • OpenJDK 15 EA Build 20: ~ 4,5 minuty

Zmieniono tylko używany JDK (i wspomniane opcje). ( -XX:-ThreadLocalHandshakesnie jest dostępny w Javie 14.)

Próbowaliśmy zarejestrować, co robi JDK 14 -Xlog:all=debug:file=app.txt:uptime,tid,level,tags:filecount=50.

Liczenie linii dziennika na każdą sekundę wydaje się dość płynne w OpenJDK 11.0.2:

$ cat jdk11-log/app* | grep "^\[" | cut -d. -f 1 | cut -d[ -f 2 | sort | uniq -c | sort -k 2 -n
  30710 0
  44012 1
  55461 2
  55974 3
  27182 4
  41292 5
  43796 6
  51889 7
  54170 8
  58850 9
  51422 10
  44378 11
  41405 12
  53589 13
  41696 14
  29526 15
   2350 16
  50228 17
  62623 18
  42684 19
  45045 20

Z drugiej strony, OpenJDK 14 wydaje się mieć ciekawe spokojne okresy:

$ cat jdk14-log/app* | grep "^\[" | cut -d. -f 1 | cut -d[ -f 2 | sort | uniq -c | sort -k 2 -n
   7726 0
   1715 5
  10744 6
   4341 11
  42792 12
  45979 13
  38783 14
  17253 21
  34747 22
   1025 28
   2079 33
   2398 39
   3016 44

Co dzieje się między sekundami 1-4, 7-10 i 14-20?

...
[0.350s][7248][debug][class,resolve        ] jdk.internal.ref.CleanerFactory$1 java.lang.Thread CleanerFactory.java:45
[0.350s][7248][debug][class,resolve        ] jdk.internal.ref.CleanerImpl java.lang.Thread CleanerImpl.java:117
[0.350s][7248][info ][biasedlocking        ] Aligned thread 0x000000001727e010 to 0x000000001727e800
[0.350s][7248][info ][os,thread            ] Thread started (tid: 2944, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.350s][6884][info ][os,thread            ] Thread is alive (tid: 6884).
[0.350s][6884][debug][os,thread            ] Thread 6884 stack dimensions: 0x00000000175b0000-0x00000000176b0000 (1024k).
[0.350s][6884][debug][os,thread            ] Thread 6884 stack guard pages activated: 0x00000000175b0000-0x00000000175b4000.
[0.350s][7248][debug][thread,smr           ] tid=7248: Threads::add: new ThreadsList=0x0000000017254500
[0.350s][7248][debug][thread,smr           ] tid=7248: ThreadsSMRSupport::free_list: threads=0x0000000017253d50 is freed.
[0.350s][2944][info ][os,thread            ] Thread is alive (tid: 2944).
[0.350s][2944][debug][os,thread            ] Thread 2944 stack dimensions: 0x00000000177b0000-0x00000000178b0000 (1024k).
[0.350s][2944][debug][os,thread            ] Thread 2944 stack guard pages activated: 0x00000000177b0000-0x00000000177b4000.
[0.351s][2944][debug][class,resolve        ] java.lang.Thread java.lang.Runnable Thread.java:832
[0.351s][2944][debug][class,resolve        ] jdk.internal.ref.CleanerImpl jdk.internal.misc.InnocuousThread CleanerImpl.java:135
[0.351s][2944][debug][class,resolve        ] jdk.internal.ref.CleanerImpl jdk.internal.ref.PhantomCleanable CleanerImpl.java:138
[0.351s][2944][info ][biasedlocking,handshake] JavaThread 0x000000001727e800 handshaking JavaThread 0x000000000286d800 to revoke object 0x00000000c0087f78
[0.351s][2944][debug][vmthread               ] Adding VM operation: HandshakeOneThread
[0.351s][6708][debug][vmthread               ] Evaluating non-safepoint VM operation: HandshakeOneThread
[0.351s][6708][debug][vmoperation            ] begin VM_Operation (0x00000000178af250): HandshakeOneThread, mode: no safepoint, requested by thread 0x000000001727e800

# no log until 5.723s

[5.723s][7248][info ][biasedlocking          ]   Revoked bias of currently-unlocked object
[5.723s][7248][debug][handshake,task         ] Operation: RevokeOneBias for thread 0x000000000286d800, is_vm_thread: false, completed in 94800 ns
[5.723s][7248][debug][class,resolve          ] java.util.zip.ZipFile$CleanableResource java.lang.ref.Cleaner ZipFile.java:715
[5.723s][7248][debug][class,resolve          ] java.lang.ref.Cleaner jdk.internal.ref.CleanerImpl$PhantomCleanableRef Cleaner.java:220
[5.723s][7248][debug][class,resolve          ] java.util.zip.ZipFile$CleanableResource java.util.WeakHashMap ZipFile.java:716
...

Druga pauza nieco później:

...
[6.246s][7248][info ][class,load              ] java.awt.Graphics source: jrt:/java.desktop
[6.246s][7248][debug][class,load              ]  klass: 0x0000000100081a00 super: 0x0000000100001080 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 5625 checksum: 0025818f
[6.246s][7248][debug][class,resolve           ] java.awt.Graphics java.lang.Object (super)
[6.246s][7248][info ][class,loader,constraints] updating constraint for name java/awt/Graphics, loader 'bootstrap', by setting class object
[6.246s][7248][debug][jit,compilation         ]   19       4       java.lang.Object::<init> (1 bytes)   made not entrant
[6.246s][7248][debug][vmthread                ] Adding VM operation: HandshakeAllThreads
[6.246s][6708][debug][vmthread                ] Evaluating non-safepoint VM operation: HandshakeAllThreads
[6.246s][6708][debug][vmoperation             ] begin VM_Operation (0x000000000203ddf8): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026b0800, is_vm_thread: true, completed in 1400 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026bb800, is_vm_thread: true, completed in 700 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026ef800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f0800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f1800, is_vm_thread: true, completed in 100 ns
[6.246s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f4800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000002768800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000276e000, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000017268800, is_vm_thread: true, completed in 100 ns
[6.247s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000001727e800, is_vm_thread: true, completed in 800 ns

# no log until 11.783s

[11.783s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000286d800, is_vm_thread: true, completed in 6300 ns
[11.783s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 5536442500 ns
[11.783s][6708][debug][vmoperation             ] end VM_Operation (0x000000000203ddf8): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[11.783s][7248][debug][protectiondomain        ] Checking package access
[11.783s][7248][debug][protectiondomain        ] class loader: a 'jdk/internal/loader/ClassLoaders$AppClassLoader'{0x00000000c0058628} protection domain: a 'java/security/ProtectionDomain'{0x00000000c058b948} loading: 'java/awt/Graphics'
[11.783s][7248][debug][protectiondomain        ] granted
[11.783s][7248][debug][class,resolve           ] sun.launcher.LauncherHelper java.awt.Graphics LauncherHelper.java:816 (reflection)
[11.783s][7248][debug][class,resolve           ] jdk.internal.reflect.Reflection [Ljava.lang.reflect.Method; Reflection.java:300
[11.783s][7248][debug][class,preorder          ] java.lang.PublicMethods$MethodList source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
...

Następnie trzeci:

...
[14.578s][7248][debug][class,preorder          ] java.lang.InheritableThreadLocal source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
[14.578s][7248][info ][class,load              ] java.lang.InheritableThreadLocal source: jrt:/java.base
[14.578s][7248][debug][class,load              ]  klass: 0x0000000100124740 super: 0x0000000100021a18 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 1338 checksum: 8013ed55
[14.578s][7248][debug][class,resolve           ] java.lang.InheritableThreadLocal java.lang.ThreadLocal (super)
[14.578s][7248][debug][jit,compilation         ]  699       3       java.lang.ThreadLocal::get (38 bytes)   made not entrant
[14.578s][7248][debug][vmthread                ] Adding VM operation: HandshakeAllThreads
[14.578s][6708][debug][vmthread                ] Evaluating non-safepoint VM operation: HandshakeAllThreads
[14.578s][6708][debug][vmoperation             ] begin VM_Operation (0x000000000203d228): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026b0800, is_vm_thread: true, completed in 1600 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026bb800, is_vm_thread: true, completed in 900 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026ef800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f0800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f1800, is_vm_thread: true, completed in 100 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x00000000026f4800, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000002768800, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000276e000, is_vm_thread: true, completed in 0 ns
[14.578s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x0000000017268800, is_vm_thread: true, completed in 0 ns
[14.579s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000001727e800, is_vm_thread: true, completed in 900 ns

# no log until 21.455s

[21.455s][6708][debug][handshake,task          ] Operation: Deoptimize for thread 0x000000000286d800, is_vm_thread: true, completed in 12100 ns
[21.455s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 6876829000 ns
[21.455s][6708][debug][vmoperation             ] end VM_Operation (0x000000000203d228): HandshakeAllThreads, mode: no safepoint, requested by thread 0x000000000286d800
[21.455s][7248][debug][class,resolve           ] sun.security.jca.Providers java.lang.InheritableThreadLocal Providers.java:39
[21.455s][7248][info ][class,init              ] 1251 Initializing 'java/lang/InheritableThreadLocal'(no method) (0x0000000100124740)
[21.455s][7248][debug][class,resolve           ] java.lang.InheritableThreadLocal java.lang.ThreadLocal InheritableThreadLocal.java:57
[21.456s][7248][debug][class,preorder          ] sun.security.jca.ProviderList source: C:\Users\example\AppData\Local\example\stable\jdk\lib\modules
[21.456s][7248][info ][class,load              ] sun.security.jca.ProviderList source: jrt:/java.base
[21.456s][7248][debug][class,load              ]  klass: 0x00000001001249a8 super: 0x0000000100001080 loader: [loader data: 0x0000000002882bd0 of 'bootstrap'] bytes: 11522 checksum: bdc239d2
[21.456s][7248][debug][class,resolve           ] sun.security.jca.ProviderList java.lang.Object (super)
...

Interesujące wydają się następujące dwie linie:

[11.783s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 5536442500 ns
[21.455s][6708][info ][handshake               ] Handshake "Deoptimize", Targeted threads: 11, Executed by targeted threads: 0, Total completion time: 6876829000 ns

Czy to normalne, że uściski dłoni trwały 5,5 i 6,8 sekundy?

Wystąpiło to samo spowolnienie (i podobne dzienniki) w przypadku aplikacji demo update4j (która jest całkowicie niezwiązana z naszą aplikacją) działającej z następującą komendą:

Z:\swing>\jdk-14\bin\java -Xlog:all=debug:file=app.txt:uptime,tid,level,tags:filecount=50 \
    -jar update4j-1.4.5.jar --remote http://docs.update4j.org/demo/setup.xml

Czego powinienem szukać, aby nasza aplikacja działała szybciej w konfiguracjach Windows 10 z jednym procesorem? Czy mogę to naprawić, zmieniając coś w naszej aplikacji lub dodając argumenty JVM?

Czy to błąd JDK, czy powinienem to zgłosić?

aktualizacja 2020-04-25:

O ile widzę pliki dziennika zawierają również dzienniki GC. Oto pierwsze dzienniki GC:

$ cat app.txt.00 | grep "\[gc"
[0.016s][7248][debug][gc,heap          ] Minimum heap 8388608  Initial heap 60817408  Maximum heap 1073741824
[0.017s][7248][info ][gc,heap,coops    ] Heap address: 0x00000000c0000000, size: 1024 MB, Compressed Oops mode: 32-bit
[0.018s][7248][info ][gc               ] Using Serial
[22.863s][6708][info ][gc,start                ] GC(0) Pause Young (Allocation Failure)
[22.863s][6708][debug][gc,heap                 ] GC(0) Heap before GC invocations=0 (full 0): def new generation   total 17856K, used 15936K [0x00000000c0000000, 0x00000000c1350000, 0x00000000d5550000)
...

Niestety nie wydaje się powiązany, ponieważ zaczyna się po trzeciej przerwie.

aktualizacja 2020-04-26:

Dzięki OpenJDK 14 aplikacja wykorzystuje 100% procesora na mojej maszynie VirtualBox (jednoprocesorowej) (działającej na procesorze i7-6600U). Maszyna wirtualna ma 3,5 GB pamięci RAM. Według Task Managera 40% + jest bezpłatne, a aktywność dysku wynosi 0% (myślę, że to oznacza brak zamiany). Dodanie kolejnego procesora do maszyny wirtualnej (i umożliwienie hiperwątkowości dla maszyn fizycznych) sprawia, że ​​aplikacja znów jest wystarczająco szybka. Zastanawiam się, czy to był celowy kompromis podczas opracowywania JDK w celu zmniejszenia wydajności na (rzadkich) maszynach jednoprocesorowych, aby przyspieszyć JVM na procesorach wielordzeniowych / hiperwątkowych?

java hang java-14 palacsint
źródło
3
Czy -Xlog:all=debugwłącza rejestrowanie GC? To byłoby moje pierwsze przypuszczenie o jakichkolwiek przerwach.
kichik
Czy próbowałeś uruchomić z profilerem i porównać wyniki? Myślę, że byłoby to naturalne.
Axel
1
sprawdź także komunikaty systemu Windows, wypróbuj inną kompilację dla jdk 14. Jeśli wszystko inne zawiedzie, eskalować jako problem?
Khanna111
1
@ Yan.F: OpenJDK 11 nie będzie obsługiwany na zawsze, czas przygotować nowe wersje i błędy. Ponadto wydaje się, że jest to błąd JDK - który można naprawić lub nie, ale może również pomóc innym. W każdym razie dla mnie to głównie ciekawość. Z drugiej strony chciałbym teraz powiedzieć, co powiedzieć naszym klientom jako minimalne wymagania systemowe naszej aplikacji.
palacsint,
1
@ Khanna111: Tak, właśnie napisałem to jako odpowiedź.
palacsint

Odpowiedzi:

6

Z mojego doświadczenia wynika, że ​​problemy z wydajnością JDK są związane głównie z jednym z następujących:

  • Kompilacja JIT
  • Konfiguracja maszyny wirtualnej (rozmiary sterty)
  • Algorytm GC
  • Zmiany w JVM / JDK, które niszczą znane dobrze działające aplikacje
  • (Aha, zapomniałem wspomnieć o ładowaniu klas ...)

Jeśli używasz tylko domyślnej konfiguracji JVM od OpenJDK11, być może powinieneś ustawić niektóre z bardziej widocznych opcji na stałe wartości, takie jak GC, wielkość sterty itp.

Być może jakieś narzędzie analizy graficznej może pomóc w zlokalizowaniu problemu. Jak Retrace, AppDynamics lub FlightRecorder i tym podobne. Dają one więcej informacji na temat ogólnego stanu sterty, cykli gc, pamięci RAM, wątków, obciążenia procesora i tak dalej w danym czasie, niż mogłyby zapewnić pliki dziennika.

Czy rozumiem poprawnie, że Twoja aplikacja zapisuje około 30710 wierszy do dziennika w ciągu pierwszej sekundy od uruchomienia (pod OpenJDK11)? Dlaczego w pierwszej sekundzie „tylko” pisze o 7k liniach pod OpenJDK14? Wydaje mi się, że to ogromna różnica dla aplikacji, która właśnie została uruchomiona na różnych maszynach JVM ... Czy jesteś pewien, że nie ma na przykład dużej ilości śladów stosu wyjątków zrzuconych do dziennika?
Inne liczby są czasem nawet wyższe, więc może spowolnienia są związane z rejestrowaniem wyjątków? A nawet zamiana, jeśli RAM się wyczerpie?
Właściwie myślę, że jeśli aplikacja nie zapisuje niczego w dzienniku, jest to oznaka płynnego działania bez problemów (chyba że w tym czasie zostanie całkowicie zamrożona). To, co dzieje się od sekund 12-22 (tutaj w przypadku OpenJDK14), bardziej mnie martwi ... logowane linie przechodzą przez dach ... dlaczego ?
A potem idzie w dół rejestrowanie wszystkich wartości niskich czasie około 1-2k linii ... co jest powodem , że ?? (cóż, może to GC uruchamia się w drugiej 22 i robi tabula rasa, która rozwiązuje niektóre rzeczy ...?)

Kolejną rzeczą może być twoje stwierdzenie o maszynach z pojedynczym procesorem. Czy oznacza to również „pojedynczy rdzeń” (Idk, może twoje oprogramowanie jest dostosowane do starszego sprzętu lub czegoś takiego)? A maszyny wirtualne z „pojedynczym procesorem” działają na tych komputerach? Ale zakładam, że mylę się co do tych założeń, ponieważ obecnie prawie wszystkie procesory są wielordzeniowe ... ale może zbadałbym problem wielowątkowości (impasu).

Antares
źródło
2
Nie używaj podpisów ani sloganów w swoich postach, powtarzające się „GL i HF” są uważane za hałas i odwracają uwagę od treści twojego postu tutaj. Aby uzyskać więcej informacji, zobacz meta.stackexchange.com/help/behavior .
Meagar
1
„Czy rozumiem poprawnie, że Twoja aplikacja zapisuje w dzienniku około 30710 wierszy w ciągu pierwszej sekundy od uruchomienia (pod OpenJDK11)?” - Tak, masz rację.
palacsint,
1
„Czy na pewno nie ma na przykład dużej ilości śladów stosu wyjątków zrzuconych do dziennika?” - Dziennik jest czysty, nie znalazłem tam nic dziwnego, aplikacja działa poprawnie (poza tym, że działa bardzo, bardzo wolno).
palacsint,
1
GC uruchamia się w 22. sekundzie, a potem aplikacja pozostaje powolna. Zaktualizowałem również pytanie. Należy pamiętać, że aplikacja demonstracyjna update4j ma również ten sam problem. Dziękuję za Twoją odpowiedź!
palacsint,
1
30k + linii logów w ciągu jednej sekundy jest dość ogromne ... nie zgadzasz się? Naprawdę zastanawiam się, co może być przydatne do zalogowania, aby zaakceptować tak dużą liczbę wierszy dziennika w tak krótkim czasie ... Czy próbowałeś całkowicie wyłączyć rejestrowanie i profilować aplikację w tym trybie? (Jestem ciekawy, ale może rejestrowanie naprawdę nie ma wpływu, ponieważ sugerujesz zachowanie update4j)
Antares
5

Ponieważ używa w 100% procesora „przez większość czasu” i zajmuje 10 razy dłużej (!) W Javie 14, oznacza to, że marnujesz 90% swojego procesora w Javie 14.

Może zabraknąć miejsca na stosie , ponieważ spędzasz dużo czasu w GC, ale wydaje się, że to wykluczyłeś.

Zauważyłem, że modyfikujesz opcję blokowania stronniczości i że robi to znaczącą różnicę. To mówi mi, że być może twój program wykonuje wiele równoczesnych prac w wielu wątkach. Możliwe, że twój program ma błąd współbieżności, który pojawia się w Javie 14, ale nie w Javie 10. To może również wyjaśniać, dlaczego dodanie innego procesora powoduje, że jest on dwa razy szybszy.

Błędy współbieżności często pojawiają się tylko wtedy, gdy masz pecha, a wyzwalaczem może być wszystko, na przykład zmiana organizacji hashap itp.

Po pierwsze, jeśli jest to wykonalne, poszukaj pętli, które mogą być zajęte - zamiast spać.

Następnie uruchom profiler w trybie próbkowania (zrobi to jvisualvm) i poszukaj metod, które zajmują znacznie większy procent całkowitego czasu niż powinny. Ponieważ wydajność spada 10 razy, wszelkie problemy w tym przypadku powinny naprawdę wyskoczyć.

Matt Timmermans
źródło
Wcześniejsze blokowanie było konieczne, ale obecnie nie tak bardzo, i proponuje się, aby domyślnie wyłączyć, a później usunąć: openjdk.java.net/jeps/374
JohannesB
2

Jest to interesująca kwestia i wymagałoby nieokreślonego wysiłku, aby ją zawęzić, ponieważ istnieje wiele kombinacji i kombinacji, które należy wypróbować, a dane zebrać i zestawić.

Wydaje się, że od jakiegoś czasu nie udało się tego rozwiązać. Być może trzeba będzie to eskalować.

EDYCJA 2: Ponieważ „ThreadLocalHandshakes” jest przestarzałe i możemy założyć, że blokowanie jest sprzeczne, sugerujemy próbę bez „UseBiasedLocking”, aby, mam nadzieję, przyspieszyć ten scenariusz.

Istnieją jednak sugestie, aby zebrać więcej danych i spróbować wyizolować problem.

  1. Przydziel więcej niż jeden rdzeń [Widzę, że próbowałeś i problem zniknął. Wydaje się, że jest to problem z wykonywaniem wątku / s wykluczający inne. Patrz nr 7 poniżej)
  2. Przydziel więcej sterty (być może wymagania wersji 14 są większe niż w przypadku wcześniejszych plików JDK)
  3. Przydziel więcej pamięci do Win 10 VB.
  4. Sprawdź komunikaty systemowe systemu operacyjnego (w twoim przypadku Win 10)
  5. Uruchom go w niewirtualizowanym Win 10.
  6. Wypróbuj inną wersję jdk 14
  7. Zrób zrzut wątku co (lub profil) kilka przedziałów czasu. Analizuj wyłącznie działający wątek. Być może istnieje ustawienie zapewniające sprawiedliwy podział czasu. Być może działa wątek o wyższym priorytecie. Co to za nić i co robi? W Linuksie można było statystycznie obserwować lekkie procesy (wątki) związane z procesem i jego stanem w czasie rzeczywistym. Coś podobnego na Win 10?
  8. Użycie procesora? 100% czy mniej? Ograniczony przez procesor lub pamięć? 100% procesora w wątkach serwisowych? Który wątek serwisowy?
  9. Czy wyraźnie ustawiłeś algo GC?

Osobiście byłem świadkiem problemów w wersjach związanych z GC, zmiany rozmiaru sterty, problemów ze zwirtualizowanymi kontenerami i tak dalej.

Wydaje mi się, że nie ma łatwej odpowiedzi na to pytanie, zwłaszcza, że ​​pytanie to pojawiło się już od jakiegoś czasu. Ale możemy spróbować, wszystkiego najlepszego i dać nam znać, co jest wynikiem niektórych z tych kroków izolacji.

EDYCJA 1: ze zaktualizowanego pytania wydaje się, że jest to związane z tym, że GC lub inny wątek usługi przejmuje pojedynczy rdzeń nierównomiernie (Hands-Local Handshakes)

Khanna111
źródło
Dodanie dodatkowego rdzenia procesora używanego do wyzwolenia przejścia z ergonomii Java w 32-bitowych systemach od klienta na serwer klasy vm z różnymi GC i warstwową kompilacją, jeśli nadal tak jest, może to tłumaczyć nagłe różnice w wydajności i zużyciu pamięci, tak JVM wydajność jest skomplikowana 😁
JohannesB
3
Ergonomia Java (ustawienia domyślne) są nadal różne dla 1 procesora (np .: -XX: + UseSerialGC) lub 2 procesorów (np .: G1GC, LoopStripMiningIter = 1000, ... ShortLoop = 100) Ale po upewnieniu się z -XX: + PrintFlagsFinal, że poprawiłem wszystkie parametry do tego samego lub podobnego działającego update4j nadal bardzo wolno uruchamiałem z jednym zamiast 2 procesorów z cmd.exe / C start / powinowactwem 0x1 (ale bardzo szybko z 0x3 - w ten sposób używając 2 cpus (1 + 10 binarnych)). Potwierdziłem, że nie możemy winić żadnego śmieciarza za pomocą Epsilon GC, który został zaprojektowany w celu uniknięcia narzutu GC. TieredCompilation jest jednak włączony
JohannesB
Widzę. Z Epsilon GC wydaje się, że był tak powolny. W takim przypadku status wątku i zrzuty pozwalające ocenić, gdzie utknie, mogą być dobrym rozwiązaniem. Zarówno w świecie Java, jak i OS (Linux, o ile pamiętam, to gcore)
Khanna111
2

TL; DR : To regresja OpenJDK.

Nie tylko to, ale mogłem odtworzyć ten problem w prostym świecie cześć:

public class Main {
    public static void main(String[] args) {
        System.out.println("Hello world");
    }
}

Użyłem tych dwóch plików wsadowych:

main-1cpu.bat, co ogranicza javaproces do jednego procesora:

c:\windows\system32\cmd.exe /C start /affinity 1 \
    \jdk-14\bin\java \
    -Xlog:all=trace:file=app-1cpu.txt:uptime,tid,level,tags:filecount=50 \
    Main

main-full.bat, javaproces może wykorzystywać oba procesory:

c:\windows\system32\cmd.exe /C start /affinity FF \
    \jdk-14\bin\java \
    -Xlog:all=trace:file=app-full.txt:uptime,tid,level,tags:filecount=50 \
    Main

(Różnice dotyczą affinitywartości i nazwy pliku dziennika. Zawijłem go, aby ułatwić czytanie, ale owijanie \prawdopodobnie nie działa w systemie Windows).

Kilka pomiarów w systemie Windows 10 x64 w VirtualBox (z dwoma procesorami):

PS Z:\main> Measure-Command { .\main-1cpu.bat }

...    
TotalSeconds      : 7.0203455
...


PS Z:\main> Measure-Command { .\main-full.bat }

...
TotalSeconds      : 1.5751352
...


PS Z:\main> Measure-Command { .\main-full.bat }

...
TotalSeconds      : 1.5585384
...


PS Z:\main> Measure-Command { .\main-1cpu.bat }

...
TotalSeconds      : 23.6482685
...

Wytworzone ścieżki śledzenia zawierają podobne przerwy, które można zobaczyć w pytaniu.

Uruchamianie Mainbez tracelogów jest szybsze, ale nadal widać różnicę między wersją z jednym procesorem a dwoma procesorami: ~ 4-7 sekund vs. ~ 400 ms.

Wysłałem te ustalenia na listę mailową hotspot-dev @ openjdk i tam deweloperzy potwierdzili, że jest to coś, z czym JDK mógłby sobie poradzić lepiej . W tym wątku możesz znaleźć rzekome poprawki . Mam nadzieję, że zostanie to naprawione w OpenJDK 15.

palacsint
źródło
Dzięki za opinie!
Antares
1

Zachowaj ostrożność przy logowaniu do wolnych dysków, spowoduje to spowolnienie aplikacji:

https://engineering.linkedin.com/blog/2016/02/ Eliminating-large-jvm-gc-pauses-caused-by-background-io-traffic

Ale wydaje się, że nie jest to przyczyną problemu, ponieważ procesor jest nadal zajęty i nie musisz czekać na bezpieczne przejście wszystkich wątków dzięki uzgadnianiu wątków lokalnych: https: // openjdk. java.net/jeps/312

Również niezwiązany bezpośrednio z twoim problemem, ale bardziej ogólnie, jeśli chcesz spróbować wycisnąć większą wydajność ze swojego sprzętu na czas uruchamiania, spójrz na AppCDS (udostępnianie danych klasowych):

https://blog.codefx.org/java/application-class-data-sharing/

JohannesB
źródło