JDK-6887619 : Memory growth when using CKM_TLS_PRF mechanism with C_DeriveKey() calls
  • Type: Bug
  • Component: security-libs
  • Sub-Component: java.security
  • Affected Version: solaris_10,solaris_10u7,6u14,8
  • Priority: P2
  • Status: Closed
  • Resolution: Duplicate
  • OS: solaris_10
  • CPU: generic,sparc
  • Submitted: 2009-10-02
  • Updated: 2012-10-09
  • Resolved: 2010-02-05
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 6 JDK 7
6-poolResolved 7-poolResolved
Related Reports
Duplicate :  
JDK-6869672 - Memory retention issues when using https handler
Duplicate :  
JDK-2170532 - SSL stress test with GF leads to 32 bit max process size in less than 5 minutes,with PCKS11 provider
Duplicate :  
JDK-6868466 - native memory leak in jdk6 (regression from jdk5)
Relates :  
JDK-6913047 - Long term memory leak when using PKCS11 and JCE exceeds 32 bit process address space
Relates :  
JDK-6750401 - SSL stress test with GF leads to 32 bit max process size in less than 5 minutes,with PCKS11 provider
Description
There have been reports from java applications using JSSE and SunPKCS11 provider about a memory growth problem. After some investigation, it seems that CKM_TLS_PRF is the culprit for the memory growth problem.
Based on the test results at hand, the memory usage remains flat when either:
1) the CKM_TLS_PRF mechanism is disabled, or
2) leave CKM_TLS_PRF mechanism enabled, but pass 0 as the base key in the C_DeriveKey(...) call instead of what actually specified by the caller. This leads to an error and Java crypto framework will fail over to the next crypto provider, i.e. SunJCE, for the TlsPrf algorithm.

