Az egész történet nagyon egyszerű és világos (ahogy René mondja a Hallo! Hallo! epizódjainak elején), csak kicsit bonyolult elmagyarázni.
Van rögtön egy ilyen stacktrace:
Cannot allocate memory
java.base/java.io.FileOutputStream.open0(Native Method)
java.base/java.io.FileOutputStream.open(Unknown Source)
java.base/java.io.FileOutputStream.<init>(Unknown Source)
java.base/java.io.FileOutputStream.<init>(Unknown Source)
com.jcraft.jsch.ChannelSftp.get(ChannelSftp.java:979)
com.jcraft.jsch.ChannelSftp.get(ChannelSftp.java:888)
--
977 try{
978 if(mode==OVERWRITE){
979 fos=new FileOutputStream(_dst);
980 }
Ilyenkor elgondolkozunk, hogy milyen memória fogyhatott el a Native Method futása során. Sacc/kb malloc-ra gondolok, kicsit pontosabban:
src/java.base/share/native/libjava/jni_util.c:
JNU_GetStringPlatformChars(JNIEnv *env, jstring jstr, jboolean *isCopy)
Ami nem csinál mást, mint a fájlnevet natív stringgé alakítja. Namostan ez is nagyon szép dolog, de mekkora lehet egy fájlnév? Pontosabban mondva, ciklusban sok szép fájlt fogadott ez a metódus, mindegyiknek ugyanolyan hosszú volt a neve, miért ennél borult ki a bili?
Olyasmiken is gondolkozom, hogy ha egy `new` nem talál szabad helyet a JVM már lefoglalt és használatlan (magyarul: allocated, unused) memóriái között, akkor vagy malloc-ot hív, vagy kezdeményezi a szemétgyűjtést. Vagy mindkettőt, valamilyen sorrendben. Namostan a natív kódból hívott `JNU_GetStringPlatformChars` (illetve az általa hívott `getStringBytes`) csak malloc-ot hív, ami viszont nem tudom, mitől nem sikerül... Mondjuk attól, hogy ő is kifogyott az allocated, unused memóriából, ezért bepróbálkozott egy mmap-pal, ami nem sikerült. Mert beleszaladt egy `ulimit -v`-be.
Illetve nem mondtam még, hogy docker-ben vagyunk? Szóval dockerben vagyunk, az ulimit -Sv azt mondja, hogy unlimited, dehát tudjuk, hogy nem unlimited, csak legfejebb valami mást kellene megnézni, nem a `ulimit -v`-t
Szerk: köszönöm a segítő hozzászólásokat, google is talált mindenféléket, pl:
https://stackoverflow.com/questions/53451103/#answer-53624438
Közben találtam egy mellékszálat: a docker 'max memória' paramétere vajon hogyan alakul át ulimit-té? Így első pillantásra azt mondanám, sehogy. (Részlet a logból)
/usr/local/bin/getrlimit
ulimit RLIMIT max current
-v RLIMIT_AS unlimited unlimited
-c RLIMIT_CORE unlimited unlimited
-t RLIMIT_CPU unlimited unlimited
-d RLIMIT_DATA unlimited unlimited
-f RLIMIT_FSIZE unlimited unlimited
-l RLIMIT_MEMLOCK 64K 64K
-e RLIMIT_NICE 0 0
-n RLIMIT_NOFILE 1048576 1048576
-u RLIMIT_NPROC unlimited unlimited
-s RLIMIT_STACK unlimited 8M
-m RLIMIT_RSS unlimited unlimited
Szerk: most már akár a verziókat is meggyónhatom:
$ java -version
openjdk version "11.0.5" 2019-10-15
OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.5+10)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.5+10, mixed mode)
$ cat /etc/redhat-release
CentOS Linux release 7.8.2003 (Core)
Ma reggel is volt hiba; a `docker stats` folyamatosan ment, a memória nem ment 339MiB/384MiB/88.28% fölé (MEM USAGE/LIMIT/% oszlopk)
A program logjában ilyenek vannak (Runtime.getRuntime.totalMemory/freeMemory()):
hiba előtt: total memory: 129761280, free memory: 48257424 utána: total memory: 129761280, free memory: 28870232
A kettő között eltelt 23mp, és azalatt le-SFTP-zett a jcraft.jsch-val 300 fájlt. Jó kérdés, hogy `gc` futtatása segítene-e a free memory csökkenésén, illetve hogy ennek van-e egyáltalán köze az aktuális problémához.
Az alkalmazás indítása ilyen opciókkal történik: `-Xms128M -Xmx128M -XX:MaxMetaspaceSize=128m` -- nyilván lehet őket növelni, ha tudjuk, hogy miért és hogyan függenek össze a jelen gonddal.
- NevemTeve blogja
- A hozzászóláshoz be kell jelentkezni
Hozzászólások
Mivel az volt az utolsó csepp a pohárban.
Nem is az a legfontosabb kérdés, hogy mi volt az utolsó csepp. hanem az, hogy mi volt a legtöbb, ami megtöltötte a poharat. Gondolom valami leakel, azt kellene megszüntetni. Ha meg nem leakel semmi (bár ilyen sosincs :-), akkor meg nagyobb memóriát adni neki.
- A hozzászóláshoz be kell jelentkezni
Hja kérem, ha ez stabilan mindig ugyanakkor/ugyanúgy jelentkezne... Mivel nem így van, arra gondolok, hogy a `gc` keze is valahol benne van a dologban: ha az éppen futott akkortájt, és az esetleg úgy látta, hogy pár bájtot visszaadhat (`free`) a libc-nek, akkor a malloc-nak nem kellett `mmap`-ot hívni.
- A hozzászóláshoz be kell jelentkezni
Nem kell ugyanúgy, ugyanakkor jelentkeznie.
Készíttess heap dump-ot, főleg akkor, ha MemoryOut van.
- A hozzászóláshoz be kell jelentkezni
Java alatt többféleképpen lehet memóriát allokálni:
* Java Heap - Java menedzselt objektumok. Ezeket szabadítja fel a GC. Ennek mérete az -Xms, -Xmx kapcsolókkal adható meg. Most nem itt van a gond.
* Java által malloc allokált memória. Pl.: ByteBuffer.allocateDirect() hívással. Ennek az a pikantériája, hogy a sima malloc space-t foglalja, de csak akkor tud felszabadulni, ha a Java Heap-en a GC lefut. A mechanizmusa az, hogy amikor az őt tartalmazó Jave Heap-beli objektum felszabadul, akkor szabadítja fel a malloc-olt memóriát. Ezeknek a mennyiségét menedzseli a JVM, és ha túl sok, akkor kikényszerít egy GC-t. Ha ez a limit nagyobb, mint amennyit összesen foglalni tudunk, akkor fordulhat elő, hogy OOM-et kapunk. Mivel a Java Heap objektumok fogják a natív memória felszabadítását.
Pl.: -XX:MaxDirectMemorySize=64M
Ez az eset gyanús, hogy itt van a fent leírt hiba. A "teljes (Docker által adott) memória limit=Java Heap+Java Direct Memory Size+nem menedzselt malloc" igaz legyen.
* Natív komponensekből hívott malloc. Ez ugye a Java Direkt memória hívásokkal azonos pool-ból foglal, azonban ezeket a JVM semmiféleképpen nem tudja nyilvántartani. Amelyik komponens ilyen módon foglal natív memóriát, azt illik explicit dispose-olni. Ha ez rosszul van megtervezve, vagy a dispose elmarad, abból lehet memória leak. JRE libekben a rossz tervezés valószínűsége szerintem kicsi, a programban viszont elmaradhat véletlenül a dispose/close. Az újabb Java-kban az AutoClose minta rendelkezésre áll, ha csak lehet érdemes használni.
- A hozzászóláshoz be kell jelentkezni
Én már jártam úgy, hogy max open files limitet ért el a JAVA alkalmazás, és memóriahibára panaszkodott.
- A hozzászóláshoz be kell jelentkezni
A memóriámmal van a baj...
Az enyémmel is de már vagy 30 éve. :)
- A hozzászóláshoz be kell jelentkezni
Az enyémmel sosem volt baj, legalábbis nem emlékszem olyanra ;-)
- A hozzászóláshoz be kell jelentkezni
Az enyémmel sincs, mert még emlékszem arra, hogy "Allo! Allo!"
- A hozzászóláshoz be kell jelentkezni
"a docker 'max memória' paramétere vajon hogyan alakul át ulimit-té? Így első pillantásra azt mondanám, sehogy. (Részlet a logból)"
Valóban sehogy, ugyanis nem az ulimit eszköztárat használja a Docker, hanem a kernelben található cgroups (control groups) eszköztárat.
A kettő közötti rövid különbségekről: https://unix.stackexchange.com/questions/302938/about-ulimit-setrlimit-…
Totál más a kettő.
- A hozzászóláshoz be kell jelentkezni
Azért vannak jó hírek is rájöttem, hogy a Midnight Command a Meta , (ESC , vagy Alt+,) hatására kapcsolja át a Layout-ot. Amit könnyű véletlenül megnyomni, csak eddig sosem tudtam, hogy mi is volt az, amit véletlenül megnyomtam.
- A hozzászóláshoz be kell jelentkezni
Aztán van egy olyan, hogy `mtrace(3)` és `mtrace(1)`
Betoltam a derék termék alá, meglátjuk, mi lesz belőle. (Mondjuk most jól jönne, ha a SpringBoot nem ébredne fel félpercenként, hogy 'na, kell valami? tudok valamit tüsténkedni?'.)
Szerk: és már itt is egy eredmény:
*** Error 'java.io.IOException: Cannot run program "df": error=1886334817, Exec failed'
in system('df -h ./tmp')
Ebből az első rész a ProcessBuilder által dobott Exception toString-je, a hibakódot még nem találtam meg az errno tipikus értékei között, de még keresem.
van pl egy olyan, hogy
/openjdk-jdk11u/src/java.base/share/classes/java/lang/ProcessBuilder.java:1124
// It's much easier for us to create a high-quality error
// message than the low-level C code which found the problem.
throw new IOException(
"Cannot run program \"" + prog + "\""
+ (dir == null ? "" : " (in directory \"" + dir + "\")")
+ exceptionInfo,
cause);
Ő ezt hívja:
/openjdk-jdk11u/src/java.base/windows/classes/java/lang/ProcessImpl.java
És végül van a natív kód:
openjdk-jdk11u/src/java.base/unix/native/libjava/ProcessImpl_md.c: Java_java_lang_ProcessImpl_forkAndExec /openjdk-jdk11u/src/java.base/unix/native/libjava/childproc.c: int childProcess(void *arg)
Szerk: stacktrace javítása után:
Root Exception: java.io.IOException: error=811743284, Exec failed Following Excp: java.io.IOException: Cannot run program "df": error=811743284, Exec failed at java.base/java.lang.ProcessImpl.forkAndExec(Native Method) at java.base/java.lang.ProcessImpl.<init>(ProcessImpl.java:340) at java.base/java.lang.ProcessImpl.start(ProcessImpl.java:271) at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1107) at java.base/java.lang.ProcessBuilder.start(ProcessBuilder.java:1071)
Szóval az a csúnya szám az errno értéke, amikor a childProcess valamilyen hibára szalad. Esetleg ez a 'valamilyen hiba' nem állítja az errno-t, bár mindenki azt hitte, hogy minden hiba állítja az errno-t?
- A hozzászóláshoz be kell jelentkezni
Már-már azon is el lehetne gondolkodni, hogy a vfork hatására létrejön-e egy "új errno". Ugyebár az errno egy thread-specifikus adat, és amit mi `errno`-nak látunk, az igazából egy #define a `*errno_location()`-ra.
- A hozzászóláshoz be kell jelentkezni
Egy másik kontextusban is kipróbáltam valami mást, ez annyival lett rosszabb, hogy ebben még C++ is látszik lenni. Mondjuk jogos, igazi nagy szoqásokat a C++ használatával lehet elérni. (Most hadd nem mondjam azt, hogy a C++ a programnyelvek uefi-je.)
#0 0x00007ffff72281ed in vfprintf () from /lib/x86_64-linux-gnu/libc.so.6
#1 0x00007ffff7232ce7 in fprintf () from /lib/x86_64-linux-gnu/libc.so.6
#2 0x00007ffff7261323 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#3 0x00007ffff694ee91 in os::strdup(char const*, MemoryType) () from /local/opt/jdk-11.0.6+10/lib/server/libjvm.so
#4 0x00007ffff6ac3550 in Symbol::print_symbol_on(outputStream*) const () from /local/opt/jdk-11.0.6+10/lib/server/libjvm.so
#5 0x00007ffff68db4e7 in Method::print_short_name(outputStream*) () from /local/opt/jdk-11.0.6+10/lib/server/libjvm.so
#6 0x00007ffff638f7b4 in CompileTask::print(outputStream*, char const*, bool, bool) ()
from /local/opt/jdk-11.0.6+10/lib/server/libjvm.so
Szerk: úgy foglalnám össze, hogy sikerrel bebizonyítottuk, hogy a mtrace nem jól kombózik a multithread-del.
- A hozzászóláshoz be kell jelentkezni
De ez le is van írva: az mtrace() az nem thread-safe library.
Itt egy 13 éves hibajegy erről: https://bugzilla.redhat.com/show_bug.cgi?id=241665
mtrace is inherently thread unsafe due to the use of malloc hooks....
In summary, for multithreaded programs use valgrind instead of mtrace.
A dokumentációja szerint ( https://www.gnu.org/software/libc/manual/html_node/Tracing-malloc.html#… ):
MT-Unsafe env race:mtrace const:malloc_hooks init
- A hozzászóláshoz be kell jelentkezni
Jaja, valgrind is jó, a legegyszerűbb HelloWorld-re is azt kérdezi: Édes fiam, minek írkálsz te stackpointer alá?
==22164== Thread 2: ==22164== Invalid write of size 4 ==22164== at 0x88AA701: ??? ==22164== by 0x889C848: ??? ==22164== by 0x66CD911: JavaCalls::call_helper(JavaValue*, methodHandle const&, JavaCallArguments*, Thread*) (javaCalls.cpp==22164== by 0x66A5745: InstanceKlass::call_class_initializer(Thread*) (instanceKlass.cpp:1334) ==22164== by 0x66A5C8A: InstanceKlass::initialize_impl(Thread*) (instanceKlass.cpp:1002) ==22164== by 0x66A59F9: InstanceKlass::initialize_impl(Thread*) (instanceKlass.cpp:960) ==22164== by 0x6BDA99E: initialize_class (thread.cpp:1059) ==22164== by 0x6BDA99E: Threads::initialize_java_lang_classes(JavaThread*, Thread*) (thread.cpp:3591) ==22164== by 0x6BDB9A3: Threads::create_vm(JavaVMInitArgs*, bool*) (thread.cpp:3856) ==22164== by 0x67502A5: JNI_CreateJavaVM_inner (jni.cpp:3961) ==22164== by 0x67502A5: JNI_CreateJavaVM (jni.cpp:4052) ==22164== by 0x5273739: InitializeJVM (java.c:1527) ==22164== by 0x5273739: JavaMain (java.c:414) ==22164== by 0x505A063: start_thread (pthread_create.c:309) ==22164== Address 0x4150568 is on thread 2's stack ==22164== 4096 bytes below stack pointer =
- A hozzászóláshoz be kell jelentkezni
Kiegészítő érdekesség: bármilyen file-megnyitási hiba `FileNotFoundException`-t ad, de legalább zárójelben ott van a valódi ok:
Root Exception: java.io.FileNotFoundException: /test1 (Permission denied) Root Exception: java.io.FileNotFoundException: test2 (Is a directory)
- A hozzászóláshoz be kell jelentkezni
Van például egy `-X:MaxRAM=` opció. Ez állítólag összességében korlátoz több dolgot. Azért a tapasztalatok szerint nem mindent.
$ (ulimit -v 393216; java11 -XX:MaxRAM=128M Hello) Error occurred during initialization of VM Could not reserve enough space for code cache (245760K)
Szóval 384MB a címtartomány, a MaxRAM 128MB, a code-cache 240MB-t szeretne. A kis szerény.
- A hozzászóláshoz be kell jelentkezni
Nem tudom, miért gondolod, hogy Java 11-ben létezik a MaxRAM opció. Mert nem létezik.
https://docs.oracle.com/en/java/javase/11/tools/java.html
Java 13 óta létezik ez a HotSpot-specifikus beállítási lehetőség (más JVM-en, pl. IBM J9-en ez nem feltétlenül támogatott):
https://docs.oracle.com/en/java/javase/13/docs/specs/man/java.html
És ez a beállítás a heap méretét érinti csak, a nem heap memóriát nem.
- A hozzászóláshoz be kell jelentkezni
Onnan lehet tudni, hogy létezik, hogy ha hibás értéket adok meg neki, akkor panaszol rá (pl. 128M helyett 128MB). Ettől függetlenül úgy tűnik nekem, hogy ez az egész csodabazár valami derűs álomvilágban él, ahol kétszáz megabájt szóra sem érdemes, hiszen a RAM a fán terem, ugyebár...
Most éppen így megy, és (pillanatnyilag!) nem verdesi a fejét a cgroup felső korlátjába az alábbi beállításokkal:
docker.mem_limit=1024M JVM_OPTS=-Xms128M -Xmx128M -XX:MaxMetaspaceSize=128M -XX:ReservedCodeCacheSize=128M
Egyébként nyilván van valami korrekt módja is a cgroup lekérdezésének, én ezt tákoltam:
Tmp=$(cat /proc/$Pid/cgroup | grep memory); Cgroup=${Tmp#*/}
cd /sys/fs/cgroup/memory/$Cgroup/
while sleep 1; do
usage=$(cat memory.usage_in_bytes)
usage_max=$(cat memory.max_usage_in_bytes)
usage_lim=$(cat memory.limit_in_bytes)
failcnt=$(cat memory.failcnt)
swusage=$(cat memory.memsw.usage_in_bytes)
swusage_max=$(cat memory.memsw.max_usage_in_bytes)
swusage_lim=$(cat memory.memsw.limit_in_bytes)
swfailcnt=$(cat memory.memsw.failcnt)
printf "%s |%12d %12d %12d %12d |%12d %12d %12d %12d\n" "$(date +%Y%m%d.%H%M%S)" \
"$usage" "$usage_max" "$usage_lim" "$failcnt" \
"$swusage" "$swusage_max" "$swusage_lim" "$swfailcnt"
done
Most, hogy a mai futás megvolt, így állnak az értékek:
dátum idő akt max limit hiba memsw.akt memsw.max memsw.limit memsw.fail 20200520.114723 | 335757312 711954432 1073741824 0 | 335757312 711954432 2147483648 0
- A hozzászóláshoz be kell jelentkezni
Off: Vagyishát amkor a JVM ilyen malloc(1024MB) szerű jóságokat csinál, akkor azt nagyjából 'reserveAddressSpace' (vö: VirtualAlloc, ENAMP) értelemben teszi. Csak olyan nincs Unix-ban (hacsak a mmap-ot nem számítjuk). Helyette van az over-committed malloc.
- A hozzászóláshoz be kell jelentkezni
Nem tudom amúgy, hogy Java 11 óta, ha HotSpotot használsz, mi a probléma. Java 11 óta a VM felismeri, hogy konténerben fut, és eszerint viselkedik - figyelembe veszi a konténer memória és CPU korlátait. Ezt expliciten kell kikapcsolnod, lád a -XX:-UseContainerSupport
kapcsolót. Hátrány, hogy ez csak Linux és x64 környezetben értelmezett.
The VM now provides automatic container detection support, which allows the VM to determine the amount of memory and number of processors that are available to a Java process running in docker containers. It uses this information to allocate system resources. This support is only available on Linux x64 platforms. If supported, the default for this flag is
true
, and container support is enabled by default. It can be disabled with-XX:-UseContainerSupport
.
- A hozzászóláshoz be kell jelentkezni
Ilyesmi lenne:
$ java -version openjdk version "11.0.5" 2019-10-15 OpenJDK Runtime Environment AdoptOpenJDK (build 11.0.5+10) OpenJDK 64-Bit Server VM AdoptOpenJDK (build 11.0.5+10, mixed mode)
- A hozzászóláshoz be kell jelentkezni
Most legutóbb két módon monitoroztam a futást, egyrészt ps -o size,vsz,rss
értékeket másodprecenként, másrészt a fenti cgroup-os mágiával.
Azt véltem látni, hogy az első nem "szaladt el", csak a második... ebből akár arra is gondolhatok, hogy a kernelben a cgroups memóriaszámolása a problémás. A korszerű kernel-verzióm 3.10.0-957.5.1.el7.x86_64
, ha nagyon bátor lennék, kipróbálnám egy frissebb kernellel.
Szerk: egyelőre ennyit mertem előrelépni, tesztelése következik:
3.10.0-957.5.1.el7.x86_64 #1 SMP -> 3.10.0-1127.13.1.el7.x86_64 #1 SMP
- A hozzászóláshoz be kell jelentkezni
És továbbra is nő a /sys/fs/cgroup/memory/docker/$Cgroup/memory.usage_in_bytes
. Viszont a docker stats
az nem nő. Sem pedig a ps -o vsz,size,rss
.
Szerk: Most 5.7.7-1.el7.elrepo.x86_64 #1 SMP
, jelenség ugyanaz. Következő ötlet: docker szinten ne legyen limit, ócska korszerűtlen ulimit -vS 1048576
viszont legyen. Ha abba belepusztul, akkor a program a problémás, ha nem pusztul bele, akkor a cgroup valami mást mér/korlátoz, mint amit szerintem kellene mérnie/korlátoznia.
- A hozzászóláshoz be kell jelentkezni
Ezt nézd meg: https://stackoverflow.com/a/52870556/574661
Valószínűleg kernel memória az, ami nő, és nem a processz memóriája.
Ennek meg sok oka lehet.
- A hozzászóláshoz be kell jelentkezni
Köszönöm szépen, most beraktam azt is a mérésbe, az is nő, itt egy részlet a végéről:
dátum.idő memory. memory.kmem. memory. memory. memory.
usage_in_bytes usage_in_bytes max_usage_in_ limit_in_bytes failcnt
20200708.161448 | 2,466,721,792 66,473,984 2,486,222,848 5,368,709,120 0
20200708.161449 | 1,319,649,280 46,796,800 2,486,222,848 5,368,709,120 0
20200708.161450 | 595,038,208 6,193,152 2,486,222,848 5,368,709,120 0
Látszik, hogy volt egy pillanat (pontosabban két másodperc), amikor az összes memóriát majd 2GB-vel, a kernel memóriát 60MB-vel vágta vissza. Legalábbis a cgroups számítása szerint. Mondjuk leállított pár thread-et?
Szerk: Következő futásnál egyidejűleg ment a ps
is, de azon nem látszik ilyen nagy ugrás:
== cgroup ==
20200708.180517 | 2,490,847,232 67,858,432 2,491,183,104 5,368,709,120
20200708.180518 | 617,824,256 7,016,448 2,491,183,104 5,368,709,120
== ps ==
vsz size rss
20200708.180517 2,960,400 732,640 621,232
20200708.180518 2,962,448 739,660 628,476
De közben érvényben volt egy ulimit -Sd 1048576
is, abból nem lett gond/baj/bánat/nehézség.
- A hozzászóláshoz be kell jelentkezni
Ma azt mértem, hogy amikor a cgroups szerint hirtelen csökken a memóriahasználat, akkor mit csinál a program az `strace` szerint.
memory.usage memory.kmem.usage
--------------------------------------------------------------------
20200709.103742 | 2468872192 67342336 2469097472 5368709120
20200709.103743 | 2387853312 67059712 2469097472 5368709120
20200709.103744 | 1825976320 59265024 2469097472 5368709120
20200709.103745 | 1255059456 45334528 2469097472 5368709120
20200709.103746 | 690331648 21778432 2469097472 5368709120
20200709.103747 | 596033536 5943296 2469097472 5368709120
Hát kérem szépen, az eredmény az, hogy épp abban az időben törli az ideiglenes fájlokat a program (unlink(2)). Ebből arra következtetnék, hogy valamilyen disk-cache-t számol hozzá a cgroups a programomhoz. Ami nagyon rendes tőle, de hogyan beszéljem le róla, vagy mit kezdjek ezzel?
- A hozzászóláshoz be kell jelentkezni