Bug 2009797
| Summary: | Memory leak in invoker.c invoker_completeInvokeRequest() during JDI operations [rhel-7.9.z] | ||
|---|---|---|---|
| Product: | Red Hat Enterprise Linux 7 | Reporter: | Simeon Andreev <simeon.andreev> |
| Component: | java-11-openjdk | Assignee: | Roman Kennke <rkennke> |
| Status: | CLOSED CURRENTRELEASE | QA Contact: | OpenJDK QA <java-qa> |
| Severity: | high | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 7.9 | CC: | ahughes, kpfleming, loskutov, mmillson, pmikova, rkennke |
| Target Milestone: | rc | ||
| Target Release: | --- | ||
| Hardware: | x86_64 | ||
| OS: | Linux | ||
| Whiteboard: | |||
| Fixed In Version: | java-11-openjdk-11.0.16.0.8-1.el7_9 | Doc Type: | If docs needed, set a value |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2022-07-21 16:53:48 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
Oddly even with this change, I still see a leak. It is much smaller, but its growing:
diff --git a/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c b/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c
index 8e2981d9fa..6b3215c420 100644
--- a/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c
+++ b/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c
@@ -840,6 +840,7 @@ invoker_completeInvokeRequest(jthread thread)
(void)outStream_writeObjectTag(env, &out, exc);
(void)outStream_writeObjectRef(env, &out, exc);
outStream_sendReply(&out);
+ outStream_destroy(&out);
}
/*
1200 JDI operations, unpatched JDK 11:
[1075200 bytes leaked]
je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2))
je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289)
os::malloc (/data/git/jdk11/src/hotspot/share/runtime/os.cpp:697)
os::malloc (/data/git/jdk11/src/hotspot/share/runtime/os.cpp:660 (discriminator 3))
JvmtiEnvBase::allocate (/data/git/jdk11/src/hotspot/share/prims/jvmtiEnvBase.hpp:195)
JvmtiEnv::Allocate (/data/git/jdk11/src/hotspot/share/prims/jvmtiEnv.cpp:126)
jvmti_Allocate (/data/git/jdk11/build/linux-x86_64-normal-server-slowdebug/hotspot/variant-server/gensrc/jvmtifiles/jvmtiEnter.cpp:341)
jvmtiAllocate (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/util.c:1794)
bagCreateBag (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/bag.c:45)
commonInit (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:50)
outStream_initReply (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:75)
invoker_completeInvokeRequest (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c:838)
handleReportInvokeDoneCommand (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:568)
handleCommand (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:618)
commandLoop (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:713)
JvmtiAgentThread::call_start_function (/data/git/jdk11/src/hotspot/share/prims/jvmtiImpl.cpp:85)
JvmtiAgentThread::start_function_wrapper (/data/git/jdk11/src/hotspot/share/prims/jvmtiImpl.cpp:79)
JavaThread::thread_main_inner (/data/git/jdk11/src/hotspot/share/runtime/thread.cpp:1752)
JavaThread::run (/data/git/jdk11/src/hotspot/share/runtime/thread.cpp:1732)
thread_native_entry (/data/git/jdk11/src/hotspot/os/linux/os_linux.cpp:698)
start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:308)
?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113)
1200 JDI operations, patched JDK 11:
[96000 bytes leaked]
je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2))
je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289)
os::malloc (/data/git/jdk11/src/hotspot/share/runtime/os.cpp:697)
os::malloc (/data/git/jdk11/src/hotspot/share/runtime/os.cpp:660 (discriminator 3))
JvmtiEnvBase::allocate (/data/git/jdk11/src/hotspot/share/prims/jvmtiEnvBase.hpp:195)
JvmtiEnv::Allocate (/data/git/jdk11/src/hotspot/share/prims/jvmtiEnv.cpp:126)
jvmti_Allocate (/data/git/jdk11/build/linux-x86_64-normal-server-slowdebug/hotspot/variant-server/gensrc/jvmtifiles/jvmtiEnter.cpp:341)
jvmtiAllocate (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/util.c:1794)
createNode (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/commonRef.c:94)
newCommonRef (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/commonRef.c:328)
commonRef_refToID (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/commonRef.c:428)
outStream_writeObjectRef (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:219)
outStream_writeValue (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:344)
invoker_completeInvokeRequest (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c:839)
handleReportInvokeDoneCommand (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:568)
handleCommand (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:618)
commandLoop (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:713)
JvmtiAgentThread::call_start_function (/data/git/jdk11/src/hotspot/share/prims/jvmtiImpl.cpp:85)
JvmtiAgentThread::start_function_wrapper (/data/git/jdk11/src/hotspot/share/prims/jvmtiImpl.cpp:79)
JavaThread::thread_main_inner (/data/git/jdk11/src/hotspot/share/runtime/thread.cpp:1752)
JavaThread::run (/data/git/jdk11/src/hotspot/share/runtime/thread.cpp:1732)
thread_native_entry (/data/git/jdk11/src/hotspot/os/linux/os_linux.cpp:698)
start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:308)
?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113)
180 JDI operations, patched JDK 11:
[14400 bytes leaked]
je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2))
je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289)
os::malloc (/data/git/jdk11/src/hotspot/share/runtime/os.cpp:697)
os::malloc (/data/git/jdk11/src/hotspot/share/runtime/os.cpp:660 (discriminator 3))
JvmtiEnvBase::allocate (/data/git/jdk11/src/hotspot/share/prims/jvmtiEnvBase.hpp:195)
JvmtiEnv::Allocate (/data/git/jdk11/src/hotspot/share/prims/jvmtiEnv.cpp:126)
jvmti_Allocate (/data/git/jdk11/build/linux-x86_64-normal-server-slowdebug/hotspot/variant-server/gensrc/jvmtifiles/jvmtiEnter.cpp:341)
jvmtiAllocate (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/util.c:1794)
createNode (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/commonRef.c:94)
newCommonRef (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/commonRef.c:328)
commonRef_refToID (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/commonRef.c:428)
outStream_writeObjectRef (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:219)
outStream_writeValue (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:344)
invoker_completeInvokeRequest (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c:839)
handleReportInvokeDoneCommand (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:568)
handleCommand (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:618)
commandLoop (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:713)
JvmtiAgentThread::call_start_function (/data/git/jdk11/src/hotspot/share/prims/jvmtiImpl.cpp:85)
JvmtiAgentThread::start_function_wrapper (/data/git/jdk11/src/hotspot/share/prims/jvmtiImpl.cpp:79)
JavaThread::thread_main_inner (/data/git/jdk11/src/hotspot/share/runtime/thread.cpp:1752)
JavaThread::run (/data/git/jdk11/src/hotspot/share/runtime/thread.cpp:1732)
thread_native_entry (/data/git/jdk11/src/hotspot/os/linux/os_linux.cpp:698)
start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:308)
?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113)
See https://bugzilla.redhat.com/show_bug.cgi?id=2010221 for the remaining big leak reported by jemalloc. Looking at the out stream destroy call, it seems to not clear its "ids" bag if the sent flag is sent (or if an error occurred).
So likely this sequence leaks memory:
(void)outStream_writeObjectRef(env, &out, exc);
outStream_sendReply(&out);
outStream_destroy(&out);
I didn't see anything in the outStream_sendReply() method that clears memory, I assume the motivation for the incomplete destroy method is something else. When I tried to unconditionally free the bag elements, the debugging from Eclipse didn't work (it didn't reach the snippet breakpoint).
So no idea about this leak, I hope an OpenJDK developer can look into it.
Opened tickets for the other leaks we found: * https://bugzilla.redhat.com/show_bug.cgi?id=2010817 * https://bugzilla.redhat.com/show_bug.cgi?id=2010850 Can you please test if the fix: http://cr.openjdk.java.net/~rkennke/patch.txt solves the problem? This is the fix for bz 2010221 and it looks like it might affect this problem too. Thanks, Roman (In reply to Roman Kennke from comment #10) > Can you please test if the fix: > > http://cr.openjdk.java.net/~rkennke/patch.txt > > solves the problem? This is the fix for bz 2010221 and it looks like it > might affect this problem too. > > Thanks, > Roman jemalloc still reports the leak with the change: diff --git a/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c b/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c index 8e2981d9fa..db92663610 100644 --- a/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c +++ b/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c @@ -241,6 +241,10 @@ deleteGlobalArgumentRefs(JNIEnv *env, InvokeRequest *request) argIndex++; argumentTag = nextArgumentTypeTag(&cursor); } + + JDI_ASSERT_MSG(request->methodSignature != NULL, "methodSignature is NULL"); + jvmtiDeallocate(request->methodSignature); + request->methodSignature = NULL; } static jvmtiError @@ -281,6 +285,7 @@ fillInvokeRequest(JNIEnv *env, InvokeRequest *request, /* * Squirrel away the method signature */ + JDI_ASSERT_MSG(request->methodSignature == NULL, "Request methodSignature not null"); error = methodSignature(method, NULL, &request->methodSignature, NULL); if (error != JVMTI_ERROR_NONE) { return error; [3225600 bytes leaked] je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2)) je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289) os::malloc (/data/git/jdk11/./src/hotspot/share/runtime/os.cpp:682) JvmtiEnv::Allocate (/data/git/jdk11/./src/hotspot/share/prims/jvmtiEnv.cpp:127) jvmti_Allocate (/data/git/jdk11/./build/linux-x86_64-normal-server-release/hotspot/variant-server/gensrc/jvmtifiles/jvmtiEnter.cpp:342) jvmtiAllocate (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/util.c:1808) bagCreateBag (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/bag.c:45) commonInit (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:50) outStream_initReply (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:75) invoker_completeInvokeRequest (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/invoker.c:843) commandLoop (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:713) JvmtiAgentThread::start_function_wrapper (/data/git/jdk11/./src/hotspot/share/prims/jvmtiImpl.cpp:80) JavaThread::thread_main_inner (/data/git/jdk11/./src/hotspot/share/runtime/thread.cpp:1863) Thread::call_run (/data/git/jdk11/./src/hotspot/share/runtime/thread.cpp:381) thread_native_entry (/data/git/jdk11/./src/hotspot/os/linux/os_linux.cpp:794) start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:307) ?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:111) [230400 bytes leaked] je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2)) je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289) os::malloc (/data/git/jdk11/./src/hotspot/share/runtime/os.cpp:682) JvmtiEnv::Allocate (/data/git/jdk11/./src/hotspot/share/prims/jvmtiEnv.cpp:127) jvmti_Allocate (/data/git/jdk11/./build/linux-x86_64-normal-server-release/hotspot/variant-server/gensrc/jvmtifiles/jvmtiEnter.cpp:342) jvmtiAllocate (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/util.c:1808) bagCreateBag (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/bag.c:40) commonInit (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:50) outStream_initReply (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:75) invoker_completeInvokeRequest (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/invoker.c:843) commandLoop (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:713) JvmtiAgentThread::start_function_wrapper (/data/git/jdk11/./src/hotspot/share/prims/jvmtiImpl.cpp:80) JavaThread::thread_main_inner (/data/git/jdk11/./src/hotspot/share/runtime/thread.cpp:1863) Thread::call_run (/data/git/jdk11/./src/hotspot/share/runtime/thread.cpp:381) thread_native_entry (/data/git/jdk11/./src/hotspot/os/linux/os_linux.cpp:794) start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:307) ?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:111) I applied the change on top of master branch: https://github.com/openjdk/jdk11u Top commit: commit 1453335629e17be9a3b8718ad0c326f26cc68cd7 (HEAD -> master, tag: jdk-11.0.14-ga, tag: jdk-11.0.14+9, origin/master, origin/HEAD) Author: Martin Balao <mbalao> Date: Thu Jul 18 08:53:06 2019 +0800 8217375: jarsigner breaks old signature with long lines in manifest 8268795: Enhance digests of Jar files Reviewed-by: mbaesken Backport-of: b6d1b1e0853a66ad34ccafea0339a69753b9a782 I compiled with: bash ./configure make clean make images I'm using the JDK at: ./build/linux-x86_64-normal-server-release/images/jdk/ Could you try this: https://github.com/rkennke/jdk11u-dev/tree/memleak-invoker2 It simply adds outStream_destroy(&out) to properly destroy the output stream. Thanks, Roman (In reply to Roman Kennke from comment #12) > Could you try this: > > https://github.com/rkennke/jdk11u-dev/tree/memleak-invoker2 > > It simply adds outStream_destroy(&out) to properly destroy the output stream. > > Thanks, > Roman I think this patch works to an extent. Without the fix, I see those 3 top leaks reported by jemalloc (also the only reported leaks with invoker_completeInvokeRequest() on the stack trace): [3225600 bytes leaked] je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2)) je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289) os::malloc (:?) JvmtiEnv::Allocate (:?) jvmti_Allocate (jvmtiEnter.cpp:?) jvmtiAllocate (:?) bagCreateBag (:?) commonInit (outStream.c:?) outStream_initReply (:?) invoker_completeInvokeRequest (:?) commandLoop (eventHelper.c:?) JvmtiAgentThread::start_function_wrapper (:?) JavaThread::thread_main_inner (:?) Thread::call_run (:?) thread_native_entry (os_linux.cpp:?) start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:307) ?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:111) [230400 bytes leaked] je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2)) je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289) os::malloc (:?) JvmtiEnv::Allocate (:?) jvmti_Allocate (jvmtiEnter.cpp:?) jvmtiAllocate (:?) bagCreateBag (:?) commonInit (outStream.c:?) outStream_initReply (:?) invoker_completeInvokeRequest (:?) commandLoop (eventHelper.c:?) JvmtiAgentThread::start_function_wrapper (:?) JavaThread::thread_main_inner (:?) Thread::call_run (:?) thread_native_entry (os_linux.cpp:?) start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:307) ?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:111) [115200 bytes leaked] je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2)) je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289) os::malloc (:?) JvmtiEnv::Allocate (:?) jvmti_Allocate (jvmtiEnter.cpp:?) jvmtiAllocate (:?) commonRef_refToID (:?) outStream_writeObjectRef.part.2 (outStream.c:?) outStream_writeValue (:?) invoker_completeInvokeRequest (:?) commandLoop (eventHelper.c:?) JvmtiAgentThread::start_function_wrapper (:?) JavaThread::thread_main_inner (:?) Thread::call_run (:?) thread_native_entry (os_linux.cpp:?) start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:307) ?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:111) With the fix from comment 12 (cloning the fork, checking out the branch, building and using the built JDK) I see only 1 of the leaks "remain": [115200 bytes leaked] je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2)) je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289) os::malloc (/tmp/jdk11u-dev/./src/hotspot/share/runtime/os.cpp:682) JvmtiEnv::Allocate (/tmp/jdk11u-dev/./src/hotspot/share/prims/jvmtiEnv.cpp:127) jvmti_Allocate (/tmp/jdk11u-dev/./build/linux-x86_64-normal-server-release/hotspot/variant-server/gensrc/jvmtifiles/jvmtiEnter.cpp:343) jvmtiAllocate (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/util.c:1808) commonRef_refToID (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/commonRef.c:428) outStream_writeObjectRef.part.2 (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:219) outStream_writeValue (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:344) invoker_completeInvokeRequest (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/invoker.c:839) commandLoop (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:713) JvmtiAgentThread::start_function_wrapper (/tmp/jdk11u-dev/./src/hotspot/share/prims/jvmtiImpl.cpp:80) JavaThread::thread_main_inner (/tmp/jdk11u-dev/./src/hotspot/share/runtime/thread.cpp:1869) Thread::call_run (/tmp/jdk11u-dev/./src/hotspot/share/runtime/thread.cpp:387) thread_native_entry (/tmp/jdk11u-dev/./src/hotspot/os/linux/os_linux.cpp:799) start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:307) ?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:111) If I reduce the number of iterations (in which JDI operations are ran), that one leak gets smaller: [28800 bytes leaked] je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2)) je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289) os::malloc (/tmp/jdk11u-dev/./src/hotspot/share/runtime/os.cpp:682) JvmtiEnv::Allocate (/tmp/jdk11u-dev/./src/hotspot/share/prims/jvmtiEnv.cpp:127) jvmti_Allocate (/tmp/jdk11u-dev/./build/linux-x86_64-normal-server-release/hotspot/variant-server/gensrc/jvmtifiles/jvmtiEnter.cpp:343) jvmtiAllocate (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/util.c:1808) commonRef_refToID (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/commonRef.c:428) outStream_writeObjectRef.part.2 (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:219) outStream_writeValue (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:344) invoker_completeInvokeRequest (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/invoker.c:839) commandLoop (/tmp/jdk11u-dev/./src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:713) JvmtiAgentThread::start_function_wrapper (/tmp/jdk11u-dev/./src/hotspot/share/prims/jvmtiImpl.cpp:80) JavaThread::thread_main_inner (/tmp/jdk11u-dev/./src/hotspot/share/runtime/thread.cpp:1869) Thread::call_run (/tmp/jdk11u-dev/./src/hotspot/share/runtime/thread.cpp:387) thread_native_entry (/tmp/jdk11u-dev/./src/hotspot/os/linux/os_linux.cpp:799) start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:307) ?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:111) So I assume there is still something to fix here.
> So I assume there is still something to fix here.
Ok thank you for testing this! Yes, this still looks like a leak, but it also looks like another one. I will try to find it, your stacktraces should be useful for this.
Thanks,
Roman
(In reply to Roman Kennke from comment #14) > > So I assume there is still something to fix here. > > Ok thank you for testing this! Yes, this still looks like a leak, but it > also looks like another one. I will try to find it, your stacktraces should > be useful for this. > > Thanks, > Roman As far as I understand, the allocation that is happening through commonRef_refToID() should not be leaky. It does create a RefNode and sticks it into a global table, but it does so with the tracked object in a weak reference. As far as I can tell, the entry in the table will be cleared once: 1. the object is no longer reachable (weakly) 2. A GC happened that identified that the object is no longer reachable and 3. a JVMTI callback is invoked, which will detect that a GC happened, and initiates cleaning of the table. So yes, memory usage will grow, and as long as the tracked object is alive, the entry in JVMTI will remain, but it *should* eventually get cleared. Is there any way that you can verify this? I would propose the other simple fix (https://github.com/rkennke/jdk11u-dev/tree/memleak-invoker2) upstream independently of the remaining issue (if it actually is one), ok? Thanks, Roman > (In reply to Roman Kennke from comment #14) > > > So I assume there is still something to fix here. > > > > Ok thank you for testing this! Yes, this still looks like a leak, but it > > also looks like another one. I will try to find it, your stacktraces should > > be useful for this. > > > > Thanks, > > Roman > > As far as I understand, the allocation that is happening through > commonRef_refToID() should not be leaky. It does create a RefNode and sticks > it into a global table, but it does so with the tracked object in a weak > reference. As far as I can tell, the entry in the table will be cleared > once: 1. the object is no longer reachable (weakly) 2. A GC happened that > identified that the object is no longer reachable and 3. a JVMTI callback is > invoked, which will detect that a GC happened, and initiates cleaning of the > table. > > So yes, memory usage will grow, and as long as the tracked object is alive, > the entry in JVMTI will remain, but it *should* eventually get cleared. Is > there any way that you can verify this? > > I would propose the other simple fix > (https://github.com/rkennke/jdk11u-dev/tree/memleak-invoker2) upstream > independently of the remaining issue (if it actually is one), ok? > > Thanks, > Roman I changed my "hello world" snippet to do some GCs: public static void main(String[] args) { System.out.println("hello world"); for (int i = 0; i < 10; ++i) { System.gc(); } System.out.println("hello world after GC"); } The breakpoint is at the first println(), then I run JDI operations as listed in the description. With the GC calls, I no longer see the leak (jemalloc doesn't list any leak for "invoker_completeInvokeRequest"). If I comment out the GC calls, I see: [28800 bytes leaked] je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2)) je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289) os::malloc (/data/git/jdk11/./src/hotspot/share/runtime/os.cpp:682) JvmtiEnv::Allocate (/data/git/jdk11/./src/hotspot/share/prims/jvmtiEnv.cpp:127) jvmti_Allocate (/data/git/jdk11/./build/linux-x86_64-normal-server-release/hotspot/variant-server/gensrc/jvmtifiles/jvmtiEnter.cpp:343) jvmtiAllocate (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/util.c:1808) commonRef_refToID (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/commonRef.c:428) outStream_writeObjectRef.part.2 (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:219) outStream_writeValue (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:344) invoker_completeInvokeRequest (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/invoker.c:839) commandLoop (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:713) JvmtiAgentThread::start_function_wrapper (/data/git/jdk11/./src/hotspot/share/prims/jvmtiImpl.cpp:80) JavaThread::thread_main_inner (/data/git/jdk11/./src/hotspot/share/runtime/thread.cpp:1869) Thread::call_run (/data/git/jdk11/./src/hotspot/share/runtime/thread.cpp:387) thread_native_entry (/data/git/jdk11/./src/hotspot/os/linux/os_linux.cpp:799) start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:307) ?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:111) So I think the bug is fixed with the fixes so far. I cherry-picked the change listed in comment 12: commit 34a54a7cad5a2cee512aa29a190893d44b674c6d (HEAD -> rkennke_patch) Author: Roman Kennke <rkennke> Date: Wed Mar 2 16:58:42 2022 +0100 Properly destroy outstream commit f7346f087a14f1878029a00104005e04468d333f (origin/master, origin/HEAD, master) Author: Goetz Lindenmaier <goetz> Date: Wed Mar 9 10:13:14 2022 +0000 8275703: System.loadLibrary fails on Big Sur for libraries hidden from filesystem Reviewed-by: mbaesken Backport-of: 6aa02d75d9f26f46fbdb54aef52cea3257aa7462 Thanks Roman! (In reply to Simeon Andreev from comment #16) > > (In reply to Roman Kennke from comment #14) > > > > So I assume there is still something to fix here. > > > > > > Ok thank you for testing this! Yes, this still looks like a leak, but it > > > also looks like another one. I will try to find it, your stacktraces should > > > be useful for this. > > > > > > Thanks, > > > Roman > > > > As far as I understand, the allocation that is happening through > > commonRef_refToID() should not be leaky. It does create a RefNode and sticks > > it into a global table, but it does so with the tracked object in a weak > > reference. As far as I can tell, the entry in the table will be cleared > > once: 1. the object is no longer reachable (weakly) 2. A GC happened that > > identified that the object is no longer reachable and 3. a JVMTI callback is > > invoked, which will detect that a GC happened, and initiates cleaning of the > > table. > > > > So yes, memory usage will grow, and as long as the tracked object is alive, > > the entry in JVMTI will remain, but it *should* eventually get cleared. Is > > there any way that you can verify this? > > > > I would propose the other simple fix > > (https://github.com/rkennke/jdk11u-dev/tree/memleak-invoker2) upstream > > independently of the remaining issue (if it actually is one), ok? > > > > Thanks, > > Roman > > I changed my "hello world" snippet to do some GCs: > > public static void main(String[] args) { > System.out.println("hello world"); > for (int i = 0; i < 10; ++i) { > System.gc(); > } > System.out.println("hello world after GC"); > } > > The breakpoint is at the first println(), then I run JDI operations as > listed in the description. > > With the GC calls, I no longer see the leak (jemalloc doesn't list any leak > for "invoker_completeInvokeRequest"). If I comment out the GC calls, I see: > > [28800 bytes leaked] > je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 > (discriminator 2)) > je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289) > os::malloc (/data/git/jdk11/./src/hotspot/share/runtime/os.cpp:682) > JvmtiEnv::Allocate > (/data/git/jdk11/./src/hotspot/share/prims/jvmtiEnv.cpp:127) > jvmti_Allocate > (/data/git/jdk11/./build/linux-x86_64-normal-server-release/hotspot/variant- > server/gensrc/jvmtifiles/jvmtiEnter.cpp:343) > jvmtiAllocate > (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/util.c:1808) > commonRef_refToID > (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/commonRef.c:428) > outStream_writeObjectRef.part.2 > (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:219) > outStream_writeValue > (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:344) > invoker_completeInvokeRequest > (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/invoker.c:839) > commandLoop > (/data/git/jdk11/./src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:713) > JvmtiAgentThread::start_function_wrapper > (/data/git/jdk11/./src/hotspot/share/prims/jvmtiImpl.cpp:80) > JavaThread::thread_main_inner > (/data/git/jdk11/./src/hotspot/share/runtime/thread.cpp:1869) > Thread::call_run (/data/git/jdk11/./src/hotspot/share/runtime/thread.cpp:387) > thread_native_entry (/data/git/jdk11/./src/hotspot/os/linux/os_linux.cpp:799) > start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:307) > ?? > (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/ > x86_64/clone.S:111) > > So I think the bug is fixed with the fixes so far. I cherry-picked the > master) Very good, thank you for testing this! The bug is tracked upstream here: https://bugs.openjdk.java.net/browse/JDK-8284094 and fix ready to go into JDK 19: https://github.com/openjdk/jdk/pull/8059 I will backport it to 18, 17 and 11 after some baking time. Thanks again, Roman I've started the process to get this into 18u - https://github.com/openjdk/jdk18u/pull/134 - and will proceed with 17u & 11u once this is approved. Now integrated into the July releases, 18.0.2, 17.0.4 and 11.0.16. This bug will be closed when 11.0.16 is integrated into RHEL 7. Fixed in RHSA-2022:5687-03 |
Description of problem: We observe a native memory leak when repeating JDI operations from Eclipse in a debuggee JVM. jemalloc reports the biggest memory leak as: [268800 bytes leaked] je_prof_backtrace (/home/sandreev/git/misc/jemalloc/src/prof.c:636 (discriminator 2)) je_malloc_default (/home/sandreev/git/misc/jemalloc/src/jemalloc.c:2289) os::malloc (/data/git/jdk11/src/hotspot/share/runtime/os.cpp:697) os::malloc (/data/git/jdk11/src/hotspot/share/runtime/os.cpp:660 (discriminator 3)) JvmtiEnvBase::allocate (/data/git/jdk11/src/hotspot/share/prims/jvmtiEnvBase.hpp:195) JvmtiEnv::Allocate (/data/git/jdk11/src/hotspot/share/prims/jvmtiEnv.cpp:126) jvmti_Allocate (/data/git/jdk11/build/linux-x86_64-normal-server-slowdebug/hotspot/variant-server/gensrc/jvmtifiles/jvmtiEnter.cpp:341) jvmtiAllocate (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/util.c:1794) bagCreateBag (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/bag.c:45) commonInit (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:50) outStream_initReply (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/outStream.c:75) invoker_completeInvokeRequest (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c:838) handleReportInvokeDoneCommand (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:568) handleCommand (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:618) commandLoop (/data/git/jdk11/src/jdk.jdwp.agent/share/native/libjdwp/eventHelper.c:713) JvmtiAgentThread::call_start_function (/data/git/jdk11/src/hotspot/share/prims/jvmtiImpl.cpp:85) JvmtiAgentThread::start_function_wrapper (/data/git/jdk11/src/hotspot/share/prims/jvmtiImpl.cpp:79) JavaThread::thread_main_inner (/data/git/jdk11/src/hotspot/share/runtime/thread.cpp:1752) JavaThread::run (/data/git/jdk11/src/hotspot/share/runtime/thread.cpp:1732) thread_native_entry (/data/git/jdk11/src/hotspot/os/linux/os_linux.cpp:698) start_thread (/usr/src/debug/glibc-2.17-c758a686/nptl/pthread_create.c:308) ?? (/usr/src/debug////////glibc-2.17-c758a686/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113) Version-Release number of selected component (if applicable): OpenJDK 11 How reproducible: Run JDI operations with Eclipse in any Java program. E.g. can be done with a command handler: public class SampleHandler extends AbstractHandler { @Override public Object execute(ExecutionEvent event) throws ExecutionException { Job job = new Job("JDI operation") { @Override protected IStatus run(IProgressMonitor monitor) { int n = 20 * 60; for (int i = 0; i < n; ++i) { try { IJavaDebugTarget javaTarget = getFirstJavaDebugTarget(); if (javaTarget != null) { IJavaThread javaThread = getFirstSuspendedJavaThread(javaTarget); if (javaThread != null) { IJavaType[] javaClass = javaTarget.getJavaTypes("java.lang.String"); if (javaClass[0] instanceof IJavaClassType) { IJavaClassType jdiClassType = (IJavaClassType) javaClass[0]; IJavaObject instance = jdiClassType.newInstance("()V", null, javaThread); try { instance.disableCollection(); if (!monitor.isCanceled()) { instance.sendMessage("isEmpty", "()Z", null, javaThread, false); } } finally { instance.enableCollection(); } } } } } catch (DebugException e) { e.printStackTrace(); } } return Status.OK_STATUS; } }; job.schedule(); return null; } private IJavaDebugTarget getFirstJavaDebugTarget() { for (IDebugTarget debugTarget : DebugPlugin.getDefault().getLaunchManager().getDebugTargets()) { if (debugTarget instanceof IJavaDebugTarget) { return (IJavaDebugTarget) debugTarget; } } return null; } private IJavaThread getFirstSuspendedJavaThread(IJavaDebugTarget javaDebugTarget) throws DebugException { for (IThread thread : javaDebugTarget.getThreads()) { if (thread.isSuspended() && (thread instanceof IJavaThread)) { return (IJavaThread) thread; } } return null; } } Actual results: Memory consumption of debuggee JVM increases as JDI operations are repeated. Expected results: No memory is leaked by invoker_completeInvokeRequest() in invoker.c. Additional info: See: https://github.com/openjdk/jdk11/blob/master/src/jdk.jdwp.agent/share/native/libjdwp/invoker.c#L838 The method invoker_completeInvokeRequest() does not seem to call outStream_destroy() on the initialized PacketOutputStream object. Looking at use of PacketOutputStream in other OpenJDK native code, the destroy call is missing. We observe more than one memory leak, we'll open other tickets and link those once we have enough info.