Since everything else on java side is the same, it looks to be a Solaris crypto implementation issue. Please refer to 6750401 "SSL stress test with GF leads to 32 bit max process size in less than 5 minutes,with PCKS11 provider" for more details.
Comments
EVALUATION Wrote a small stress test "P11TlsPrfStressTest.java" exercising the TlsPrf functionality using JCE APIs (this get rid of the JSSE dependency and can easily changed into a fixed iteration kind of test instead of a stress one). Reproduced the memory growth problem with this small stress test. If the native PKCS11 C_DeriveKey(...) call is commented out (everything else on java side remains the same), the memory remains flat. This should conclude the problem to be on the Solaris side. Re-assigning this bug back to Solaris team.
11-01-2010
EVALUATION I wrote another Dtrace script, javaleakbyfunction.d. Here's the output, which shows that the Java PKCS11 glue/wrapper code is (1) continually creating excessive sessions at the rate of about 1 per second. (2) Further C_Derivekey() is being called without C_DestoryObject() ever being called freeing paramter 6 of C_DeriveKey (phKey). (1) C_OpenSession handles, created from from Java PKCS glue/wrapper function Java_sun_security_pkcs11_wrapper_PKCS11_C_1OpenSession(), are NOT being closed by C_CloseSession or C_CloseAllSessions(). This leaves ~150000 sessions open with 1.5GB of memory leaks. This same problem was reported in last year in the evaluation of CR 6870296, but has not been fixed in the Java pkcs11 glue/wrapper code. (2) C_DeriveKeys calls create objects that are never destroyed by C_DestroyObject() calls (as C_DestoryObject() is never called by the Java PKCS11 wrapper. -------Invoking Java test program -------- h=v4v-t5220b-sca11; p=443; pwd=`pwd` JAVA_HOME=/net/shimmer.sfbay/export/home/valeriep/6U18ML/build/solaris-sparc $JAVA_HOME/bin/java -Xms64m -Xmx64m -verbose:gc -XX:+UseParallelGC -XX:ParallelGCThreads=16 -Djavax.net.ssl.trustStoreType=JKS -Djavax.net.ssl.trustStore=$pwd/testkeystore -Djavax.net.ssl.trustStorePassword=testpassword -jar $pwd/ckcert.jar $h $p > ckcert.out.dan 2>&1 ./javaleakbyfunction.d -p 2500 -------Dtrace output -------- dtrace: pid 2500 has exited 0 2 :END PID 2500 terminated. Results are: 214268 C_OpenSession() calls, 57792 C_CloseSession() calls, 0 C_CloseAllSessions() calls 156476 C_OpenSession() sessions NOT closed 33685968 C_DeriveKey() calls, 0 C_DestroyObject() calls 1548451313 bytes allocted in C_OpenSession() - 6379 freed = 1548444934 not freed 27 frees of 11601 allocs inside C_DeriveKey() = 11574 not freed 735716816 bytes allocated in C_Derivekey - 1579204 freed = 734137612 not freed 1747 frees of 8869 allocs inside C_OpenSession() = 7122 not freed 33685458 objects created by C_DeriveKey - 0 by C_DestroyObject = 336865458 not freed real 36:44:30.5 user 53:39.4 sys 56:38.4 Thursday, December 24, 2009 10:47:02 PM PST Because the problems originate with the Java PKCS11 glue/wrapper code, I am redirecting this bug to product/cat/subcat java/java/classes_security.
05-01-2010
EVALUATION [evaluation by bruce.chapman removed and moved to 6913047 as this appears to not be related to this bug]
04-01-2010
EVALUATION I wrote and run Dtrace script javaleakbyfunction.d (attached) and also ran mdb on the running Java program. The Java program was started with script test.5220c.sh.dan (attached). There seems to be leaks coming from two sources C_OpenSession() creating sessions but never being closed by C_CloseSession() and C_DeriveKey() objects never being destroyed by C_DestroyObject() First the Java program is calling C_OpenSession() several times (about once per second), constantly creating new sessions and constantly leaking memory. Only one session should be created--not thousands. A stack dump shows the C_OpenSession() being called from a Java wrapper function libj2pkcs11.so`Java_sun_security_pkcs11_wrapper_PKCS11_C_1OpenSession(). That in turn is called by a unknown function (the stack dump doesn't show names and only mdb showed who called C_OpenSession(). Here's the annotated stack dump: /export/home/test/valeriep # mdb -p 807 Loading modules: [ ld.so.1 libc.so.1 libuutil.so.1 ] > C_OpenSession:b > :c mdb: stop at libpkcs11.so.1`C_OpenSession mdb: target stopped at: libpkcs11.so.1`C_OpenSession: save %sp, -0x68, %sp > $c libpkcs11.so.1`C_OpenSession(30110, 0, 0, 6, fbeefde0, 6) CALLED FROM 0xfc00d5c0(271, fe37f18c, fe37f100, ffffff80, fb1db5f8, 0) libj2pkcs11.so`Java_sun_security_pkcs11_wrapper_PKCS11_C_1OpenSession+0xf4: CALLED FROM MYSTERY JAVA FUNCTION 0xfc00d56c(f7814148, b6, 0, 1c, f78012c8, fe37f118) 0xfc00d5c8: mov %l7, %g2 . . . call <libjvm.so`__1cKJavaThreadbOcheck_special_condition_for_native_trans6Fp0_v_> . . . call <libjvm.so`__1cSInterpreterRuntimeXthrow_pending_exception6FpnKJavaThread__v_> 0xfc0059d0(f7815ea8, 0, 0, fc017080, fb1db5f8, fe37f1d8) 0xfc0059d8: srl %g1, 0x0, %o1 0xfc0e755c(f7801fd8, f7801fd8, f3daa5f8, f3f6a4c0, f78012c8, fb1cba38) 0xfc161104(fb1db628, 0, f7801fd8, fb1ccd98, fb1db5f8, f3d27eb8) 0xfc1a472c(fb1db628, f7801fd8, f3daa5f8, f3f6a4c0, f78012c8, fb1cba38) 0xfc1215b0(fb1db628, 0, f7801fd8, fb1ccd98, fb1db5f8, f3d27eb8) 0xfc18b87c(fb1db5f8, fb1ccd98, 0, f3f6a4c0, f78012c8, fb1cba38) 0xfc1b4dbc(fb1db558, fb1db598, f7801840, fb1ccd98, fb1db5f8, f3d27eb8) 0xfc228cc8(f7801840, fb1ce1e8, fb1ccd98, fda94000, f78012c8, fb1cba38) 0xfc241c58(fb1cb530, ffffffb0, 36, ffffffa0, fffffffd, fffffffd) 0xfc1ae898(fb1cb530, 14, fb1cdbc8, c, f78d2230, f3ef64b0) 0xfc13eef0(f3ef64b0, ff3ee000, 8, c, fffffff6, ffffffbe) 0xfc16f93c(fb1cb530, fb1c2c08, 0, ffffffc9, 25, ffffffe7) 0xfc1f7314(f3e30400, fb1cc0b0, f3f2a9f8, 7fffffff, 0, 0) 0xfc25b088(f78ec300, fb1c2c08, f783a1c8, f3acac72, f785ad80, 0) 0xfc156ec4(f3c8bc30, f78ec290, fb, 7fffffff, 0, 0) 0xfc0b212c(f78f0938, fb1cc120, f78edf88, f3acac72, f785ad80, 0) 0xfc167c8c(fb1cc120, f3f1eaa8, fb, 7fffffff, 0, 0) 0xfc24ba60(f3a61c98, f3a57078, ff3ee000, fda94000, f7842b60, f3a04ff8) 0xfc005940(fad8da50, 0, 0, fc017460, 6000, fe37f900) 0xfc005940(fad90060, 0, 0, fc017080, 6000, fe37f9b8) 0xfc005940(fad90060, 0, 0, fc017080, 6000, fe37fa38) 0xfc005940(fee375c0, 0, 0, fc017080, 6000, fe37fad8) 0xfc005940(fee375c0, 0, 0, fc017460, 6000, fe37fb58) 0xfc005940(fee375c0, 0, 0, fc017460, 6000, fe37fbf0) 0xfc005ab0(fc0001c0, 30000, 0, fc0174b0, f39be4e8, fe37fc90) 0xfc00021c(fe37fd7c, fe37ff08, a, f39be4e8, fc00b460, fe37fe60) libjvm.so`__1cJJavaCallsLcall_helper6FpnJJavaValue_pnMmethodHandle_pnRJavaCallA rguments_pnGThread__v_+0x208(fc0001c0, 30000, 1, 0, f39be4e8, fe37ff08) libjvm.so`jni_CallStaticVoidMethod+0x4b8(30110, 308a4, 304a0, 30000, 30498, 2e9e8) JavaMain+0x15f0(314a8, 2c524, 2af20, 30110, 2, fee30ce4) libc.so.1`_lwp_start(0, 0, 0, 0, 0, 0) Second, C_DeriveKey() is being called, but the key created by C_DeriveKey is never destroyed by calling C_DestroyObject(). This also leaks memory. I'll file a full run after the break in January, 2010, but one can still investigate fixing the problem by making these two fixes named above (calling C_DestroySession() and C_DestoryObject() to prevent leaks).
22-12-2009
EVALUATION I ran the following script on v4v-t5220c-sca11.sfbay and after running ~48 hours, the program leaked 322528 sessions (91% of the 353027 sessions created). This was detrmined by running the dtrace script javaleak.d (attached). Environmental details follow. $ hostname v4v-t5220c-sca11 $ uname -a SunOS v4v-t5220c-sca11 5.10 Generic_137137-09 sun4v sparc SUNW,SPARC-Enterprise-T5220 $ pwd /net/cores.central/cores/dir33/71010682/Jun16-data/test-case/lc/5220c $ /net/shimmer/export/home/valeriep/6U18ML/build/solaris-sparc/bin/java -version java version "1.6.0-internal" Java(TM) SE Runtime Environment (build 1.6.0-internal-valeriep_28_aug_2009_15_24-b00) Java HotSpot(TM) Server VM (build 16.0-b09, mixed mode) $ ps -ef |grep bin/java UID PID PPID C STIME TTY TIME CMD da73024 20844 20834 1 Oct 05 pts/4 406:26 /net/shimmer/export/home/valeriep/6U18ML/build/solaris-sparc/bin/java -Xms64m - $ cat test.5220c.sh.dan #!/bin/sh h=v4v-t5220c-sca11; p=443; pwd=`pwd` JAVA_HOME=/net/shimmer/export/home/valeriep/6U18ML/build/solaris-sparc $JAVA_HOME/bin/java -version LD_PRELOAD=libumem.so.1 UMEM_LOGGING=transaction UMEM_DEBUG=default $JAVA_HOME/bin/java -Xms64m -Xmx64m -verbose:gc -XX:+UseParallelGC -XX:ParallelGCThreads=16 -Djavax.net.ssl.trustStoreType=JKS -Djavax.net.ssl.trustStore=$pwd/testkeystore -Djavax.net.ssl.trustStorePassword=testpassword -jar $pwd/ckcert.jar $h $p > ckcert.out.dan 2>&1 Separately, I created a program c_opensession.c that created 262144 sessions and left them open (This is less than the above Java program that created and left open 322528 sessions). The c_opensession program leaked 53MB of memory, or about 203KB/session.
07-10-2009