Java run-time compilation, JAVA_JIT_ENABLED (JIT), was first introduced as a performance upgrade in JDK 1.1.6,
and now is a standard tool invoked whenever Java is used.
It enables JVM well exploit the features of the computer hardware and operating system (OS).
On AIX, when calling Oracle 19.4 Java stored procedure, which is running on server-side integrated OracleJVM,
JIT enabled is not working, it behaves same as disabled.
If the Java stored procedure is invoking system dependent native compiled Java classes (big endian),
it falls back to the default OracleJVM provided Java classes (little endian),
hence performance degradation.
In this Blog, we first demonstrate this behaviour with JarInputStream to import signed Jar file with JIT enabled
(Oracle Doc: For platforms that support the JIT compiler, the default value of this parameter is true).
Then we reveal the bug by investigating the call stacks, and finally present a workaround.
A JAR file is essentially a Zip file that contains an optional META-INF directory.
If a manifest is present under META-INF directory (security signatures) and verify is true (default),
JarInputStream attempts to verify each file for the signed Jar.
JarInputStream and JarOutputStream classes extend to ZipInputStream and ZipOutputStream
(For JAR File,
see
JAR File Specification
For Security Provider,
see
Java Cryptography Architecture (JCA) Reference Guide).
Update (07 Feb. 2020): The bug should be fixed in Patch 29707582: EC.C COMPILE FAILURE.
1. Test Setup
Here the complete steps and code to reproduce the issue.
------ 1. Create a Jar file under directory /tmp ------
$> jar -cvf testJar.jar test1.txt
------ 2. List Jar content ------
$> unzip -l testJar.jar
Archive: testJar.jar
Length Date Time Name
--------- ---------- ----- ----
144 12-01-2019 08:27 META-INF/MANIFEST.MF
306 12-01-2019 08:27 META-INF/KUNALIAS.SF
1471 12-01-2019 08:27 META-INF/KUNALIAS.DSA
0 12-01-2019 08:26 META-INF/
110947240 12-01-2019 08:23 test1.txt
--------- -------
110949161 5 files
------ 3. Create a key ------
$> keytool -genkey -alias kunalias1 -keystore kunkey1
------ 4. Sign Jar file ------
$> jarsigner -keystore kunkey1 -storepass kunkey1 -keypass kunkey1 testJar.jar kunalias1
------ 5. Create a DB table to store Jar entries, and a Plsql row insert procedure to be called by Java ------
create table test_blob_tab(jar_name varchar2(100), jar_entry blob, sts timestamp with time zone);
create or replace function insert_blob(p_jar_name varchar2, p_jar_entry blob) return number as
l_rowcount integer;
begin
insert into test_blob_tab values (p_jar_name, p_jar_entry, systimestamp);
l_rowcount := sql%rowcount;
commit;
return l_rowcount;
end;
/
------ 6. Create Java stored procedure OracleJVMJarInputStream.java ------
(see Blog appended code in Section 8 OracleJVM Test Code).
------ 7. Publishing the Java Java stored procedure to Plsql ------
create or replace procedure OracleJVMJarInputStream(p_verify varchar2, p_info varchar2) as language java
name 'OracleJVMJarInputStream.run(java.lang.String, java.lang.String)';
/
2. Test Run
We will make two tests, one with signature verify, another without signature verify.
The test shows that signature verify takes 34 minutes, but another 12 seconds.
2.1. Invoke OracleJVMJarInputStream with signature verify
Sql > set serveroutput on size 50000
Sql > exec dbms_java.set_output(50000);
Sql > exec OracleJVMJarInputStream('true', 'no');
********* getNextJarEntry *********
------ NextJarEntry: 1, Name: META-INF/KUNALIAS.SF ------
getNextEntry ElapsedMills: 2, at: 1576576740110
Insert DB 1 row, blob size 0 at Sun Dec 01 10:59:00 CET 2019
readContent ElapsedMills: 20, at: 1576576740130
------ NextJarEntry: 2, Name: META-INF/KUNALIAS.DSA ------
getNextEntry ElapsedMills: 0, at: 1576576740130
Insert DB 1 row, blob size 0 at Sun Dec 01 10:59:06 CET 2019
readContent ElapsedMills: 6440, at: 1576576746571
------ NextJarEntry: 3, Name: META-INF/ ------
getNextEntry ElapsedMills: 0, at: 1576576746572
Insert DB 1 row, blob size 0 at Sun Dec 01 10:59:06 CET 2019
readContent ElapsedMills: 16, at: 1576576746588
------ NextJarEntry: 4, Name: test1.txt ------
getNextEntry ElapsedMills: 1, at: 1576576746589
Insert DB 1 row, blob size 110920480 at Sun Dec 01 11:33:01 CET 2019
readContent ElapsedMills: 2034693, at: 1576578781282
Elapsed: 00:34:01.35
2.2. Invoke OracleJVMJarInputStream without signature verify
Sql > exec OracleJVMJarInputStream('false', 'no');
********* getNextJarEntry *********
------ NextJarEntry: 1, Name: META-INF/KUNALIAS.SF ------
getNextEntry ElapsedMills: 2, at: 1576588511208
Insert DB 1 row, blob size 0 at Sun Dec 01 14:15:11 CET 2019
readContent ElapsedMills: 18, at: 1576588511226
------ NextJarEntry: 2, Name: META-INF/KUNALIAS.DSA ------
getNextEntry ElapsedMills: 0, at: 1576588511226
Insert DB 1 row, blob size 0 at Sun Dec 01 14:15:11 CET 2019
readContent ElapsedMills: 10, at: 1576588511237
------ NextJarEntry: 3, Name: META-INF/ ------
getNextEntry ElapsedMills: 0, at: 1576588511237
Insert DB 1 row, blob size 0 at Sun Dec 01 14:15:11 CET 2019
readContent ElapsedMills: 10, at: 1576588511247
------ NextJarEntry: 4, Name: test1.txt ------
getNextEntry ElapsedMills: 0, at: 1576588511248
Insert DB 1 row, blob size 110920480 at Sun Dec 01 14:15:23 CET 2019
readContent ElapsedMills: 12271, at: 1576588523519
Elapsed: 00:00:12.44
3. Reasoning
The above two tests showed a factor of 170 difference (34 minutes vs. 12 seconds)
between Jar import with vs. without signature verify.
For each Jar entry of size n, the complexity seems non-linear to its size (O(n^2) or higher).
When reading Jar archived big sized entries, the performance degradation becomes dramatic.
3.1. Code Path
Open two Sqlplus sessions.
In the first session with (sid, serial#) = (101, 1010), we execute again import with signature verify:
Sql > set serveroutput on size 50000
Sql > exec dbms_java.set_output(50000);
Sql > alter session set tracefile_identifier = 'java_dump_1';
Sql > exec OracleJVMJarInputStream('true', 'no');
In the second session, we make a few Java stack dump:
Sql > begin
for i in 1..600 loop
sys.dbms_java_dump.dump(sys.dbms_java_dump.java_dump_stack, 101, 1010);
dbms_lock.sleep(0.1);
end loop;
end;
/
Now if we open the dump file, we can see most of them having call stacks like:
*** 2019-12-01T13:34:24.768993+01:00
*** Java stack trace for the active thread
at sun.security.provider.ByteArrayAccess.b2iBig(ByteArrayAccess.java:247)
at sun.security.provider.ByteArrayAccess.b2iBig64(ByteArrayAccess.java:309)
at sun.security.provider.ByteArrayAccess.b2iBig(ByteArrayAccess.java:256)
at sun.security.provider.ByteArrayAccess.b2iBig64(ByteArrayAccess.java:309)
at sun.security.provider.SHA2.implCompress(SHA2.java:196)
at sun.security.provider.DigestBase.implCompressMultiBlock(DigestBase.java:141)
at sun.security.provider.DigestBase.engineUpdate(DigestBase.java:128)
at java.security.MessageDigest$Delegate.engineUpdate(MessageDigest.java:584)
at java.security.MessageDigest.update(MessageDigest.java:325)
at sun.security.util.ManifestEntryVerifier.update(ManifestEntryVerifier.java:173)
at java.util.jar.JarVerifier.update(JarVerifier.java:227)
at java.util.jar.JarInputStream.read(JarInputStream.java:212)
at java.util.zip.ZipInputStream.closeEntry(ZipInputStream.java:140)
at java.util.zip.ZipInputStream.getNextEntry(ZipInputStream.java:118)
at java.util.jar.JarInputStream.getNextEntry(JarInputStream.java:142)
at java.util.jar.JarInputStream.getNextJarEntry(JarInputStream.java:179)
at OracleJVMJarInputStream.run(OracleJVMJarInputStream:49)
3.2. Java Class: sun.security.provider.ByteArrayAccess
If we look the Java 8 ByteArrayAccess source delivered by sun.security.provider.
The document states that the method is optimized for little endian, and big endian, such as SPARC.
Sticking to above call stack, we can see that sun.security.provider.DigestBase
calls big endian specific b2iBig64 for algorithm SHA2, and it is further implemented by b2iBig,
which contains a while loop.
/**
* Optimized methods for converting between byte[] and int[]/long[], both for
* big endian and little endian byte orders.
*
* Currently, it includes a default code path plus two optimized code paths.
* One is for little endian architectures that support full speed int/long
* access at unaligned addresses (i.e. x86/amd64). The second is for big endian
* architectures (that only support correctly aligned access), such as SPARC.
* These are the only platforms we currently support, but other optimized
* variants could be added as needed.
*/
final class ByteArrayAccess {
...
/**
* byte[] to int[] conversion, big endian byte order.
*/
static void b2iBig(byte[] in, int inOfs, int[] out, int outOfs, int len) {
...
while (inOfs < len) {
// Special optimization of b2iBig(in, inOfs, out, 0, 64)
static void b2iBig64(byte[] in, int inOfs, int[] out) {
...
b2iBig(in, inOfs, out, 0, 64);
3.3. Security Provider
If we list all Security Providers in OracleJVM:
Sql > exec OracleJVMJarInputStream('true', 'info');
===============0. Provider: SUN version 1.8
----- 97. Element:MessageDigest.SHA-256
===============1. Provider: SunRsaSign version 1.8
===============2. Provider: SunJSSE version 1.8
===============3. Provider: SunJCE version 1.8
===============4. Provider: SunJGSS version 1.8
===============5. Provider: SunSASL version 1.8
===============6. Provider: XMLDSig version 1.8
===============7. Provider: SunPCSC version 1.8
we can see "MessageDigest.SHA-256" (for SHA2) is provided by "SUN version 1.8".
No any IBM Security Provider is listed.
4. Deep into JIT Compiled Native Code
Now we can have a further look of the allocated shared memory segments from UNIX.
4.1. JIT Compiled Native Code
JIT run-time Compiled Native Code are dynamically allocated in shared memory, and can be monitored by ipcs command.
If we compare the following ipcs output on shared memory allocated for JIT Compiled Native Code
between not working Oracle 19.4 and that of properly working Oracle 19.3:
---=============== Oracle 19.4 on AIX, JIT not Working ===============---
$> ipcs -ar
T ID KEY MODE OWNER GROUP CREATOR CGROUP NATTCH SEGSZ CPID LPID ATIME DTIME CTIME RTFLAGS NAME
Shared Memory:
m - 0xffffffff --rw-r----- oracle dba oracle dba 0 0 30146690 0 no-entry no-entry 15:28:51 - /JOEZSHM_testdb194_1_0_1_0_0_2971349679
m - 0xffffffff --rw-r----- oracle dba oracle dba 0 0 18219016 0 no-entry no-entry 15:28:43 - /JOEZSHM_testdb194_1_0_0_0_0_1989310950
m - 0xffffffff --rw-r----- oracle dba oracle dba 0 0 20185178 0 no-entry no-entry 14:23:14 - /JOEZSHM_testdb194_1_0_1_0_0_2979596769
---=============== Oracle 19.3 on AIX, JIT works ===============---
$> ipcs -ar
T ID KEY MODE OWNER GROUP CREATOR CGROUP NATTCH SEGSZ CPID LPID ATIME DTIME CTIME RTFLAGS NAME
Shared Memory:
m - 0xffffffff --rw-rw---- oracle dba oracle dba 0 16777216 31588636 0 no-entry no-entry 13:30:56 - /JOEZSHM_testdb193_1_0_1_0_0_2979282907
m - 0xffffffff --rw-rw---- oracle dba oracle dba 0 8388608 31588636 0 no-entry no-entry 8:10:45 - /JOEZSHM_testdb193_1_0_1_1_0_2979282907
m - 0xffffffff --rw-rw---- oracle dba oracle dba 0 16777216 34931180 0 no-entry no-entry 12:27:51 - /JOEZSHM_testdb193_1_0_0_0_0_1989371893
we can see two differences, the first is the permissions; the second is shared segment size:
Oracle 19.4 MODE --rw-r-----
Oracle 19.3 MODE --rw-rw----
Oracle 19.4 SEGSZ 0
Oracle 19.3 SEGSZ not 0, one is with 8388608 (8MB), and two are 16MB 16777216(16MB)
Later we will see that MZ00 process trace file constantly shows error message: "Unable to allocate code space",
probably because of insufficient permissions and 0 sized shared segments in Oracle 19.4.
Since enabling JIT is not working on AIX (big endian) for Oracle 19.4,
it falls back to the default OracleJVM provided Java classes (little endian),
hence performance degradation.
As a small test, we can also create a shared segment with
SEGSZ: 1024 bytes, and MODE: "--rw-r-----"
as follows:
(see IBM Doc:
shmget–Allocate shared memory)
#include <sys/ipc.h>
#include <sys/shm.h>
int main()
{
key_t key;
int i;
key = ftok("/usr/testfile2", 2);
i= shmget(key, 1024, IPC_CREAT|S_IRUSR|S_IWUSR|S_IRGRP);
printf("shmget key: %i\n", i);
}
-- compile and run compiled c code
$ > ipcs -ar
T ID KEY MODE OWNER GROUP CREATOR CGROUP NATTCH SEGSZ CPID LPID ATIME DTIME CTIME RTFLAGS NAME
Shared Memory:
m 329257579 0xffffffff --rw-r----- oracle dba oracle dba 0 1024 29229194 0 no-entry no-entry 9:17:54
4.2. Oracle JAVAVM JIT Compiler Slave MZ00
According to Oracle Doc, JIT compiler runs as an MMON slave, in a single background process MZ00 for the DB instance.
While the JIT compiler is running and actively compiling methods,
we may see this background process consuming CPU and memory resources equivalent to an active user Java session.
In fact, above Oracle 19.4 ipcs output shows that CPID (creator process ID) is 20185178, which is the UNIX process id of MZ00.
Open Oracle 19.4 MZ00 trace file: aix194db_mz00_20185178.trc, we can see the failed message:
(turn on 10046 Event Trace on MZ00 can observe more activities)
Unix process pid: 20185178, image: oracle@aix194db (MZ00)
*** 2019-12-01T22:23:14.257628+01:00
*** SERVICE NAME:(SYS$BACKGROUND) 2019-12-01T22:23:14.257687+01:00
*** MODULE NAME:(MMON_SLAVE) 2019-12-01T22:23:14.257699+01:00
*** ACTION NAME:(JAVAVM JIT slave action) 2019-12-01T22:23:14.257711+01:00
*** 2019-12-01T22:23:14.257754+01:00
JIT running
joez_shm_open_object failed: size = 16777216, extnam = /JOEZSHM_testdb194_1_0_1_0_0_2979596769 flags = 0x34
joez: Failed loading machine code: Unable to allocate code space
Done compiling java/lang/SecurityManager$1.run
*** 2019-12-01T22:23:26.185994+01:00
joez_shm_open_object failed: size = 16777216, extnam = /JOEZSHM_testdb194_1_0_0_0_0_1989310950 flags = 0x34
joez: Failed loading machine code: Unable to allocate code space
Done compiling oracle/aurora/rdbms/EnvironmentSpecificImpl.securityManagerImpl
The above output shows that each joez_shm_open_object is indentified by "extnam", which maybe indicates
that Java launcher uses Java Extension path to find classes.
However if we search Bootstrap classes in rt.jar, we can see IBM security provider and ibm SHA2 algorithm.
unzip -l $ORACLE_HOME/jdk/jre/lib/rt.jar
0 02-07-2019 17:37 com/ibm/security/bootstrap/
3339 10-30-2018 16:47 com/ibm/security/bootstrap/SHA2.class
The above "flags" value "0x34" is ASCII "4", which could signify GroupMode "r--" in above ipcs output.
If we truss MZ00 JIT slave, it shows constantly "Err#22 EINVAL".
According to AIX Doc, lseek Error Codes: EINVAL stands for:
The resulting offset would be greater than the maximum offset allowed for the file or device associated with FileDescriptor.
The lseek subroutine was used with a file descriptor obtained from a call to the shm_open subroutine.
Since Oracle 19.4 created shared segments are 0 sized, MZ00 throws above offset error.
$> truss -dp 20185178
Sun Dec 01 22:25:31 2019
0.0000: thread_post(50135221) = 0
0.0009: shm_open(0x0FFFFFFFFFFE4590, 258, 504) = 3606
0.0013: lseek(3606, 0, 1) Err#22 EINVAL
0.0018: lseek(3259, 0, 1) = 701432
0.0072: kwrite(3259, "\n * * * 2 0 1 9 - 1 2".., 38) = 38
0.0075: kwrite(3505, " ! 0 e 4 c\n", 6) = 6
0.0078: lseek(3259, 0, 1) = 701470
0.0080: kwrite(3259, " j o e z _ s h m _ o p e".., 108) = 108
0.0083: kwrite(3505, " J ? g T y P ~ 0 i 1\n", 11) = 11
0.0086: kwrite(3259, "\n", 1) = 1
0.0089: kwrite(3259, " j o e z : F a i l e d".., 64) = 64
0.0092: kwrite(3259, "\n", 1) = 1
0.0172: kwrite(3259, " D o n e c o m p i l i".., 77) = 77
0.0174: kwrite(3259, "\n", 1) = 1
0.0178: kwrite(3259, " C o m p i l i n g c o".., 119) = 119
0.0181: kwrite(3259, "\n", 1) = 1
1.3517: thread_post(50135221) = 0
1.3574: shm_open(0x0FFFFFFFFFFE4590, 258, 504) = 3607
1.3578: lseek(3607, 0, 1) Err#22 EINVAL
5. Reproduce In Lower Oracle Versions
The above observed behaviour shows the JIT enabled is same as disabled in Oracle 19.4.
So we can try to disable JIT in Oracle versions before 19.4 on AIX,
and check if it is reproducible
(following tests are done in Oracle 12c, 18c, 19.3 on AIX).
5.1. JIT enabled Test
Take one oracle 12c DB on AIX with JAVA_JIT_ENABLED enabled, run the same test with signature verify,
it takes about 11 seconds, compared to above 34 minutes from Oracle 19.4.
Sql > set serveroutput on size 50000
Sql > exec dbms_java.set_output(50000);
Sql > alter session set tracefile_identifier = 'java_dump_1';
Sql > exec OracleJVMJarInputStream('true', 'no');
********* getNextJarEntry *********
------ NextJarEntry: 1, Name: META-INF/KUNALIAS.SF ------
getNextEntry ElapsedMills: 70, at: 1576667113846
Insert DB 1 row, blob size 0 at Sun Dec 01 12:05:14 CET 2019
readContent ElapsedMills: 333, at: 1576667114180
------ NextJarEntry: 2, Name: META-INF/KUNALIAS.DSA ------
getNextEntry ElapsedMills: 0, at: 1576667114180
Insert DB 1 row, blob size 0 at Sun Dec 01 12:05:14 CET 2019
readContent ElapsedMills: 504, at: 1576667114684
------ NextJarEntry: 3, Name: META-INF/ ------
getNextEntry ElapsedMills: 0, at: 1576667114685
Insert DB 1 row, blob size 0 at Sun Dec 01 12:05:14 CET 2019
readContent ElapsedMills: 2, at: 1576667114687
------ NextJarEntry: 4, Name: test1.txt ------
getNextEntry ElapsedMills: 3, at: 1576667114690
Insert DB 1 row, blob size 110920480 at Sun Dec 01 12:05:24 CET 2019
readContent ElapsedMills: 10333, at: 1576667125023
Elapsed: 00:00:11.51
5.2. JIT disabled Test
Now we remove all JIT compiled native code from the same Oracle 12c DB, disable JIT, re-run above test
(For details, see Blog:
Remove Stale Native Code Files on AIX).
------ 1. List JIT compiled native code ------
$ > ipcs -ar |grep -e JOXSHM_EXT | awk '{cnt+=1; sum+=$10} END {print "Count=",cnt,"Sum=",sum,"Average=",sum/cnt}'
Count= 1918 Sum= 24076288 Average= 12552.8
------ 2. Remove JIT compiled native code ------
$ > ipcs -ar |grep -e JOXSHM_EXT | awk ' {name = $17; cmd = "ipcrm -r -m " name; print "Run ", cmd; system( cmd )}'
------ 3. Disable java_jit_enabled ------
Sql > alter system set java_jit_enabled = false scope=both;
------ 4. Restart DB ------
Sql > startup force
------ 5. Slow Test: 16 minutes ------
Sql > exec OracleJVMJarInputStream('true', 'no');
********* getNextJarEntry *********
------ NextJarEntry: 1, Name: META-INF/KUNALIAS.SF ------
getNextEntry ElapsedMills: 72, at: 1576667818306
Insert DB 1 row, blob size 0 at Sun Dec 01 12:16:58 CET 2019
readContent ElapsedMills: 872, at: 1576667819179
------ NextJarEntry: 2, Name: META-INF/KUNALIAS.DSA ------
getNextEntry ElapsedMills: 1, at: 1576667819180
Insert DB 1 row, blob size 0 at Sun Dec 01 12:17:02 CET 2019
readContent ElapsedMills: 3456, at: 1576667822636
------ NextJarEntry: 3, Name: META-INF/ ------
getNextEntry ElapsedMills: 1, at: 1576667822637
Insert DB 1 row, blob size 0 at Sun Dec 01 12:17:02 CET 2019
readContent ElapsedMills: 3, at: 1576667822640
------ NextJarEntry: 4, Name: test1.txt ------
getNextEntry ElapsedMills: 37, at: 1576667822677
Insert DB 1 row, blob size 110920480 at Sun Dec 01 12:33:23 CET 2019
readContent ElapsedMills: 980996, at: 1576668803674
Elapsed: 00:16:27.43
------ 6. Dump Java call stack of test session ------
-- Open a second Sqlplus session, make a few Java stack dump:
Sql > begin
for i in 1..600 loop
sys.dbms_java_dump.dump(sys.dbms_java_dump.java_dump_stack, 101, 1010);
dbms_lock.sleep(0.1);
end loop;
end;
/
-- The call stack shows similar sun.security.provider for invoked SHA2 algorithm:
-- sun.security.provider.SHA2.implCompress(SHA2.java:193)
------ 7. List JIT compiled native code ------
$ > ipcs -ar |grep -e JOXSHM_EXT
-- JIT disable, no row returned, no shared memory segment created
The above test in Oracle 12c DB shows it takes about 16 minutes when JIT disabled,
compared to above 11 seconds with JIT enabled.
In case of JIT disabled, no shared memory segments created,
Oracle JVM can not benefit from computer hardware and operating system (OS) dependent optimized JAVA classes.
Therefore the same behaviour can be reproduced if JIT is disabled in Oracle versions lower than 19.4.
5.3. Shared Memory Segment for JIT compiled native code
We also observed changes of JIT compiled Shared Memory Segment naming and size following Oracle versions.
--- Oracle 12c JIT compiled Shared Memory Segment naming ---
/JOXSHM_EXT_420_testdb12c_11534967
--- Oracle 18c JIT compiled Shared Memory Segment naming ---
/JOEZSHM_testdb18c_1_0_32075_0_0_1164116801
--- Oracle 19c JIT compiled Shared Memory Segment naming ---
/JOEZSHM_testdb194_1_0_1_0_0_3031177879
Till 18c, there are about 1000 JIT compiled Shared Memory Segments with each around 10KB,
probably each one represents one Java class.
From 19c, there are only a few (less than 10) JIT compiled Shared Memory Segments with each around 8MB or 16MB,
probably they are now grouped under Java Packages.
6. Workaround
As a workaround, we can use standard Java JVM to import Jar files into DB by JDBC.
Besides fixing the performance problem, one more advantage is that the workaround
can be called from any other platforms, or even little endian machine
(See appended code in Section: "9. Standard Java JVM Test Code").
Here is one test run, which takes about 25 seconds.
$ > $ORACLE_HOME/jdk/bin/java -cp $ORACLE_HOME/jdbc/lib/ojdbc8.jar:. \
JavaJVMJarInputStream \
"jdbc:oracle:thin:k/s@testdb194:1522:testdb194" true no
********* getNextJarEntry *********
------ NextJarEntry: 1, Name: META-INF/KUNALIAS.SF ------
getNextEntry ElapsedMills: 1, at: 1576670454217
Insert DB 1 row, blob size 0 at Sun Dec 01 13:00:55 CET 2019
readContent ElapsedMills: 1116, at: 1576670455334
------ NextJarEntry: 2, Name: META-INF/KUNALIAS.DSA ------
getNextEntry ElapsedMills: 0, at: 1576670455335
Insert DB 1 row, blob size 0 at Sun Dec 01 13:00:55 CET 2019
readContent ElapsedMills: 151, at: 1576670455486
------ NextJarEntry: 3, Name: META-INF/ ------
getNextEntry ElapsedMills: 0, at: 1576670455486
Insert DB 1 row, blob size 0 at Sun Dec 01 13:00:55 CET 2019
readContent ElapsedMills: 18, at: 1576670455504
------ NextJarEntry: 4, Name: test1.txt ------
getNextEntry ElapsedMills: 0, at: 1576670455504
Insert DB 1 row, blob size 110920480 at Sun Dec 01 13:01:18 CET 2019
readContent ElapsedMills: 23346, at: 1576670478850
If we re-run the test with JMX option, and monitor it by Java VisualVM:
$ > $ORACLE_HOME/jdk/bin/java -cp $ORACLE_HOME/jdbc/lib/ojdbc8.jar:. \
-Dcom.sun.management.jmxremote.port=1521 \
-Dcom.sun.management.jmxremote.authenticate=false \
-Dcom.sun.management.jmxremote.ssl=false \
JavaJVMJarInputStream \
"jdbc:oracle:thin:k/s@testdb194:1522:testdb194" true no
From VisualVM, we make a few Thread Dump.
The call stack shows that com.ibm.security.bootstrap provider is invoked for SHA2 algorithm.
Here one Thread Dump:
2019-12-01 13:36:17
Full thread dump IBM J9 VM (2.9 JRE 1.8.0 AIX ppc64-64-Bit Compressed References 20190124_408237 (JIT enabled, AOT enabled)
OpenJ9 - 9c77d86
OMR - dad8ba7
IBM - e2996d1):
"main" - Thread t@1
java.lang.Thread.State: RUNNABLE
at com.ibm.security.bootstrap.SHA2.implCompress(SHA2.java:278)
at com.ibm.security.bootstrap.DigestBase.engineUpdate(DigestBase.java:157)
at java.security.MessageDigest$Delegate.engineUpdate(MessageDigest.java:595)
at java.security.MessageDigest.update(MessageDigest.java:336)
at sun.security.util.ManifestEntryVerifier.update(ManifestEntryVerifier.java:185)
at java.util.jar.JarVerifier.update(JarVerifier.java:238)
at java.util.jar.JarInputStream.read(JarInputStream.java:223)
at java.io.FilterInputStream.read(FilterInputStream.java:118)
at JavaJVMJarInputStream.jarEntryReadInsertDB(JavaJVMJarInputStream.java:111)
at JavaJVMJarInputStream.main(JavaJVMJarInputStream.java:88)
If we list all Security Providers by:
$ > $ORACLE_HOME/jdk/bin/java -cp $ORACLE_HOME/jdbc/lib/ojdbc8.jar:. \
JavaJVMJarInputStream \
"jdbc:oracle:thin:k/s@testdb194:1522:testdb194" true info
===============0. Provider: IBMJSSE2 version 1.8
===============1. Provider: IBMJCE version 1.8
----- 23. Element:MessageDigest.SHA2
===============2. Provider: IBMJGSSProvider version 8.0
===============3. Provider: IBMCertPath version 1.8
===============4. Provider: IBMSASL version 1.8
===============5. Provider: IBMXMLCRYPTO version 8.0
===============6. Provider: IBMXMLEnc version 8.0
===============7. Provider: IBMSPNEGO version 8.0
===============8. Provider: SUN version 1.8
----- 1. Element:Provider.id info
----- 2. Element:Provider.id className
----- 3. Element:Policy.JavaPolicy
----- 4. Element:Provider.id version
----- 5. Element:Provider.id name
we can see "MessageDigest.SHA2" is only provided by "IBMJCE version 1.8".
There is one single "SUN version 1.8" Provider, which contains 5 Elements.
7. Related Work
Here two Blogs about Java JIT native compiler:
Remove Stale Native Code Files on AIX
What the heck are the /dev/shm/JOXSHM_EXT_x files on Linux?
One Blog about both PLSQL and JAVA native compiler code:
Native Code Files: Ora-7445 [Ioc_pin_shared_executable_object()] Reproducing
One Blog about Linux:
joez: Failed loading machine code: Unable to allocate code space
On docker, Ubuntu and Oracle RDBMS
One Blog about SHA2 provider performance in Linux:
SHA2 calculation extremely slow under unknown conditions
In Oracle, there is one Java error message (ORA-10880).
We also tried this event, but no lines recorded in the trace file.
ORA-10880: trace Java VM execution
alter session set events '10880 trace name context forever, level 4294967295';
(where 4294967295 (2^32-1) seems the maximum tracing level with most details)
By the way, besides JIT, IBM JVM (platform-specific) is advanced by its Ahead-Of-Time (AOT).
8. OracleJVM Test Code
create or replace and compile java source named "OracleJVMJarInputStream" as
import java.io.FileInputStream;
import java.io.IOException;
import java.io.InputStream;
import java.io.OutputStream;
import java.io.BufferedInputStream;
import java.util.Date;
import java.util.Arrays;
import java.util.jar.JarInputStream;
import java.util.jar.JarEntry;
import java.util.jar.Manifest;
import java.util.jar.Attributes;
import java.util.zip.ZipEntry;
import java.sql.DriverManager;
import java.sql.Connection;
import java.sql.CallableStatement;
import java.sql.Blob;
import oracle.jdbc.OracleDriver;
import oracle.jdbc.OracleTypes;
import oracle.jdbc.OraclePreparedStatement;
import oracle.sql.BLOB;
import java.security.Provider;
import java.security.Security;
import java.util.Enumeration;
class OracleJVMJarInputStream
{
static String INSERT_DB = "begin :1 := insert_blob(:2, :3); end;";
public static void run(String verifyStr, String infoStr) throws Exception {
boolean verify = verifyStr.equalsIgnoreCase("true")? true:false;
boolean printInfo = infoStr.equalsIgnoreCase("info")? true:false;
FileInputStream fis = new FileInputStream("/tmp/testJar.jar");
JarInputStream jis = new JarInputStream(fis, verify); // default verify is true
if (printInfo) {
printManifest(jis);
printSecurityProviders();
}
Connection conn;
conn = new OracleDriver().defaultConnection();
long start, finish, elapsed;
int seq = 1;
JarEntry je;
String entryName;
start = System.currentTimeMillis();
System.out.println("\n********* getNextJarEntry *********");
try {
while ((je = jis.getNextJarEntry()) != null) {
finish = System.currentTimeMillis();
elapsed = finish - start;
entryName = je.getName();
System.out.println("------ NextJarEntry: " + seq + ", Name: " + entryName + " ------");
System.out.println(" getNextEntry ElapsedMills: " + elapsed + ", at: " + finish);
seq++;
start = System.currentTimeMillis();
jarEntryReadInsertDB(conn, entryName, jis);
finish = System.currentTimeMillis();
elapsed = finish - start;
System.out.println(" readContent ElapsedMills: " + elapsed + ", at: " + finish);
start = System.currentTimeMillis();
}
jis.close();
conn.close();
} catch (Exception e) {
e.printStackTrace();
}
}
static void jarEntryReadInsertDB(Connection conn, String jarEntryName, JarInputStream jis) {
BLOB blob = null;
byte[] buf;
OutputStream blobStream;
int bytesRead;
try {
blob = BLOB.createTemporary(conn, false, BLOB.DURATION_SESSION);
buf = new byte[blob.getChunkSize()];
blobStream = blob.getBinaryOutputStream();
while (jis.available() > 0) {
bytesRead = jis.read(buf);
blobStream.write(buf, 0, bytesRead);
}
CallableStatement cStmt = conn.prepareCall(INSERT_DB);
cStmt.registerOutParameter(1, OracleTypes.INTEGER);
cStmt.setString(2, jarEntryName);
cStmt.setBlob(3, blob);
cStmt.execute();
int insRows = cStmt.getInt(1);
System.out.println(" Insert DB " + insRows + " row, blob size " + blob.length() + " at " + new Date());
blob.freeTemporary();
cStmt.close();
// OraclePreparedStatement pstmt = (OraclePreparedStatement) conn.prepareStatement("insert into test_blob_tab values(?, ?)");
// pstmt.setString(1, jarEntryName);
// pstmt.setBLOB(2, blob);
// pstmt.execute();
// pstmt.close();
} catch (Exception e) {
e.printStackTrace();
}
}
static void printManifest(JarInputStream jis) {
Manifest manifest = jis.getManifest();
if (manifest != null) {
System.out.println("********* Print Manifest *********");
System.out.println("Manifest=" + manifest.toString());
Attributes mainAttributes = manifest.getMainAttributes();
System.out.println("Manifest Manifest-Version=" + mainAttributes.getValue("Manifest-Version"));
System.out.println("Manifest Created-By=" + mainAttributes.getValue("Created-By"));
} else {
System.out.println("********* No Manifest *********");
}
}
static void printSecurityProviders() throws Exception {
Provider p[] = Security.getProviders();
for (int i = 0; i < p.length; i++) {
System.out.println(" ===============" + i + ". Provider: " + p[i]);
int j = 1;
for (Enumeration e = p[i].keys(); e.hasMoreElements();) {
System.out.println("\t ----- " + j + ". Element:" + e.nextElement());
j++;
}
}
}
}
/
create or replace procedure OracleJVMJarInputStream(p_verify varchar2, p_info varchar2) as language java
name 'OracleJVMJarInputStream.run(java.lang.String, java.lang.String)';
/
--- Test Steps ---
Sqlplus > set serveroutput on size 50000
Sqlplus > exec dbms_java.set_output(50000);
--- Verify true ---
Sqlplus > exec OracleJVMJarInputStream('true', 'no');
--- Verify false ---
Sqlplus > exec OracleJVMJarInputStream('false', 'no');
--- Verify true, print manifest and security providers ---
Sqlplus > exec OracleJVMJarInputStream('true', 'info');
9. Standard Java JVM Test Code
import java.io.FileInputStream;
import java.io.IOException;
import java.io.InputStream;
import java.io.OutputStream;
import java.io.BufferedInputStream;
import java.util.Date;
import java.util.Arrays;
import java.util.Enumeration;
import java.util.jar.JarInputStream;
import java.util.jar.JarEntry;
import java.util.jar.Manifest;
import java.util.jar.Attributes;
import java.util.zip.ZipEntry;
import java.sql.DriverManager;
import java.sql.Connection;
import java.sql.CallableStatement;
import java.sql.Blob;
import java.security.Provider;
import java.security.Security;
import oracle.jdbc.OracleDriver;
import oracle.jdbc.OracleTypes;
import oracle.jdbc.OraclePreparedStatement;
import oracle.sql.BLOB;
/* --------------------- DB Setup ---------------------
create table test_blob_tab(jar_name varchar2(100), jar_entry blob, sts timestamp with time zone);
create or replace function insert_blob(p_jar_name varchar2, p_jar_entry blob) return number as
l_rowcount integer;
begin
insert into test_blob_tab values (p_jar_name, p_jar_entry, systimestamp);
l_rowcount := sql%rowcount;
commit;
return l_rowcount;
end;
/
--------------------- Java Compile and Run (JarInputStream verify true or false)---------------------
$ORACLE_HOME/jdk/bin/javac -cp $ORACLE_HOME/jdbc/lib/ojdbc8.jar JavaJVMJarInputStream.java
$ORACLE_HOME/jdk/bin/java -cp $ORACLE_HOME/jdbc/lib/ojdbc8.jar:. JavaJVMJarInputStream \
"jdbc:oracle:thin:k/s@testdb194:1522:testdb194" true no
$ORACLE_HOME/jdk/bin/java -cp $ORACLE_HOME/jdbc/lib/ojdbc8.jar:. JavaJVMJarInputStream \
"jdbc:oracle:thin:k/s@testdb194:1522:testdb194" false no
*/
class JavaJVMJarInputStream
{
static String INSERT_DB = "begin :1 := insert_blob(:2, :3); end;";
public static void main(String[] args) throws Exception
{
String jdbcURL = args[0];
boolean verify = args[1].equalsIgnoreCase("true")? true:false;
boolean printInfo = args[2].equalsIgnoreCase("info")? true:false;
FileInputStream fis = new FileInputStream("/tmp/testJar.jar");
JarInputStream jis = new JarInputStream(fis, verify); // default verify is true
if (printInfo) {
printManifest(jis);
printSecurityProviders();
}
Connection conn = null;
try {
Class.forName("oracle.jdbc.driver.OracleDriver");
conn = DriverManager.getConnection(jdbcURL);
} catch (Exception e) {
e.printStackTrace();
return;
}
long start, finish, elapsed;
int seq = 1;
JarEntry je;
String entryName;
start = System.currentTimeMillis();
System.out.println("\n********* getNextJarEntry *********");
try {
while ((je = jis.getNextJarEntry()) != null) {
finish = System.currentTimeMillis();
elapsed = finish - start;
entryName = je.getName();
System.out.println("------ NextJarEntry: " + seq + ", Name: " + entryName + " ------");
System.out.println(" getNextEntry ElapsedMills: " + elapsed + ", at: " + finish);
seq++;
start = System.currentTimeMillis();
jarEntryReadInsertDB(conn, entryName, jis);
finish = System.currentTimeMillis();
elapsed = finish - start;
System.out.println(" readContent ElapsedMills: " + elapsed + ", at: " + finish);
start = System.currentTimeMillis();
}
jis.close();
conn.close();
} catch (Exception e) {
e.printStackTrace();
}
}
static void jarEntryReadInsertDB(Connection conn, String jarEntryName, JarInputStream jis) {
BLOB blob = null;
byte[] buf;
OutputStream blobStream;
int bytesRead;
try {
blob = BLOB.createTemporary(conn, false, BLOB.DURATION_SESSION);
buf = new byte[blob.getChunkSize()];
blobStream = blob.getBinaryOutputStream();
while (jis.available() > 0) {
bytesRead = jis.read(buf);
blobStream.write(buf, 0, bytesRead);
}
CallableStatement cStmt = conn.prepareCall(INSERT_DB);
cStmt.registerOutParameter(1, OracleTypes.INTEGER);
cStmt.setString(2, jarEntryName);
cStmt.setBlob(3, blob);
cStmt.execute();
int insRows = cStmt.getInt(1);
System.out.println(" Insert DB " + insRows + " row, blob size " + blob.length() + " at " + new Date());
blob.freeTemporary();
cStmt.close();
// OraclePreparedStatement pstmt = (OraclePreparedStatement) conn.prepareStatement("insert into test_blob_tab values(?, ?)");
// pstmt.setString(1, jarEntryName);
// pstmt.setBLOB(2, blob);
// pstmt.execute();
// pstmt.close();
} catch (Exception e) {
e.printStackTrace();
}
}
static void printManifest(JarInputStream jis) {
Manifest manifest = jis.getManifest();
if (manifest != null) {
System.out.println("********* Print Manifest *********");
System.out.println("Manifest=" + manifest.toString());
Attributes mainAttributes = manifest.getMainAttributes();
System.out.println("Manifest Manifest-Version=" + mainAttributes.getValue("Manifest-Version"));
System.out.println("Manifest Created-By=" + mainAttributes.getValue("Created-By"));
} else {
System.out.println("********* No Manifest *********");
}
}
static void printSecurityProviders() throws Exception {
Provider p[] = Security.getProviders();
for (int i = 0; i < p.length; i++) {
System.out.println(" ===============" + i + ". Provider: " + p[i]);
int j = 1;
for (Enumeration e = p[i].keys(); e.hasMoreElements();) {
System.out.println("\t ----- " + j + ". Element:" + e.nextElement());
j++;
}
}
}
}
