Cześć, mam program, w którym mierzę czas wykonania programu za pomocą metody System.nanoTime(). Wywołuję ją przed wykonaniem konkretnego kodu i po a następnie obliczam różnicę i dzielę tak aby otrzymać ms. W załączniku można zobaczyć rezultat. Oś pionowa to czas wykonania programu a pozioma "czas rzeczywisty". Zależy mi na tym aby jak najbardziej obciąć skoki czasu, nawet kosztem średniego czasu wykonania programu. Zmieniłem już GC na G1, MaxGCPauseMillis mam na 50ms a NewRatio=2, jednak nic to nie zmieniło. Tworzę jak najmniej obiektów, używam jak najwięcej typów prostych, nie wiem co jeszcze mogę poprawić.
0
1
Najstarsza i najskuteczniejsza metoda to zwalniać zasoby na bieżąco i zrezygnować z usług z GC.
Obiekty może małe ale dużo ?
1
Teorii na ten temat może być pewnie wiele. Natomiast:
- Nie ka nic złego w tworzeniu obiektów, które żyją krótko - każdy GC w Javie jest PPD to zoptymalizowany
- 50ms to tylko wskazanie, może G1 się po prostu nie wyrabia. Spróbuj ustalić większa wartość i zobacz wtedy.
- Wrzuć gc.loga do jakiegoś GCeasy
- Sprawdź wykres zajętości heapa
1
Podstawowe pytanie, ten skoki to wynikają z GC czy czegoś innego?
0
yarel napisał(a):
Podstawowe pytanie, ten skoki to wynikają z GC czy czegoś innego?
W kodzie nie mam żadnych pauz ani oczekiwania na żadne dane. Ogólnie to wygląda to tak:
before = System.nanoTime();
controlValue = pid.calculateControlValue(m.readHoldingRegisters(slaveId, 1, 1)[0]);
m.writeSingleRegister(slaveId, 0, (int) controlValue);
m.writeSingleCoil(slaveId, 0, false);
now = System.nanoTime();
result = (now - before) / 1000000;
, gdzie m jest obiektem klasy Modbus z biblioteki JLibModbus służącym do komunikacji za pomocą protokołu Modbus TCP a pid jest obiektem do obliczania wartości za pomocą dodawania odejmowania i mnożenia, nie ma tam nic skomplikowanego.
3
Java posiada dwa wbudowane GC o niskich pauzach:
https://openjdk.java.net/projects/shenandoah/
https://openjdk.java.net/projects/zgc/
W twoim przypadku jednak zamiast próbować walczyć z pauzami zaczął bym je po prostu wykrywać i ignorować wyniki testów podczas których odpalił się GC. Do wykrywania liczby cykli GC możesz użyć JMXa: https://docs.oracle.com/javase/8/docs/api/java/lang/management/GarbageCollectorMXBean.html W JVMie może być kilka rodzajów GCków odpalonych (np GC young i GC old). Sprawdź który rodzaj GC ma zauważalny wpływ na skoki czasowe i tylko ten rodzaj GC bierz pod uwagę przy ignorowaniu wyników testów.
Kojarzę jedno narzędzie, które chwali się wykrywaniem aktywności GC - https://scalameter.github.io/ (jest jednak napisane w Scali):
automatically eliminate noise due to JIT compilation, garbage collection or undesired heap allocation patterns
1
infantylny napisał(a):
...
W kodzie nie mam żadnych pauz ani oczekiwania na żadne dane. Ogólnie to wygląda to tak:
before = System.nanoTime(); controlValue = pid.calculateControlValue(m.readHoldingRegisters(slaveId, 1, 1)[0]); m.writeSingleRegister(slaveId, 0, (int) controlValue); m.writeSingleCoil(slaveId, 0, false); now = System.nanoTime(); result = (now - before) / 1000000;, gdzie m jest obiektem klasy Modbus z biblioteki JLibModbus służącym do komunikacji za pomocą protokołu Modbus TCP a pid jest obiektem do obliczania wartości za pomocą dodawania odejmowania i mnożenia, nie ma tam nic skomplikowanego.
Nie twierdzę, że nie jest to GC, ale sprawdzałeś jakie masz wahania na poszczególnych operacjach readHoldingRegisters/writeSingleRegister/writeSingleCoil i wiesz, że nie ma zależności między wahaniem, a wywolaniem konkretnej operacji?
1
Spróbuj z Epsilonem.
https://blogs.oracle.com/javamagazine/epsilon-the-jdks-do-nothing-garbage-collector
1
yarel napisał(a):
infantylny napisał(a):
Nie twierdzę, że nie jest to GC, ale sprawdzałeś jakie masz wahania na poszczególnych operacjach readHoldingRegisters/writeSingleRegister/writeSingleCoil i wiesz, że nie ma zależności między wahaniem, a wywolaniem konkretnej operacji?
Szedłbym tą drogą. Spróbowałbym sprawdzić czasy zapisu i odczytu do sterownika/urządzenia które tam masz, może to jest powodem takich różnic czasowych?
Jak miałem trochę doświadczenia z urządzeniami działającymi po modbusie to czas odpowiedzi bywa różny.
Może coś takiego i wyświetlić czasy readTime, calculationTime i writeTime?
before = System.nanoTime();
int value = m.readHoldingRegisters(slaveId, 1, 1)[0];
long readTime = before - System.nanoTime();
before = System.nanoTime();
controlValue = pid.calculateControlValue(value);
long calculationTime = before - System.nanoTime();
before = System.nanoTime();
m.writeSingleRegister(slaveId, 0, (int) controlValue);
m.writeSingleCoil(slaveId, 0, false);
long writeTime = before - System.nanoTime();
Ewentualnie przeprowadzić taką symulację, tzn odseparować się od zapisu/odczytu po modbusie i sprawdzić sam czas obliczania wartości?
int[] intArray = new int[] {4,5,6,7,8, ...};
...
before = System.nanoTime();
controlValue = pid.calculateControlValue(intArray[i++]);
//m.writeSingleRegister(slaveId, 0, (int) controlValue);
//m.writeSingleCoil(slaveId, 0, false);
now = System.nanoTime();
result = (now - before) / 1000000;
1
Zawsze można też włączyć logowanie aktywności GC (są do tego przełączniki w JVMie, wystarczy poguglać) i nawet ręcznie porównać z czasami wystąpienia pików na wykresie.
0
Nie wiem czy robię coś nie tak, ale po zmianie GC powinny nastąpić chyba jakieś różnice w wywołaniach GC? Z tego co wiem to np. po zmianie Parallel na CSM skoki powinny być mniejsze, ale wywołania GC częstsze a z moich obserwacji tak nie wynika więc coś najprawdopodobniej robię źle, tylko niestety nie wiem co. Na zdjęciach można zobaczyć czasy wywołania poszczególnych funkcji oraz uruchamianie GC w trakcie ich działania. jednak na każdym wykresie wygląda to bardzo podobnie, praktycznie nie widać różnicy.
1
Ja tam widzę różnice. Zamiast oceniać coś na oko włącz logowanie zdarzeń GC i potem załaduj je do analizatora logów GC.
Próbowałeś wykrywać cykle GC i ignorować wyniki testów podczas których te cykle się odpaliły?
1
Z tych screenów wygląda że czas wykonania wzrasta głównie w zapisie. Często jest to dwu-krotność, trzykrotność - jest możliwość że akurat sterownik/urządzenie nie wyrabia się w skanie i zapis jest wykonywany dopiero w drugim, trzecim skanie?
Na tą chwilę nie skupiałbym się jeszcze na GC i sprawdził jak wygląda komunikacja po TCP. Zainstalowałbym wiresharka i sprawdził jak wyglądają kolejne pakiety, a przede wszystkim jak wygląda różnica czasu pomiędzy żądaniem a odpowiedzią.
Jak u Ciebie ze znajmością wireshark i modbusa? Potrzebujesz w tym pomocy?
0
Włączyłem zapisywanie logów GC i nie rozumiem dlaczego w logach w ogóle nie mam pokazane uruchamianie GC. W przypadku ręcznego uruchamiania GC za pomocą System.gc() jest już wszystko okej. Na wykresie 1 można też zauważyć, że akurat przy tym uruchomieniu aplikacji (bez System.gc()) GC w ciągu ponad 3 minut uruchamiał się bardzo rzadko, bo raczej nie jest możliwe, żeby GC w ogóle się nie uruchomił w ciągu 3 minut a za opóźnienia odpowiadała sama komunikacja po Modbus TCP?. JAVA_TOOL_OPTIONS ustawiam z parametrem -XX:MaxGCPauseMillis=50 -XX:+UseParallelGC -Xlog:gc*:file=C:\Users\Mateusz\Desktop\GCLogs\GClogs.log
1
bo raczej nie jest możliwe, żeby GC w ogóle się nie uruchomił w ciągu 3 minut a za opóźnienia odpowiadała sama komunikacja po Modbus TCP
Oczywiście że jest mozliwe. Co więcej, ja bardzo wątpie żeby to GC powodowało ci tutaj problemy... Bo nawet jak poleci GC, to o ile ten twój kod nie robi skomplikowanych i dużych alokacji, to GC będzie trwało bardzo krótko.
2
Załadowałem GClogs2.log do https://gceasy.io/ (strona znaleziona na szybko w Guglu) i wychodzi na to, że sumaryczna ilość śmiecia wygenerowana przez te 3 min i 15 sekund to 243 megabajty, a maksymalna ilość zajętej pamięci to ledwo 6 megabajtów. Prawdopodobnie jest tak, że te 243 megabajty mieszą się spokojnie w jednej młodej generacji i dlatego nie ma nawet powodu by odpalić chociaż jeden niewymuszony cykl GC.
0
Na wstępie chciałbym wszystkim podziękować za pomoc. Tak jak @Shalom napisał GC nie ma tu nic do rzeczy a wszystkiemu jest winna sama komunikacja. Za radą @Wilktar odpaliłem Wiresharka i podejrzałem jakie są informacje wysyłane i w jakich odstępach czasowych. W pliku "wireSharkJavaModbusTCP" można zobaczyć, że przy standardowym obciążeniu sieciowym, z włączonym wifi i paroma zakładkami w Firefoxie, odczyt i zapis informacji za pomocą Modbusa TCP zajmuje około 30ms. W pliku "wireSharkMatlabModbusTCP" gdzie badałem czas przesyłania i odbierania informacji pomiędzy symulatorem Modbus a Matlabem z próbkowaniem 2s czas ten wynosi w przybliżeniu 20 ms. W pliku tym można również zauważyć dość duży skok zaznaczony na czerwono wynikający być może z chwilowego większego obciążenia sieci. W pliku "eleganckoDziala" przy wyłączonym wifi (w celu obniżenia jak najbardziej ruchu sieciowego) i włączonym Matlabie, Eclipse, Wireshark i symulatorze Modbus nie występują praktycznie żadne duże opóźnienia przez aż 30 minut. W ciągu tych 30 minut GC uruchomił się tylko 2 razy i trwał 9ms oraz 3ms. Jeszcze raz dziękuję za pomoc i wesołych świąt :)