A memóriámmal van a baj...

TL;DR: kernelt kellett frissíteni a Centos7 alatt, hogy megjavuljon a cgroups; mindenki más ártatlan az egészben.

Kicsit pontosabban: azt mondja a Java-alkalmazás, hogy `Cannot allocate memory`

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.

( enpassant v | 2020. 05. 13., sze – 07:57 )

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.

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.

( asch v | 2020. 05. 13., sze – 12:41 )

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.

( sibike | 2020. 05. 13., sze – 12:46 )

Én már jártam úgy, hogy max open files limitet ért el a JAVA alkalmazás, és memóriahibára panaszkodott.

( zolti v | 2020. 05. 13., sze – 15:53 )

Szerkesztve: 2020. 05. 13., sze – 15:54

A memóriámmal van a baj...

Az enyémmel is de már vagy 30 éve. :)

( lcsaszar v | 2020. 05. 13., sze – 20:00 )

Az enyémmel sincs, mert még emlékszem arra, hogy "Allo! Allo!"

( persicsb | 2020. 05. 13., sze – 23:53 )

"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ő.

( NevemTeve | 2020. 05. 14., cs – 10:51 )

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.

( NevemTeve | 2020. 05. 15., p – 05:27 )

Szerkesztve: 2020. 05. 15., p – 16:53

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?

( NevemTeve | 2020. 05. 18., h – 08:31 )

Szerkesztve: 2020. 05. 18., h – 13:34

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.

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

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
=

( NevemTeve | 2020. 05. 19., k – 14:01 )

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)

( NevemTeve | 2020. 05. 20., sze – 10:08 )

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.

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.

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

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.

( NevemTeve | 2020. 07. 07., k – 11:12 )

Szerkesztve: 2020. 07. 07., k – 20:10

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

É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.

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.

( NevemTeve | 2020. 07. 09., cs – 11:15 )

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?