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
 - 831 megtekintés
 
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
 
- A hozzászóláshoz be kell jelentkezni
 
- A hozzászóláshoz be kell jelentkezni