search

eclipse-openj9 / openj9

Eclipse OpenJ9: A Java Virtual Machine for OpenJDK that's optimized for small footprint, fast start-up, and high throughput. Builds on Eclipse OMR (https://github.com/eclipse/omr) and combines with the Extensions for OpenJDK for OpenJ9 repo.
Other
3.29k stars 723 forks source link

Investigate liberty daytrader7 steady-state throughput gap between java8 and java11 #9135

Open harryyu1994 opened 4 years ago

harryyu1994 commented 4 years ago 
Compilation levels:
Level=1 numComp=7695
Level=2 numComp=10039
Level=3 numComp=6
Run 9 Throughput=2184.9 WS=618796 CPU=175313 Errors=0
Results for JDK=/home/harryayu2/sdks/java8 jvmOpts=-Xnoaot -Xmx1G 
Throughput  avg=2257.87 min=2184.90 max=2338.60 stdDev=57.2 maxVar=7.03%    confInt=1.57%   samples= 9
Intermediate results:
Run 0   2235.6  Avg=2236    CPU=166353 ms  Footprint=612788 KB
Run 1   2338.6  Avg=2339    CPU=162923 ms  Footprint=613648 KB
Run 2   2315.9  Avg=2316    CPU=167866 ms  Footprint=608356 KB
Run 3   2270.6  Avg=2271    CPU=169253 ms  Footprint=606584 KB
Run 4   2258.6  Avg=2259    CPU=170535 ms  Footprint=606376 KB
Run 5   2186.3  Avg=2186    CPU=167245 ms  Footprint=605152 KB
Run 6   2214.8  Avg=2215    CPU=169812 ms  Footprint=601064 KB
Run 7   2315.5  Avg=2316    CPU=165812 ms  Footprint=606920 KB
Run 8   2184.9  Avg=2185    CPU=175313 ms  Footprint=618796 KB
CompTime    avg=168345.78   min=162923.00   max=175313.00   stdDev=3491.9   maxVar=7.60%    confInt=1.29%   samples= 9
Footprint   avg=608853.78   min=601064.00   max=618796.00   stdDev=5326.5   maxVar=2.95%    confInt=0.54%   samples= 9
Level=1 numComp=7312
Level=2 numComp=10454
Level=3 numComp=6
Run 9 Throughput=2190.4 WS=618956 CPU=168973 Errors=0
Results for JDK=/home/harryayu2/sdks/java11 jvmOpts=-Xnoaot -Xmx1G 
Throughput  avg=2175.72 min=2096.00 max=2316.70 stdDev=67.3 maxVar=10.53%   confInt=1.92%   samples= 9
Intermediate results:
Run 0   2137.9  Avg=2138    CPU=172329 ms  Footprint=640228 KB
Run 1   2316.7  Avg=2317    CPU=158169 ms  Footprint=608228 KB
Run 2   2219.4  Avg=2219    CPU=167760 ms  Footprint=612148 KB
Run 3   2129.2  Avg=2129    CPU=174637 ms  Footprint=628884 KB
Run 4   2124.5  Avg=2124    CPU=174872 ms  Footprint=617940 KB
Run 5   2155.7  Avg=2156    CPU=169916 ms  Footprint=637068 KB
Run 6   2096.0  Avg=2096    CPU=177876 ms  Footprint=622904 KB
Run 7   2211.7  Avg=2212    CPU=169638 ms  Footprint=627580 KB
Run 8   2190.4  Avg=2190    CPU=168973 ms  Footprint=618956 KB
CompTime    avg=170463.33   min=158169.00   max=177876.00   stdDev=5667.3   maxVar=12.46%   confInt=2.06%   samples= 9
Footprint   avg=623770.67   min=608228.00   max=640228.00   stdDev=10740.8  maxVar=5.26%    confInt=1.07%   samples= 9

liberty version: liberty-20.0.0.2_wlp_webProfile7_java8 (https://developer.ibm.com/wasdev/downloads/#asset/runtimes-webprofile7-ibm-java)

(2257.87-2175.72)/2257.87 = 0.03638384849

3.6% Throughput gap.

mpirvu commented 4 years ago

Confidence interval is quite large for throughput 1.6% - 1.9% The maximum value is about the same for both Java8 and Java11, the minimum is better for Java8. It is going to be difficult to track this one because of the fluctuation.

Have you pinned the JVM to a specific set of processors?

mpirvu commented 4 years ago

Let's use only warm compilations with -Xjit:initialOptLevel=warm,inhibitRecompilation and maybe do the same for the cold opt level, hoping the gap will stay the same.

mpirvu commented 4 years ago

How is the stimulus/load applied? We typically so 1 client for 60 seconds followed by 2-3 bursts of 50 clients for 180 sec.

harryyu1994 commented 4 years ago

Have you pinned the JVM to a specific set of processors?

my $wasCPUSet = "0,1,32,33"; my $db2CPUSet = "16-23"; my $clientCPUSet = "48-55";

harryyu1994 commented 4 years ago

How is the stimulus/load applied? We typically so 1 client for 60 seconds followed by 2-3 bursts of 50 clients for 180 sec.

10 runs: 1 cold run + 9 warm runs Each run is 50 clients for 300 seconds (No 1-client involved)

I will change the configuration so that we do a single 1-client run for 60 seconds then 3 50-client runs each for 180 seconds. @mpirvu Is this what's preferred?

mpirvu commented 4 years ago

I assume that each of the 10 runs is a new JVM invocation. If that is the case, then measuring throughput for the first 300 seconds captures the rampup phase were all compilations are happeining. If Java11 is heavier in compilation it may show a lower throughput. I woud like to separate the concerns by using a warm-up period of 60 seconds with one client, followed by 1 or 2 periods of 3 minutes with 50 clients. If needed I have the script that achieves that.

harryyu1994 commented 4 years ago

Warm compilations only:

Compilation levels:
Level=2 numComp=12974
Run 9 Throughput=3093.4 WS=603700 CPU=130928 Errors=0
Results for JDK=/home/harryayu2/sdks/java8 jvmOpts=-Xnoaot -Xmx1G -Xjit:initialOptLevel=warm,inhibitRecompilation
Throughput  avg=3078.88 min=3031.60 max=3113.60 stdDev=28.6 maxVar=2.70%    confInt=0.58%   samples= 9
Intermediate results:
Run 0   131.9   2650.3  3086.8  3053.8  Avg=3054    CPU=124467 ms  Footprint=590964 KB
Run 1   163.8   2709.5  3074.7  3087.8  Avg=3088    CPU=125897 ms  Footprint=612708 KB
Run 2   144.4   2679.7  3139.5  3110.3  Avg=3110    CPU=126396 ms  Footprint=596324 KB
Run 3   166.1   2713.1  3112.7  3085.4  Avg=3085    CPU=121880 ms  Footprint=602964 KB
Run 4   153.0   2597.6  3095.2  3113.6  Avg=3114    CPU=130583 ms  Footprint=596524 KB
Run 5   138.0   2697.6  3112.3  3087.7  Avg=3088    CPU=124150 ms  Footprint=595776 KB
Run 6   172.4   2696.0  3028.2  3031.6  Avg=3032    CPU=128667 ms  Footprint=603276 KB
Run 7   162.7   2689.5  3071.9  3046.3  Avg=3046    CPU=125665 ms  Footprint=599936 KB
Run 8   172.1   2687.3  3123.1  3093.4  Avg=3093    CPU=130928 ms  Footprint=603700 KB
CompTime    avg=126514.78   min=121880.00   max=130928.00   stdDev=3021.7   maxVar=7.42%    confInt=1.48%   samples= 9
Footprint   avg=600241.33   min=590964.00   max=612708.00   stdDev=6317.3   maxVar=3.68%    confInt=0.65%   samples= 9
Level=2 numComp=13305
Run 9 Throughput=2964 WS=609736 CPU=137585 Errors=0
Results for JDK=/home/harryayu2/sdks/java11 jvmOpts=-Xnoaot -Xmx1G -Xjit:initialOptLevel=warm,inhibitRecompilation
Throughput  avg=2948.32 min=2884.70 max=3001.30 stdDev=36.5 maxVar=4.04%    confInt=0.77%   samples= 9
Intermediate results:
Run 0   143.1   2540.5  3009.1  2955.1  Avg=2955    CPU=134932 ms  Footprint=605224 KB
Run 1   150.0   2536.2  2956.6  2921.2  Avg=2921    CPU=134527 ms  Footprint=616476 KB
Run 2   155.2   2570.2  2983.2  2973.2  Avg=2973    CPU=134011 ms  Footprint=620252 KB
Run 3   172.6   2574.1  2954.6  2968.5  Avg=2968    CPU=134670 ms  Footprint=608428 KB
Run 4   139.1   2534.0  2940.8  2907.9  Avg=2908    CPU=135342 ms  Footprint=616440 KB
Run 5   134.7   2516.4  2996.2  3001.3  Avg=3001    CPU=139006 ms  Footprint=612512 KB
Run 6   145.5   2568.8  2975.8  2884.7  Avg=2885    CPU=134862 ms  Footprint=623276 KB
Run 7   143.9   2576.5  2951.9  2959.0  Avg=2959    CPU=136426 ms  Footprint=612496 KB
Run 8   170.8   2519.2  2961.8  2964.0  Avg=2964    CPU=137585 ms  Footprint=609736 KB
CompTime    avg=135706.78   min=134011.00   max=139006.00   stdDev=1647.7   maxVar=3.73%    confInt=0.75%   samples= 9
Footprint   avg=613871.11   min=605224.00   max=623276.00   stdDev=5785.6   maxVar=2.98%    confInt=0.58%   samples= 9
harryyu1994 commented 4 years ago

Actually since I'm not even using AOT, what effect does the 1-client warmup have? Should I turn on AOT and SCC? @mpirvu

harryyu1994 commented 4 years ago

Is what we are trying to compare here the code quality of the optimizer?

mpirvu commented 4 years ago

4.2% gap with just warm compilations.

Actually since I'm not even using AOT, what effect does the 1-client warmup have

It excludes the time to perform compilations. Assuming Java11 takes more CPU to compile, but eventually reaches the same peak throughput, it will appear as a false regression because that CPU is taken at the expense of application threads.

mpirvu commented 4 years ago

Java11 consumes 7% more CPU for compilations.

Let's do the same for cold because cold compilations are easier to investigate when we generate compilation logs.

harryyu1994 commented 4 years ago

Cold Compilations Only

Compilation levels:
Level=1 numComp=14200
Run 9 Throughput=2149.4 WS=493948 CPU=19983 Errors=0
Results for JDK=/home/harryayu2/sdks/java8 jvmOpts=-Xnoaot -Xmx1G -Xjit:initialOptLevel=cold,inhibitRecompilation
Throughput  avg=2149.14 min=2117.90 max=2171.80 stdDev=16.4 maxVar=2.54%    confInt=0.47%   samples= 9
Intermediate results:
Run 0   174.6   2007.0  2120.1  2135.1  Avg=2135    CPU=20094 ms  Footprint=484808 KB
Run 1   174.1   2024.7  2176.2  2169.8  Avg=2170    CPU=19854 ms  Footprint=501544 KB
Run 2   181.8   2028.6  2142.4  2171.8  Avg=2172    CPU=20226 ms  Footprint=512856 KB
Run 3   165.6   1996.0  2134.4  2147.5  Avg=2148    CPU=20172 ms  Footprint=510984 KB
Run 4   181.3   2038.5  2143.6  2154.0  Avg=2154    CPU=20086 ms  Footprint=503836 KB
Run 5   170.4   2042.5  2131.3  2150.3  Avg=2150    CPU=20171 ms  Footprint=506524 KB
Run 6   188.1   2047.0  2127.4  2117.9  Avg=2118    CPU=20052 ms  Footprint=512732 KB
Run 7   184.7   2035.7  2164.3  2146.5  Avg=2146    CPU=20001 ms  Footprint=489088 KB
Run 8   178.0   2035.5  2106.5  2149.4  Avg=2149    CPU=19983 ms  Footprint=493948 KB
CompTime    avg=20071.00    min=19854.00    max=20226.00    stdDev=114.6    maxVar=1.87%    confInt=0.35%   samples= 9
Footprint   avg=501813.33   min=484808.00   max=512856.00   stdDev=10395.9  maxVar=5.79%    confInt=1.28%   samples= 9
Compilation levels:
Level=1 numComp=14478
Level=2 numComp=2
Run 9 Throughput=2005.6 WS=512672 CPU=20038 Errors=0
Results for JDK=/home/harryayu2/sdks/java11 jvmOpts=-Xnoaot -Xmx1G -Xjit:initialOptLevel=cold,inhibitRecompilation
Throughput  avg=2040.53 min=2005.60 max=2062.90 stdDev=17.3 maxVar=2.86%    confInt=0.53%   samples= 9
Intermediate results:
Run 0   175.3   1909.7  2022.9  2035.1  Avg=2035    CPU=20312 ms  Footprint=519608 KB
Run 1   168.3   1958.3  2066.5  2057.8  Avg=2058    CPU=20521 ms  Footprint=539056 KB
Run 2   170.9   1927.6  2017.4  2062.9  Avg=2063    CPU=20293 ms  Footprint=509676 KB
Run 3   176.2   1912.2  2029.3  2030.1  Avg=2030    CPU=20850 ms  Footprint=520340 KB
Run 4   170.5   1931.6  2040.2  2041.8  Avg=2042    CPU=20712 ms  Footprint=501584 KB
Run 5   153.3   1903.1  2051.0  2046.2  Avg=2046    CPU=20654 ms  Footprint=538680 KB
Run 6   173.3   1933.1  2056.1  2052.4  Avg=2052    CPU=20335 ms  Footprint=517460 KB
Run 7   144.8   1896.6  2053.5  2032.9  Avg=2033    CPU=20610 ms  Footprint=528204 KB
Run 8   131.9   1857.6  1998.6  2005.6  Avg=2006    CPU=20038 ms  Footprint=512672 KB
CompTime    avg=20480.56    min=20038.00    max=20850.00    stdDev=254.7    maxVar=4.05%    confInt=0.77%   samples= 9
Footprint   avg=520808.89   min=501584.00   max=539056.00   stdDev=12647.4  maxVar=7.47%    confInt=1.51%   samples= 9
mpirvu commented 4 years ago

5% gap with just cold compilations and the CI has been reduced to about 0.5%. I wonder if the trend continues if we use noOpt.

harryyu1994 commented 4 years ago

NoOpt Compilations Only

Compilation levels:
Level=0 numComp=15008
Run 9 Throughput=1398.2 WS=437808 CPU=9277 Errors=0
Results for JDK=/home/harryayu2/sdks/java8 jvmOpts=-Xnoaot -Xmx1G -Xjit:initialOptLevel=noOpt,inhibitRecompilation
Throughput  avg=1397.88 min=1373.90 max=1419.80 stdDev=13.6 maxVar=3.34%    confInt=0.60%   samples= 9
Intermediate results:
Run 0   121.3   1317.7  1392.9  1409.5  Avg=1410    CPU=8810 ms  Footprint=425072 KB
Run 1   140.7   1326.3  1384.3  1419.8  Avg=1420    CPU=9341 ms  Footprint=444228 KB
Run 2   145.0   1347.0  1394.5  1398.6  Avg=1399    CPU=9308 ms  Footprint=439996 KB
Run 3   139.6   1320.5  1387.0  1384.5  Avg=1384    CPU=9345 ms  Footprint=428268 KB
Run 4   139.3   1340.5  1403.0  1390.5  Avg=1390    CPU=9309 ms  Footprint=439788 KB
Run 5   139.7   1312.4  1357.1  1373.9  Avg=1374    CPU=9430 ms  Footprint=428868 KB
Run 6   150.6   1317.9  1395.0  1403.6  Avg=1404    CPU=9265 ms  Footprint=447396 KB
Run 7   151.1   1345.8  1410.5  1402.3  Avg=1402    CPU=9390 ms  Footprint=449932 KB
Run 8   151.4   1322.9  1373.6  1398.2  Avg=1398    CPU=9277 ms  Footprint=437808 KB
CompTime    avg=9275.00 min=8810.00 max=9430.00 stdDev=182.0    maxVar=7.04%    confInt=1.22%   samples= 9
Footprint   avg=437928.44   min=425072.00   max=449932.00   stdDev=8816.6   maxVar=5.85%    confInt=1.25%   samples= 9
Compilation levels:
Level=0 numComp=15458
Level=2 numComp=2
Run 9 Throughput=1342.8 WS=452080 CPU=9609 Errors=0
Results for JDK=/home/harryayu2/sdks/java11 jvmOpts=-Xnoaot -Xmx1G -Xjit:initialOptLevel=noOpt,inhibitRecompilation
Throughput  avg=1351.71 min=1336.40 max=1366.50 stdDev=8.9  maxVar=2.25%    confInt=0.41%   samples= 9
Intermediate results:
Run 0   94.9    1285.3  1358.4  1353.1  Avg=1353    CPU=9633 ms  Footprint=450616 KB
Run 1   136.5   1287.4  1322.7  1354.2  Avg=1354    CPU=9549 ms  Footprint=448064 KB
Run 2   151.4   1267.5  1328.1  1346.3  Avg=1346    CPU=9622 ms  Footprint=460196 KB
Run 3   144.7   1289.4  1358.9  1366.5  Avg=1366    CPU=9567 ms  Footprint=472240 KB
Run 4   146.0   1304.1  1332.8  1336.4  Avg=1336    CPU=9533 ms  Footprint=456364 KB
Run 5   129.5   1263.7  1349.2  1352.0  Avg=1352    CPU=9719 ms  Footprint=474816 KB
Run 6   144.2   1287.4  1341.5  1356.5  Avg=1356    CPU=9469 ms  Footprint=454956 KB
Run 7   114.8   1284.2  1366.5  1357.6  Avg=1358    CPU=9685 ms  Footprint=441896 KB
Run 8   141.7   1278.0  1335.0  1342.8  Avg=1343    CPU=9609 ms  Footprint=452080 KB
CompTime    avg=9598.44 min=9469.00 max=9719.00 stdDev=77.7 maxVar=2.64%    confInt=0.50%   samples= 9
Footprint   avg=456803.11   min=441896.00   max=474816.00   stdDev=10822.8  maxVar=7.45%    confInt=1.47%   samples= 9
harryyu1994 commented 4 years ago

3.9% gap with NoOpt compilations and I'm guessing the CI is low enough.

mpirvu commented 4 years ago

This to me smells like path length. At this point we can generate a profile (either tprof or linux perf) and see where the biggest discrepancies are

harryyu1994 commented 4 years ago 
Results for JDK=/home/harryayu2/sdks/java8 jvmOpts=-Xnoaot -Xmx1G -Xjit:initialOptLevel=noOpt,inhibitRecompilation -agentlib:jprof=tprof,logpath=/home/harryayu2/scripts
Throughput  avg=1393.55 min=1380.50 max=1406.60 stdDev=18.5 maxVar=1.89%    confInt=5.91%   samples= 2
Intermediate results:
Run 0   149.9   1313.6  1393.3  1406.6  Avg=1407    CPU=9255 ms  Footprint=426448 KB
Run 1   154.4   1332.7  1390.3  1380.5  Avg=1380    CPU=9424 ms  Footprint=455220 KB
CompTime    avg=9339.50 min=9255.00 max=9424.00 stdDev=119.5    maxVar=1.83%    confInt=5.71%   samples= 2
Footprint   avg=440834.00   min=426448.00   max=455220.00   stdDev=20344.9  maxVar=6.75%    confInt=20.60%  samples= 2
Results for JDK=/home/harryayu2/sdks/java11 jvmOpts=-Xnoaot -Xmx1G -Xjit:initialOptLevel=noOpt,inhibitRecompilation -agentlib:jprof=tprof,logpath=/home/harryayu2/scripts
Throughput  avg=1334.35 min=1319.30 max=1349.40 stdDev=21.3 maxVar=2.28%    confInt=7.12%   samples= 2
Intermediate results:
Run 0   145.5   1266.4  1322.9  1349.4  Avg=1349    CPU=9471 ms  Footprint=444768 KB
Run 1   148.9   1249.6  1326.8  1319.3  Avg=1319    CPU=9710 ms  Footprint=466704 KB
CompTime    avg=9590.50 min=9471.00 max=9710.00 stdDev=169.0    maxVar=2.52%    confInt=7.87%   samples= 2
Footprint   avg=455736.00   min=444768.00   max=466704.00   stdDev=15511.1  maxVar=4.93%    confInt=15.20%  samples= 2

Java 8

PID 666337 18.43    java_de6d
    MOD 460492 12.74     JITCODE
    MOD 103048  2.85     vmlinux
    MOD  41823  1.16     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9vm29.so
    MOD  18486  0.51     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9gc29.so
    MOD   8169  0.23     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9jit29.so
    MOD   6929  0.19     [ip_tables]
    MOD   6325  0.17     [nf_conntrack]
    MOD   5558  0.15     /usr/lib64/libc-2.17.so
    MOD   4987  0.14     /usr/lib64/libpthread-2.17.so
    MOD   1423  0.04     /home/harryayu2/sdks/java8/jre/lib/amd64/libnet.so
    MOD   1266  0.04     [vdso]
    MOD    817  0.02     [nf_conntrack_ipv4]
    MOD    743  0.02     [nf_nat_ipv4]
    MOD    710  0.02     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libjclse29.so
    MOD    610  0.02     [xt_conntrack]
    MOD    553  0.02     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9thr29.so
    MOD    484  0.01     [nf_nat]
    MOD    438  0.01     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9prt29.so
    MOD    415  0.01     [iptable_mangle]
    MOD    309  0.01     [iptable_raw]
    MOD    301  0.01     [iptable_nat]
    MOD    301  0.01     /home/harryayu2/sdks/java8/jre/lib/amd64/j9vm/libjvm.so
    MOD    292  0.01     /home/harryayu2/sdks/java8/jre/lib/amd64/libjava.so
    MOD    246  0.01     /home/harryayu2/sdks/java8/jre/lib/amd64/libnio.so
    MOD    234  0.01     [nf_defrag_ipv4]
    MOD    227  0.01     [iptable_security]
    MOD    224  0.01     [iptable_filter]
    MOD    217  0.01     /usr/lib64/libm-2.17.so
    MOD    214  0.01     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libjvm.so
    MOD    213  0.01     /usr/lib64/libcrypto.so.1.0.2k
    MOD    105  0.00     /home/harryayu2/sdks/java8/jre/lib/amd64/libzip.so
    MOD     77  0.00     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9trc29.so
    MOD     57  0.00     /opt/pi-75050cffff_retry/Dpiperf/lib/libperfutil.so
    MOD     20  0.00     /home/harryayu2/sdks/java8/jre/lib/amd64/libjncrypto.so
    MOD     15  0.00     /usr/lib64/ld-2.17.so
    MOD      2  0.00     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9hookable29.so
    MOD      2  0.00     /opt/pi-75050cffff_retry/Dpiperf/lib/libjprof.so
    MOD      2  0.00     [igb]
    MOD      1  0.00     [usbnet]
    MOD      1  0.00     /usr/lib64/libgcc_s-4.8.5-20150702.so.1
    MOD      1  0.00     NoModule

Java 11

PID 655166 18.25    java_1ca2
    MOD 472834 13.17     JITCODE
    MOD  88390  2.46     vmlinux
    MOD  32248  0.90     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9vm29.so
    MOD  16820  0.47     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9gc29.so
    MOD   7814  0.22     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9jit29.so
    MOD   7231  0.20     /usr/lib64/libc-2.17.so
    MOD   6911  0.19     [ip_tables]
    MOD   6634  0.18     [nf_conntrack]
    MOD   4277  0.12     /usr/lib64/libpthread-2.17.so
    MOD   1814  0.05     [vdso]
    MOD   1605  0.04     /home/harryayu2/sdks/java11/lib/compressedrefs/libjclse29.so
    MOD   1587  0.04     /home/harryayu2/sdks/java11/lib/libnet.so
    MOD    875  0.02     [nf_conntrack_ipv4]
    MOD    719  0.02     [nf_nat_ipv4]
    MOD    553  0.02     [xt_conntrack]
    MOD    541  0.02     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9prt29.so
    MOD    434  0.01     [nf_nat]
    MOD    403  0.01     [iptable_mangle]
    MOD    387  0.01     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9thr29.so
    MOD    360  0.01     /home/harryayu2/sdks/java11/lib/compressedrefs/libjvm.so
    MOD    340  0.01     /home/harryayu2/sdks/java11/lib/server/libjvm.so
    MOD    338  0.01     [iptable_raw]
    MOD    292  0.01     [iptable_security]
    MOD    289  0.01     [iptable_nat]
    MOD    274  0.01     [iptable_filter]
    MOD    230  0.01     [nf_defrag_ipv4]
    MOD    205  0.01     /usr/lib64/libcrypto.so.1.0.2k
    MOD    192  0.01     /usr/lib64/libm-2.17.so
    MOD    192  0.01     /home/harryayu2/sdks/java11/lib/libnio.so
    MOD    178  0.00     /home/harryayu2/sdks/java11/lib/libjava.so
    MOD     98  0.00     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9trc29.so
    MOD     61  0.00     /opt/pi-75050cffff_retry/Dpiperf/lib/libperfutil.so
    MOD     18  0.00     /home/harryayu2/sdks/java11/lib/libjncrypto.so
    MOD     15  0.00     /usr/lib64/ld-2.17.so
    MOD      3  0.00     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9hookable29.so
    MOD      2  0.00     NoModule
    MOD      1  0.00     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9jvmti29.so
    MOD      1  0.00     /usr/lib64/libgcc_s-4.8.5-20150702.so.1
harryyu1994 commented 4 years ago

java8

PID 666337 18.43    java_de6d
    MOD 460492 12.74     JITCODE
     SYM   8445  0.23      sun/nio/cs/ISO_8859_1$Encoder.encodeISOArray([CI[BII)I_7ff2c3a25928
     SYM   6500  0.18      java/lang/Object.<init>()V_7ff2c38047a0
     SYM   6389  0.18      java/util/HashMap.getNode(ILjava/lang/Object;)Ljava/util/HashMap$Node;_7ff2c380ee28
     SYM   3927  0.11      java/lang/String.lengthInternal()I_7ff2c3801280
     SYM   3579  0.10      com/ibm/websphere/ras/TraceComponent.isAnyTracingEnabled()Z_7ff2c3835938
     SYM   3339  0.09      java/util/HashMap.hash(Ljava/lang/Object;)I_7ff2c380a1a0
     SYM   2964  0.08      java/lang/String.equals(Ljava/lang/Object;)Z_7ff2c3808180
     SYM   2885  0.08      java/lang/ThreadLocal$ThreadLocalMap.getEntry(Ljava/lang/ThreadLocal;)Ljava/lang/ThreadLocal$ThreadLocalMap$Entry;_7ff2c3827be0
     SYM   2799  0.08      java/lang/J9VMInternals.fastIdentityHashCode(Ljava/lang/Object;)I_7ff2c3814980
     SYM   2626  0.07      java/lang/String.charAtInternal(I[C)C_7ff2c3803a88
     SYM   2371  0.07      java/lang/String.regionMatchesInternal(Ljava/lang/String;Ljava/lang/String;[C[CIII)Z_7ff2c38087e8
     SYM   2173  0.06      java/lang/String.charAt(I)C_7ff2c3803b20
     SYM   2116  0.06      java/lang/String.hashCode()I_7ff2c3808500
     SYM   2033  0.06      java/util/concurrent/ConcurrentHashMap.get(Ljava/lang/Object;)Ljava/lang/Object;_7ff2c384f6a0
     SYM   1888  0.05      java/util/HashMap.putVal(ILjava/lang/Object;Ljava/lang/Object;ZZ)Ljava/lang/Object;_7ff2c380b008
     SYM   1614  0.04      java/util/concurrent/ConcurrentHashMap.tabAt([Ljava/util/concurrent/ConcurrentHashMap$Node;I)Ljava/util/concurrent/ConcurrentHashMap$Node;_7ff2c38276e0
     SYM   1500  0.04      java/util/HashMap.get(Ljava/lang/Object;)Ljava/lang/Object;_7ff2c3813ce0
     SYM   1454  0.04      com/ibm/db2/jcc/am/qo.b(IZ)V_7ff2c3abeca8
     SYM   1365  0.04      java/lang/StringBuilder.append(Ljava/lang/String;)Ljava/lang/StringBuilder;_7ff2c380e380
     SYM   1286  0.04      java/util/HashMap.resize()[Ljava/util/HashMap$Node;_7ff2c3812440
     SYM   1260  0.03      com/ibm/ejs/j2c/SharedPool.getSharedConnection(Ljava/lang/Object;Ljavax/security/auth/Subject;Ljavax/resource/spi/ConnectionRequestInfo;ZLjava/lang/String;II)Lcom/ibm/ws/j2c/MCWrapper;_7ff2c3b44d48
     SYM   1193  0.03      java/lang/ThreadLocal.get()Ljava/lang/Object;_7ff2c3827a00
     SYM   1150  0.03      com/ibm/wsspi/genericbnf/KeyMatcher$KeyBucket.match(Ljava/lang/String;II)Lcom/ibm/wsspi/genericbnf/GenericKeys;_7ff2c3a37f28
     SYM   1145  0.03      com/ibm/db2/jcc/am/Agent.loggingEnabled()Z_7ff2c39ed140
     SYM   1140  0.03      java/lang/StringBuilder.toString()Ljava/lang/String;_7ff2c381b6e0
     SYM   1125  0.03      com/ibm/db2/jcc/t4/x.c()V_7ff2c3a3ab60
     SYM   1097  0.03      sun/nio/cs/UTF_8$Decoder.decode([BII[C)I_7ff2c382d168
     SYM   1051  0.03      java/lang/StringBuilder.ensureCapacityImpl(I)V_7ff2c381bac0
     SYM   1042  0.03      java/util/Hashtable.get(Ljava/lang/Object;)Ljava/lang/Object;_7ff2c38074c0
     SYM   1016  0.03      com/ibm/wsspi/webcontainer/util/BufferedWriter.write(Ljava/lang/String;II)V_7ff2c3ae8528
     SYM   1003  0.03      java/lang/ThreadLocal.getMap(Ljava/lang/Thread;)Ljava/lang/ThreadLocal$ThreadLocalMap;_7ff2c3823cc0
     SYM    933  0.03      java/lang/String.<init>([CIIZ)V_7ff2c380d1e8
     SYM    932  0.03      java/lang/String.length()I_7ff2c3807740
     SYM    928  0.03      org/apache/myfaces/view/facelets/tag/jsf/ComponentTagHandlerDelegate.apply(Ljavax/faces/view/facelets/FaceletContext;Ljavax/faces/component/UIComponent;)V_7ff2c3b06008
     SYM    886  0.02      com/ibm/tx/jta/impl/TransactionImpl.equals(Ljava/lang/Object;)Z_7ff2c3e22860
     SYM    868  0.02      java/lang/StringBuilder.<init>(I)V_7ff2c381c1e0
     SYM    837  0.02      com/ibm/ws/tx/util/logging/WASTraceComponent.isEntryEnabled()Z_7ff2c3980720
     SYM    835  0.02      sun/nio/cs/UTF_8$Encoder.encodeArrayLoop(Ljava/nio/CharBuffer;Ljava/nio/ByteBuffer;)Ljava/nio/charset/CoderResult;_7ff2c39cc3e8
     SYM    834  0.02      org/eclipse/persistence/internal/descriptors/ObjectBuilder.buildWorkingCopyCloneFromRow(Lorg/eclipse/persistence/queries/ObjectBuildingQuery;Lorg/eclipse/persistence/internal/queries/JoinedAttributeManager;Lorg/eclipse/persistence/internal/sessions/AbstractRecord;Lorg/eclipse/persistence/internal/sessions/UnitOfWorkImpl;Ljava/lang/Object;Lorg/eclipse/persistence/internal/identitymaps/CacheKey;)Ljava/lang/Object;_7ff2c3a084e8
     SYM    831  0.02      org/apache/myfaces/shared/renderkit/html/util/HTMLEncoder.encode(Ljava/io/Writer;Ljava/lang/String;ZZZ)V_7ff2c3af5d88
     SYM    826  0.02      com/ibm/ws/rsadapter/jdbc/WSJdbcConnection.beginTransactionIfNecessary()V_7ff2c3a041a0
     SYM    818  0.02      sun/nio/cs/UTF_8$Encoder.encode([CII[B)I_7ff2c381a4e8
     SYM    813  0.02      com/ibm/db2/jcc/t4/x.r()I_7ff2c3a26000
     SYM    802  0.02      java/lang/String.decompressedArrayCopy([CI[CII)V_7ff2c3809d08
     SYM    802  0.02      com/ibm/ejs/j2c/PoolManager.reserve(Ljavax/resource/spi/ManagedConnectionFactory;Ljavax/security/auth/Subject;Ljavax/resource/spi/ConnectionRequestInfo;Ljava/lang/Object;ZZII)Lcom/ibm/ws/j2c/MCWrapper;_7ff2c3a912a8
     SYM    799  0.02      javax/faces/component/UIComponent.popComponentFromEL(Ljavax/faces/context/FacesContext;)V_7ff2c3ae6800
     SYM    793  0.02      org/eclipse/persistence/internal/databaseaccess/DatabaseAccessor.basicExecuteCall(Lorg/eclipse/persistence/queries/Call;Lorg/eclipse/persistence/internal/sessions/AbstractRecord;Lorg/eclipse/persistence/internal/sessions/AbstractSession;Z)Ljava/lang/Object;_7ff2c3a74e28
     SYM    780  0.02      com/ibm/ws/jpa/container/eclipselink/logging/EclipseLinkLogger.getLogChannel(Ljava/lang/String;)Lcom/ibm/ws/jpa/container/eclipselink/logging/LogChannel;_7ff2c3a2af00
     SYM    770  0.02      java/util/concurrent/atomic/AtomicReference.get()Ljava/lang/Object;_7ff2c3850860
     SYM    766  0.02      com/ibm/db2/jcc/t4/ab.v(Lcom/ibm/db2/jcc/am/vo;)Lcom/ibm/db2/jcc/t4/i;_7ff2c3a294e0
     SYM    747  0.02      com/ibm/db2/jcc/t4/x.b(I)I_7ff2c3ab3ec0
     SYM    713  0.02      javax/faces/component/_ComponentAttributesMap.containsKey(Ljava/lang/Object;)Z_7ff2c3ae5640
     SYM    665  0.02      org/eclipse/persistence/internal/databaseaccess/DatabaseAccessor.getObjectThroughOptimizedDataConversion(Ljava/sql/ResultSet;Lorg/eclipse/persistence/internal/helper/DatabaseField;IILorg/eclipse/persistence/internal/databaseaccess/DatabasePlatform;Lorg/eclipse/persistence/internal/sessions/AbstractSession;)Ljava/lang/Object;_7ff2c39efe28

java11

PID 655166 18.25    java_1ca2
    MOD 472834 13.17     JITCODE
     SYM   8439  0.24      sun/nio/cs/ISO_8859_1$Encoder.implEncodeISOArray([CI[BII)I_7f7f8aa5e468
     SYM   7153  0.20      java/lang/Object.<init>()V_7f7f8a816e60
     SYM   6048  0.17      java/util/HashMap.getNode(ILjava/lang/Object;)Ljava/util/HashMap$Node;_7f7f8a8218e8
     SYM   5243  0.15      java/lang/String.decompressedArrayCopy([BI[BII)V_7f7f8a817de8
     SYM   5218  0.15      java/lang/String.lengthInternal()I_7f7f8a816ae0
     SYM   3318  0.09      com/ibm/websphere/ras/TraceComponent.isAnyTracingEnabled()Z_7f7f8a8b7158
     SYM   3219  0.09      java/util/HashMap.hash(Ljava/lang/Object;)I_7f7f8a8192e0
     SYM   3033  0.08      java/lang/ThreadLocal$ThreadLocalMap.getEntry(Ljava/lang/ThreadLocal;)Ljava/lang/ThreadLocal$ThreadLocalMap$Entry;_7f7f8a842a40
     SYM   2602  0.07      java/lang/String.charAtInternal(I[B)C_7f7f8a817068
     SYM   2553  0.07      java/lang/J9VMInternals.fastIdentityHashCode(Ljava/lang/Object;)I_7f7f8a819460
     SYM   2490  0.07      java/lang/String.equals(Ljava/lang/Object;)Z_7f7f8a81c6c0
     SYM   2408  0.07      java/lang/String.regionMatchesInternal(Ljava/lang/String;Ljava/lang/String;[B[BIII)Z_7f7f8a8188a8
     SYM   2259  0.06      java/lang/String.hashCode()I_7f7f8a816f00
     SYM   1901  0.05      java/lang/String.charAt(I)C_7f7f8a81a280
     SYM   1781  0.05      java/util/HashMap.putVal(ILjava/lang/Object;Ljava/lang/Object;ZZ)Ljava/lang/Object;_7f7f8a8199a8
     SYM   1714  0.05      java/lang/String.decompressedArrayCopy([BI[CII)V_7f7f8a83ad28
     SYM   1685  0.05      java/lang/StringUTF16.putChar([BII)V_7f7f8a81a7a8
     SYM   1594  0.04      java/util/concurrent/ConcurrentHashMap.get(Ljava/lang/Object;)Ljava/lang/Object;_7f7f8a821640
     SYM   1547  0.04      java/util/concurrent/ConcurrentHashMap.tabAt([Ljava/util/concurrent/ConcurrentHashMap$Node;I)Ljava/util/concurrent/ConcurrentHashMap$Node;_7f7f8a8196a0
     SYM   1541  0.04      java/lang/StringCoding.decodeUTF8_0([BIIZ)Ljava/lang/StringCoding$Result;_7f7f8a86d7e8
     SYM   1425  0.04      java/util/Arrays.copyOfRange([BII)[B_7f7f8a82b088
     SYM   1367  0.04      java/lang/ThreadLocal.get()Ljava/lang/Object;_7f7f8a83d520
     SYM   1320  0.04      java/util/HashMap.get(Ljava/lang/Object;)Ljava/lang/Object;_7f7f8a824b80
     SYM   1311  0.04      java/util/HashMap.resize()[Ljava/util/HashMap$Node;_7f7f8a830c20
     SYM   1310  0.04      com/ibm/db2/jcc/am/Agent.loggingEnabled()Z_7f7f8aa2cb20
     SYM   1307  0.04      java/lang/ThreadLocal.getMap(Ljava/lang/Thread;)Ljava/lang/ThreadLocal$ThreadLocalMap;_7f7f8a842160
     SYM   1228  0.03      com/ibm/db2/jcc/am/qo.b(IZ)V_7f7f8aa671c8
     SYM   1195  0.03      com/ibm/ejs/j2c/SharedPool.getSharedConnection(Ljava/lang/Object;Ljavax/security/auth/Subject;Ljavax/resource/spi/ConnectionRequestInfo;ZLjava/lang/String;II)Lcom/ibm/ws/j2c/MCWrapper;_7f7f8aaa30a8
     SYM   1137  0.03      java/lang/AbstractStringBuilder.ensureCapacityInternal(I)V_7f7f8a81d8a0
     SYM   1119  0.03      java/lang/StringUTF16.newBytesFor(I)[B_7f7f8a82ba98
     SYM   1103  0.03      com/ibm/wsspi/genericbnf/KeyMatcher$KeyBucket.match(Ljava/lang/String;II)Lcom/ibm/wsspi/genericbnf/GenericKeys;_7f7f8aa6e168
     SYM   1091  0.03      java/lang/String.length()I_7f7f8a81ea00
     SYM   1080  0.03      java/util/Hashtable.get(Ljava/lang/Object;)Ljava/lang/Object;_7f7f8a82d360
     SYM   1059  0.03      java/lang/AbstractStringBuilder.append(Ljava/lang/String;)Ljava/lang/AbstractStringBuilder;_7f7f8a823560
     SYM   1031  0.03      java/util/Arrays.copyOf([BI)[B_7f7f8a825a20
     SYM   1025  0.03      java/lang/reflect/Method.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;_7f7f8a87f448
     SYM    986  0.03      java/lang/Integer.valueOf(I)Ljava/lang/Integer;_7f7f8a841458
     SYM    984  0.03      com/ibm/db2/jcc/t4/x.c()V_7f7f8aa771e0
     SYM    977  0.03      java/lang/ThreadLocal$ThreadLocalMap.getEntryAfterMiss(Ljava/lang/ThreadLocal;ILjava/lang/ThreadLocal$ThreadLocalMap$Entry;)Ljava/lang/ThreadLocal$ThreadLocalMap$Entry;_7f7f8a8bf728
     SYM    967  0.03      com/ibm/wsspi/webcontainer/util/BufferedWriter.write(Ljava/lang/String;II)V_7f7f8ae8f208
     SYM    962  0.03      org/eclipse/persistence/internal/descriptors/ObjectBuilder.buildWorkingCopyCloneFromRow(Lorg/eclipse/persistence/queries/ObjectBuildingQuery;Lorg/eclipse/persistence/internal/queries/JoinedAttributeManager;Lorg/eclipse/persistence/internal/sessions/AbstractRecord;Lorg/eclipse/persistence/internal/sessions/UnitOfWorkImpl;Ljava/lang/Object;Lorg/eclipse/persistence/internal/identitymaps/CacheKey;)Ljava/lang/Object;_7f7f8aa482a8
     SYM    883  0.02      java/nio/charset/Charset.lookup(Ljava/lang/String;)Ljava/nio/charset/Charset;_7f7f8a85e300
     SYM    868  0.02      org/apache/myfaces/view/facelets/tag/jsf/ComponentTagHandlerDelegate.apply(Ljavax/faces/view/facelets/FaceletContext;Ljavax/faces/component/UIComponent;)V_7f7f8ae9bdc8
     SYM    843  0.02      com/ibm/ws/jpa/container/eclipselink/logging/EclipseLinkLogger.getLogChannel(Ljava/lang/String;)Lcom/ibm/ws/jpa/container/eclipselink/logging/LogChannel;_7f7f8aa656a0
     SYM    835  0.02      com/ibm/ws/tx/util/logging/WASTraceComponent.isEntryEnabled()Z_7f7f8a9b90e0
     SYM    828  0.02      org/eclipse/persistence/internal/databaseaccess/DatabaseAccessor.basicExecuteCall(Lorg/eclipse/persistence/queries/Call;Lorg/eclipse/persistence/internal/sessions/AbstractRecord;Lorg/eclipse/persistence/internal/sessions/AbstractSession;Z)Ljava/lang/Object;_7f7f8aa8b408
     SYM    828  0.02      com/ibm/tx/jta/impl/TransactionImpl.equals(Ljava/lang/Object;)Z_7f7f8ae32ca0
     SYM    824  0.02      com/ibm/db2/jcc/t4/ab.v(Lcom/ibm/db2/jcc/am/vo;)Lcom/ibm/db2/jcc/t4/i;_7f7f8ab76560
     SYM    820  0.02      java/lang/AbstractStringBuilder.putStringAt(ILjava/lang/String;)V_7f7f8a8236a8
     SYM    810  0.02      java/lang/String.decompressedArrayCopy([CI[BII)V_7f7f8a81a908
     SYM    789  0.02      org/apache/myfaces/shared/renderkit/html/util/HTMLEncoder.encode(Ljava/io/Writer;Ljava/lang/String;ZZZ)V_7f7f8ae9adc8
     SYM    785  0.02      java/lang/StringCoding.encodeUTF8_UTF16([BZ)[B_7f7f8a8264a0
     SYM    783  0.02      java/util/concurrent/atomic/AtomicReference.get()Ljava/lang/Object;_7f7f8a8726e0
     SYM    763  0.02      sun/nio/cs/UTF_8$Encoder.encodeArrayLoop(Ljava/nio/CharBuffer;Ljava/nio/ByteBuffer;)Ljava/nio/charset/CoderResult;_7f7f8a9f3948
     SYM    750  0.02      java/util/ArrayList.get(I)Ljava/lang/Object;_7f7f8a950000
     SYM    736  0.02      org/eclipse/persistence/internal/databaseaccess/DatabaseAccessor.getObjectThroughOptimizedDataConversion(Ljava/sql/ResultSet;Lorg/eclipse/persistence/internal/helper/DatabaseField;IILorg/eclipse/persistence/internal/databaseaccess/DatabasePlatform;Lorg/eclipse/persistence/internal/sessions/AbstractSession;)Ljava/lang/Object;_7f7f8aa2fba8
     SYM    733  0.02      com/ibm/ws/rsadapter/jdbc/WSJdbcConnection.beginTransactionIfNecessary()V_7f7f8aa40860
     SYM    714  0.02      com/ibm/ejs/j2c/PoolManager.reserve(Ljavax/resource/spi/ManagedConnectionFactory;Ljavax/security/auth/Subject;Ljavax/resource/spi/ConnectionRequestInfo;Ljava/lang/Object;ZZII)Lcom/ibm/ws/j2c/MCWrapper;_7f7f8aaaeda8
     SYM    695  0.02      com/ibm/db2/jcc/t4/x.r()I_7f7f8aa5f1e0
     SYM    690  0.02      org/eclipse/persistence/internal/descriptors/ObjectBuilder.buildAttributesIntoWorkingCopyClone(Ljava/lang/Object;Lorg/eclipse/persistence/internal/identitymaps/CacheKey;Lorg/eclipse/persistence/queries/ObjectBuildingQuery;Lorg/eclipse/persistence/internal/queries/JoinedAttributeManager;Lorg/eclipse/persistence/internal/sessions/AbstractRecord;Lorg/eclipse/persistence/internal/sessions/UnitOfWorkImpl;Z)V_7f7f8aa4fd08
     SYM    687  0.02      java/util/IdentityHashMap.put(Ljava/lang/Object;Ljava/lang/Object;)Ljava/lang/Object;_7f7f8a920348
     SYM    686  0.02      javax/faces/component/UIComponent.popComponentFromEL(Ljavax/faces/context/FacesContext;)V_7f7f8ae8be80
     SYM    685  0.02      java/lang/Boolean.booleanValue()Z_7f7f8a871820
     SYM    676  0.02      java/util/HashMap$Node.<init>(ILjava/lang/Object;Ljava/lang/Object;Ljava/util/HashMap$Node;)V_7f7f8a820ec8
     SYM    669  0.02      java/lang/String.getBytes([BIB)V_7f7f8a823888
     SYM    639  0.02      javax/faces/component/_ComponentAttributesMap.containsKey(Ljava/lang/Object;)Z_7f7f8ae8d900
     SYM    634  0.02      java/lang/AbstractStringBuilder.isLatin1()Z_7f7f8a81a880
     SYM    632  0.02      java/util/concurrent/ConcurrentHashMap$Traverser.advance()Ljava/util/concurrent/ConcurrentHashMap$Node;_7f7f8a867260
     SYM    628  0.02      com/ibm/db2/jcc/t4/x.b(I)I_7f7f8aae6f20
     SYM    621  0.02      com/ibm/db2/jcc/t4/c.b(I)Z_7f7f8aa2cec0
     SYM    620  0.02      java/util/ArrayList.add(Ljava/lang/Object;[Ljava/lang/Object;I)V_7f7f8a82df28
     SYM    617  0.02      org/eclipse/persistence/internal/databaseaccess/DatabaseAccessor.fetchRow(Ljava/util/Vector;[Lorg/eclipse/persistence/internal/helper/DatabaseField;Ljava/sql/ResultSet;Ljava/sql/ResultSetMetaData;Lorg/eclipse/persistence/internal/sessions/AbstractSession;)Lorg/eclipse/persistence/internal/sessions/AbstractRecord;_7f7f8aa38188
     SYM    610  0.02      java/util/LinkedList.remove(Ljava/lang/Object;)Z_7f7f8ab09620
     SYM    601  0.02      org/eclipse/persistence/descriptors/DescriptorEventManager.executeEvent(Lorg/eclipse/persistence/descriptors/DescriptorEvent;)V_7f7f8aa52bc0
     SYM    600  0.02      java/lang/Object.hashCode()I_7f7f8a8239e0
     SYM    591  0.02      java/lang/ThreadLocal$ThreadLocalMap.set(Ljava/lang/ThreadLocal;Ljava/lang/Object;)V_7f7f8a8863e8
     SYM    588  0.02      java/lang/StringUTF16.newString([BII)Ljava/lang/String;_7f7f8a82b428
     SYM    587  0.02      com/ibm/ws/tcpchannel/internal/TCPBaseRequestContext.setBuffers([Lcom/ibm/wsspi/bytebuffer/WsByteBuffer;)V_7f7f8aabf360
     SYM    582  0.02      com/ibm/tx/jta/impl/RegisteredSyncs.coreDistributeAfter(I)V_7f7f8aadf920
     SYM    579  0.02      java/util/HashMap.newNode(ILjava/lang/Object;Ljava/lang/Object;Ljava/util/HashMap$Node;)Ljava/util/HashMap$Node;_7f7f8a821108
     SYM    569  0.02      java/lang/StringBuilder.toString()Ljava/lang/String;_7f7f8a82b9a0
     SYM    563  0.02      java/lang/String.deduplicateStrings(Ljava/lang/String;Ljava/lang/Object;Ljava/lang/String;Ljava/lang/Object;)V_7f7f8a83a288
     SYM    561  0.02      com/ibm/ejs/j2c/ConnectionManager.allocateConnection(Ljavax/resource/spi/ManagedConnectionFactory;Ljavax/resource/spi/ConnectionRequestInfo;)Ljava/lang/Object;_7f7f8ab46368
     SYM    561  0.02      java/lang/String.equalsIgnoreCase(Ljava/lang/String;)Z_7f7f8a863dc0
     SYM    560  0.02      java/util/HashMap.removeNode(ILjava/lang/Object;Ljava/lang/Object;ZZ)Ljava/util/HashMap$Node;_7f7f8a881f88
     SYM    541  0.02      java/util/ArrayList$Itr.next()Ljava/lang/Object;_7f7f8a832ba0
     SYM    535  0.01      com/ibm/db2/jcc/am/ResultSet.nextX()Z_7f7f8aa43460
     SYM    533  0.01      org/apache/myfaces/application/ApplicationImpl.publishEvent(Ljavax/faces/context/FacesContext;Ljava/lang/Class;Ljava/lang/Class;Ljava/lang/Object;)V_7f7f8aea2488
     SYM    530  0.01      javax/faces/component/_ComponentChildrenList.get(I)Ljavax/faces/component/UIComponent;_7f7f8ae8e020
     SYM    529  0.01      java/lang/Boolean.valueOf(Z)Ljava/lang/Boolean;_7f7f8a88e438
     SYM    528  0.01      com/ibm/ejs/container/EJSContainer.postInvoke(Lcom/ibm/ejs/container/EJSWrapperBase;ILcom/ibm/ejs/container/EJSDeployedSupport;)V_7f7f8aacafa8
     SYM    525  0.01      com/ibm/ws/webcontainer/srt/SRTServletRequestThreadData.getInstance()Lcom/ibm/ws/webcontainer/srt/SRTServletRequestThreadData;_7f7f8aa5daf8
     SYM    524  0.01      org/jboss/weld/manager/BeanManagerImpl.internalGetContext(Ljava/lang/Class;)Ljavax/enterprise/context/spi/Context;_7f7f8ababa40
     SYM    523  0.01      java/lang/Object.clone()Ljava/lang/Object;_7f7f8a869fe0
     SYM    521  0.01      com/ibm/db2/jcc/t4/db.b(Ljava/io/OutputStream;)V_7f7f8aaeb1a0
     SYM    518  0.01      com/ibm/ejs/j2c/MCWrapper.setPoolState(I)V_7f7f8aa78960
     SYM    515  0.01      com/ibm/ws/rsadapter/impl/CacheMap.remove(Ljava/lang/Object;)Ljava/lang/Object;_7f7f8aac8e60
     SYM    514  0.01      com/ibm/db2/jcc/t4/x.c(I)I_7f7f8aa5e600
     SYM    510  0.01      com/ibm/tx/jta/impl/RegisteredSyncs.coreDistributeBefore()V_7f7f8aaed020
     SYM    505  0.01      java/util/ArrayList.elementData(I)Ljava/lang/Object;_7f7f8a8301e0
     SYM    504  0.01      java/io/PrintWriter.write(Ljava/lang/String;II)V_7f7f8ae8ee28
     SYM    500  0.01      java/util/ArrayList$Itr.hasNext()Z_7f7f8a832480
     SYM    499  0.01      com/ibm/db2/jcc/am/ResultSet.<init>(Lcom/ibm/db2/jcc/am/Agent;Lcom/ibm/db2/jcc/am/po;Lcom/ibm/db2/jcc/am/jc;III)V_7f7f8ab788e8
     SYM    497  0.01      com/ibm/ws/rsadapter/impl/WSRdbManagedConnectionImpl.getConnection(Ljavax/security/auth/Subject;Ljavax/resource/spi/ConnectionRequestInfo;)Ljava/lang/Object;_7f7f8ab54c28
     SYM    491  0.01      com/ibm/ws/jpa/container/eclipselink/logging/LogChannel.shouldLog(I)Z_7f7f8aa65ba0
     SYM    487  0.01      com/ibm/tx/jta/embeddable/impl/EmbeddableTranManagerSet.self()Lcom/ibm/tx/jta/embeddable/impl/EmbeddableTranManagerImpl;_7f7f8aa5d440
     SYM    486  0.01      org/eclipse/persistence/internal/databaseaccess/DatabaseAccessor.getObject(Ljava/sql/ResultSet;Lorg/eclipse/persistence/internal/helper/DatabaseField;Ljava/sql/ResultSetMetaData;ILorg/eclipse/persistence/internal/databaseaccess/DatabasePlatform;ZLorg/eclipse/persistence/internal/sessions/AbstractSession;)Ljava/lang/Object;_7f7f8aa2f268
mpirvu commented 4 years ago

java/lang/Object.<init>()V is more expensive in Java8, but I would start from java/lang/String.decompressedArrayCopy. We may have string compressin enabled by default in Java11, but I am not sure

harryyu1994 commented 4 years ago

Here's a java11 run with -XX:-CompactStrings. It looks like String compression is disabled by default and java/lang/String.decompressedArrayCopy([BI[BII)V is something that will get called without string compression enabled.

   PID 647465 18.11    java_07d4
    MOD 457364 12.79     JITCODE
     SYM   8023  0.22      sun/nio/cs/ISO_8859_1$Encoder.implEncodeISOArray([CI[BII)I_7fcd3af5a8c8
     SYM   6411  0.18      java/lang/Object.<init>()V_7fcd3ac40760
     SYM   5751  0.16      java/util/HashMap.getNode(ILjava/lang/Object;)Ljava/util/HashMap$Node;_7fcd3ac4cc88
     SYM   5256  0.15      java/lang/String.decompressedArrayCopy([BI[BII)V_7fcd3ac45348
     SYM   5212  0.15      java/lang/String.lengthInternal()I_7fcd3ac40580
     SYM   3269  0.09      java/util/HashMap.hash(Ljava/lang/Object;)I_7fcd3ac42a60
     SYM   3234  0.09      com/ibm/websphere/ras/TraceComponent.isAnyTracingEnabled()Z_7fcd3ad52d18
     SYM   2780  0.08      java/lang/ThreadLocal$ThreadLocalMap.getEntry(Ljava/lang/ThreadLocal;)Ljava/lang/ThreadLocal$ThreadLocalMap$Entry;_7fcd3ac60940
     SYM   2692  0.08      java/lang/String.charAtInternal(I[B)C_7fcd3ac40b08
     SYM   2530  0.07      java/lang/String.equals(Ljava/lang/Object;)Z_7fcd3ac46740
     SYM   2471  0.07      java/lang/J9VMInternals.fastIdentityHashCode(Ljava/lang/Object;)I_7fcd3ac42be0
     SYM   2393  0.07      java/lang/String.regionMatchesInternal(Ljava/lang/String;Ljava/lang/String;[B[BIII)Z_7fcd3ac45008
     SYM   2117  0.06      java/lang/String.hashCode()I_7fcd3ac40800
     SYM   2027  0.06      java/lang/String.charAt(I)C_7fcd3ac43700
     SYM   1807  0.05      java/lang/String.decompressedArrayCopy([BI[CII)V_7fcd3ac68928
     SYM   1633  0.05      java/util/concurrent/ConcurrentHashMap.get(Ljava/lang/Object;)Ljava/lang/Object;_7fcd3ac4ca00
harryyu1994 commented 4 years ago

@mpirvu Please let me know if you have any idea on how to move forward with this.

mpirvu commented 4 years ago

To summarize previous experiments with -Xnoaot and no recompilation: 1) For just warm compilations we see a 4.2% throughput gap, 7.2% more CPU and 375 more methods being compiled with Java11 2) For just cold compilations we see a 5% gap, 2% more CPU and 278 more methods being compiled 3) For just noOpt compilations we see a 3.3% gap, 3.5% more CPU and 450 more methods being compiled

One avenue of investigation would be to see which methods are consistently being compiled in Java11, but not in Java8

From the profile collected at noOpt we see 1) More ticks in jitted code 2) less ticks in VM/GC/JIT dlls 3) fewer ticks in kernel 4) More ticks in libc ==> Why?

Looking at the profile for jitted code the common thread is that String related methods take more ticks and java/lang/String.decompressedArrayCopy doesn't even appear in Java8. I do not see something in Java8 that could replace it.

I wonder if it's possible to replace the String class from Java8 into Java11 or viceversa as a test. @fjeremic how difficult would this be?

fjeremic commented 4 years ago

I wonder if it's possible to replace the String class from Java8 into Java11 or viceversa as a test. @fjeremic how difficult would this be?

This would be very difficult. The Java 11 String class is built on top of a byte[] while the Java 8 version is backed by a char[]. Moreover the Java 11 class introduces the notion of a "coder" which is used with the StringCoding classes and other classes in java.lang package.

decompressedArrayCopy in particular is a recognized method. We should generally never see that in a profile because it should always get reduced to a TR::arraycopy IL in VP. It would be interesting to find who the callers of this method are and to get traces for them and find out why the failed to replace calls to decompressedArrayCopy with TR::arraycopy.

mpirvu commented 4 years ago

The profiles above are from runs with noOpt, so inlining and VP are not performed. @harryyu1994 Let's collect a pair of profiles with initialOptLevel=cold,inhibitRecompilation, though I do expect the differences to move to TR::arraycopy in this case. I actually found String.decompressedArrayCopy in Java8 and it takes 802 ticks: SYM 802 0.02 java/lang/String.decompressedArrayCopy([CI[CII)V_7ff2c3809d08 compared to 5243 ticks in Java11 SYM 5243 0.15 java/lang/String.decompressedArrayCopy([BI[BII)V_7f7f8a817de8

harryyu1994 commented 4 years ago

initialOptLevel=cold,inhibitRecompilation

I'm going to get a brand new build and redo the experiment again. This was done with the previous script I had and the previous build I had. Things may have changed.

mpirvu commented 4 years ago

@harryyu1994 The profiles above show very close number of ticks between Java8 and Java11. When you do the next experiments please record and report the throughput from the profiled runs. I am guessing you profile for a fixed duration of time which is the same for both Java8 and Java11.

harryyu1994 commented 4 years ago 
PID 656033 37.72    java_257f8a
    MOD 378447 21.76     JITCODE
     SYM   5541  0.32      java/lang/String.equals(Ljava/lang/Object;)Z_7f412ce07000
     SYM   3054  0.18      java/lang/String.charAtInternal(I[C)C_7f412ce03de8
     SYM   2914  0.17      java/lang/ThreadLocal$ThreadLocalMap.getEntry(Ljava/lang/ThreadLocal;)Ljava/lang/ThreadLocal$ThreadLocalMap$Entry;_7f412ce19960
     SYM   2678  0.15      java/lang/String.hashCode()I_7f412ce05b40
     SYM   2617  0.15      java/util/HashMap.hash(Ljava/lang/Object;)I_7f412ce0c160
     SYM   2377  0.14      java/util/HashMap.putVal(ILjava/lang/Object;Ljava/lang/Object;ZZ)Ljava/lang/Object;_7f412ce0e328
     SYM   2116  0.12      java/util/concurrent/ConcurrentHashMap.get(Ljava/lang/Object;)Ljava/lang/Object;_7f412ce36c00
     SYM   1936  0.11      com/ibm/ws/jpa/container/eclipselink/logging/EclipseLinkLogger.getLogChannel(Ljava/lang/String;)Lcom/ibm/ws/jpa/container/eclipselink/logging/LogChannel;_7f412d186ac0
     SYM   1908  0.11      java/lang/String.charAt(I)C_7f412ce04400
     SYM   1780  0.10      java/util/concurrent/ConcurrentHashMap.tabAt([Ljava/util/concurrent/ConcurrentHashMap$Node;I)Ljava/util/concurrent/ConcurrentHashMap$Node;_7f412ce1fc80
     SYM   1768  0.10      java/lang/ThreadLocal.get()Ljava/lang/Object;_7f412ce19720
     SYM   1694  0.10      java/lang/String.<init>(Ljava/lang/String;Ljava/lang/String;)V_7f412cef5f08
     SYM   1676  0.10      com/ibm/ejs/j2c/SharedPool.getSharedConnection(Ljava/lang/Object;Ljavax/security/auth/Subject;Ljavax/resource/spi/ConnectionRequestInfo;ZLjava/lang/String;II)Lcom/ibm/ws/j2c/MCWrapper;_7f412d1d7c68
     SYM   1513  0.09      com/ibm/wsspi/webcontainer/util/BufferedWriter.write(Ljava/lang/String;II)V_7f412d488a88
     SYM   1473  0.08      com/ibm/wsspi/genericbnf/KeyMatcher$KeyBucket.match(Ljava/lang/String;II)Lcom/ibm/wsspi/genericbnf/GenericKeys;_7f412d187a48
     SYM   1454  0.08      java/lang/Object.hashCode()I_7f412ce16500
     SYM   1369  0.08      java/util/HashMap.resize()[Ljava/util/HashMap$Node;_7f412ce13ac0
     SYM   1351  0.08      javax/faces/component/UIComponent.getValueExpression(Ljava/lang/String;)Ljavax/el/ValueExpression;_7f412d48a2e0
     SYM   1246  0.07      javax/faces/component/_ComponentAttributesMap.getUnderlyingMap()Ljava/util/Map;_7f412d488340
     SYM   1229  0.07      com/ibm/tx/jta/impl/TransactionImpl.equals(Ljava/lang/Object;)Z_7f412d60a7e0
     SYM   1193  0.07      java/lang/String.getCharsNoBoundChecks(II[CI)V_7f412ce0dca8
     SYM   1192  0.07      javax/faces/component/UIComponent.popComponentFromEL(Ljavax/faces/context/FacesContext;)V_7f412d48d960
     SYM   1147  0.07      java/util/Hashtable.get(Ljava/lang/Object;)Ljava/lang/Object;_7f412ce09a20
     SYM   1103  0.06      java/lang/StringBuilder.append(Ljava/lang/String;)Ljava/lang/StringBuilder;_7f412ce0b400
     SYM   1063  0.06      com/ibm/db2/jcc/am/qo.b(IZ)V_7f412d195d88
     SYM   1050  0.06      sun/nio/cs/UTF_8$Decoder.decode([BII[C)I_7f412ce07428
     SYM   1040  0.06      javax/faces/component/UIComponent.pushComponentToEL(Ljavax/faces/context/FacesContext;Ljavax/faces/component/UIComponent;)V_7f412d48c8c8
     SYM   1026  0.06      java/lang/Enum.hashCode()I_7f412d09a380
     SYM    957  0.06      java/io/CharArrayWriter.write(Ljava/lang/String;II)V_7f412d185688
     SYM    928  0.05      java/lang/ThreadLocal$ThreadLocalMap.set(Ljava/lang/ThreadLocal;Ljava/lang/Object;)V_7f412ce46d88
     SYM    928  0.05      java/util/Arrays.copyOf([Ljava/lang/Object;ILjava/lang/Class;)[Ljava/lang/Object;_7f412ce26588
     SYM    917  0.05      com/ibm/websphere/ras/TraceComponent.isAnyTracingEnabled()Z_7f412cf395b8
     SYM    915  0.05      org/apache/myfaces/shared/renderkit/html/util/HTMLEncoder.encode(Ljava/io/Writer;Ljava/lang/String;ZZZ)V_7f412d49b3a8
     SYM    876  0.05      com/ibm/db2/jcc/t4/x.c()V_7f412d19dd40
     SYM    875  0.05      java/lang/StringCoding$StringDecoder.decode([BII)[C_7f412ce1b628
     SYM    869  0.05      sun/nio/cs/UTF_8$Encoder.encode([CII[B)I_7f412ce06888
     SYM    857  0.05      java/lang/StringCoding.decode(Ljava/lang/String;[BII)[C_7f412ce1af68
     SYM    845  0.05      com/ibm/ws/webcontainer/srt/SRTServletRequest.getAttribute(Ljava/lang/String;)Ljava/lang/Object;_7f412d1a20e0
     SYM    827  0.05      com/ibm/ws/genericbnf/internal/BNFHeadersImpl.findHeader(Lcom/ibm/wsspi/genericbnf/HeaderKeys;)Lcom/ibm/ws/genericbnf/internal/HeaderElement;_7f412d19a5e0
     SYM    820  0.05      com/ibm/db2/jcc/t4/x.r()I_7f412d17c8e0
     SYM    811  0.05      sun/nio/cs/UTF_8$Encoder.encodeArrayLoop(Ljava/nio/CharBuffer;Ljava/nio/ByteBuffer;)Ljava/nio/charset/CoderResult;_7f412d490bc8
     SYM    807  0.05      java/util/LinkedList.remove(Ljava/lang/Object;)Z_7f412d268820
PID 661353 38.59    java_254cbb
    MOD 385058 22.47     JITCODE
     SYM   5502  0.32      java/lang/String.equals(Ljava/lang/Object;)Z_7f843f186860
     SYM   3141  0.18      java/lang/String.charAtInternal(I[B)C_7f843f180fa8
     SYM   3125  0.18      java/lang/ThreadLocal$ThreadLocalMap.getEntry(Ljava/lang/ThreadLocal;)Ljava/lang/ThreadLocal$ThreadLocalMap$Entry;_7f843f1a04e0
     SYM   2674  0.16      java/lang/String.hashCode()I_7f843f17ff60
     SYM   2542  0.15      java/util/HashMap.hash(Ljava/lang/Object;)I_7f843f1836c0
     SYM   2421  0.14      java/util/HashMap.putVal(ILjava/lang/Object;Ljava/lang/Object;ZZ)Ljava/lang/Object;_7f843f182e48
     SYM   2340  0.14      java/util/concurrent/ConcurrentHashMap.get(Ljava/lang/Object;)Ljava/lang/Object;_7f843f18caa0
     SYM   2179  0.13      java/lang/StringUTF16.putChar([BII)V_7f843f185a28
     SYM   1986  0.12      java/lang/AbstractStringBuilder.ensureCapacityInternal(I)V_7f843f1884a0
     SYM   1986  0.12      java/lang/String.charAt(I)C_7f843f184720
     SYM   1804  0.11      java/lang/Object.hashCode()I_7f843f18e9a0
     SYM   1758  0.10      java/util/concurrent/ConcurrentHashMap.tabAt([Ljava/util/concurrent/ConcurrentHashMap$Node;I)Ljava/util/concurrent/ConcurrentHashMap$Node;_7f843f183880
     SYM   1722  0.10      java/lang/StringCoding.decodeUTF8_0([BIIZ)Ljava/lang/StringCoding$Result;_7f843f18a668
     SYM   1686  0.10      com/ibm/ws/jpa/container/eclipselink/logging/EclipseLinkLogger.getLogChannel(Ljava/lang/String;)Lcom/ibm/ws/jpa/container/eclipselink/logging/LogChannel;_7f843f5da240
     SYM   1548  0.09      java/lang/String.<init>(Ljava/lang/String;Ljava/lang/String;)V_7f843f468da8
     SYM   1524  0.09      com/ibm/ejs/j2c/SharedPool.getSharedConnection(Ljava/lang/Object;Ljavax/security/auth/Subject;Ljavax/resource/spi/ConnectionRequestInfo;ZLjava/lang/String;II)Lcom/ibm/ws/j2c/MCWrapper;_7f843f72f8c8
     SYM   1478  0.09      java/lang/ThreadLocal.get()Ljava/lang/Object;_7f843f1a03a0
     SYM   1449  0.08      java/util/HashMap.resize()[Ljava/util/HashMap$Node;_7f843f1a1fa0
     SYM   1366  0.08      com/ibm/tx/jta/impl/TransactionImpl.equals(Ljava/lang/Object;)Z_7f843f992440
     SYM   1323  0.08      java/lang/reflect/Method.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object;_7f843f4a2a28
     SYM   1307  0.08      com/ibm/wsspi/genericbnf/KeyMatcher$KeyBucket.match(Ljava/lang/String;II)Lcom/ibm/wsspi/genericbnf/GenericKeys;_7f843f5f73e8
     SYM   1274  0.07      java/lang/ThreadLocal.getMap(Ljava/lang/Thread;)Ljava/lang/ThreadLocal$ThreadLocalMap;_7f843f1a0320
     SYM   1175  0.07      java/util/Arrays.copyOfRange([BII)[B_7f843f196b48
     SYM   1150  0.07      javax/faces/component/UIComponent.popComponentFromEL(Ljavax/faces/context/FacesContext;)V_7f843f611000
     SYM   1125  0.07      java/lang/Enum.hashCode()I_7f843f23e780
     SYM   1122  0.07      java/util/Hashtable.get(Ljava/lang/Object;)Ljava/lang/Object;_7f843f191960
     SYM   1091  0.06      javax/faces/component/UIComponent.getValueExpression(Ljava/lang/String;)Ljavax/el/ValueExpression;_7f843f619e20
     SYM   1044  0.06      java/lang/String.getBytes([BIB)V_7f843f18bea8
     SYM   1023  0.06      com/ibm/db2/jcc/am/qo.b(IZ)V_7f843f70b808
     SYM   1015  0.06      com/ibm/wsspi/webcontainer/util/BufferedWriter.write(Ljava/lang/String;II)V_7f843f616048
     SYM   1001  0.06      java/util/Arrays.copyOf([Ljava/lang/Object;ILjava/lang/Class;)[Ljava/lang/Object;_7f843f1aa108
     SYM    997  0.06      org/apache/myfaces/shared/renderkit/html/util/HTMLEncoder.encode(Ljava/io/Writer;Ljava/lang/String;ZZZ)V_7f843f6292a8
     SYM    991  0.06      javax/faces/component/_ComponentAttributesMap.getUnderlyingMap()Ljava/util/Map;_7f843f615940
     SYM    974  0.06      java/lang/String.getCharsNoBoundChecks(II[CI)V_7f843f1e0ce8
     SYM    956  0.06      java/util/ArrayList.add(Ljava/lang/Object;)Z_7f843f19ae20
     SYM    936  0.05      javax/faces/component/_ComponentAttributesMap.containsKey(Ljava/lang/Object;)Z_7f843f613580
     SYM    936  0.05      java/nio/charset/Charset.lookup(Ljava/lang/String;)Ljava/nio/charset/Charset;_7f843f198e80
     SYM    923  0.05      javax/faces/component/UIComponent.pushComponentToEL(Ljavax/faces/context/FacesContext;Ljavax/faces/component/UIComponent;)V_7f843f61e048
     SYM    917  0.05      java/lang/AbstractStringBuilder.append(Ljava/lang/String;)Ljava/lang/AbstractStringBuilder;_7f843f18c0e0
     SYM    907  0.05      org/apache/jasper/runtime/JspWriterImpl.print(Ljava/lang/Object;)V_7f843f5d7b20
     SYM    887  0.05      com/ibm/db2/jcc/t4/x.c()V_7f843f5e37a0
     SYM    879  0.05      com/ibm/websphere/ras/TraceComponent.isAnyTracingEnabled()Z_7f843f498bd8
     SYM    856  0.05      java/util/HashMap$Node.<init>(ILjava/lang/Object;Ljava/lang/Object;Ljava/util/HashMap$Node;)V_7f843f18c228
     SYM    853  0.05      java/lang/StringCoding.encodeUTF8_UTF16([BZ)[B_7f843f189a00
     SYM    835  0.05      com/ibm/db2/jcc/t4/x.r()I_7f843f5c76c0
     SYM    813  0.05      org/eclipse/persistence/internal/databaseaccess/DatabaseAccessor.fetchRow(Ljava/util/Vector;[Lorg/eclipse/persistence/internal/helper/DatabaseField;Ljava/sql/ResultSet;Ljava/sql/ResultSetMetaData;Lorg/eclipse/persistence/internal/sessions/AbstractSession;)Lorg/eclipse/persistence/internal/sessions/AbstractRecord;_7f843f2b57c8
     SYM    810  0.05      com/ibm/db2/jcc/t4/ab.v(Lcom/ibm/db2/jcc/am/vo;)Lcom/ibm/db2/jcc/t4/i;_7f843f5e40c0
     SYM    798  0.05      com/ibm/ws/genericbnf/internal/BNFHeadersImpl.findHeader(Lcom/ibm/wsspi/genericbnf/HeaderKeys;)Lcom/ibm/ws/genericbnf/internal/HeaderElement;_7f843f5e2b00
     SYM    793  0.05      java/lang/Integer.valueOf(I)Ljava/lang/Integer;_7f843f3ba618
     SYM    789  0.05      org/apache/jasper/runtime/JspWriterImpl.write([CII)V_7f843f5f1d68
mpirvu commented 4 years ago

@harryyu1994 Could you please post the ticks in other modules as well? I am thinking that since the difference in ticks for jitted code does not account for the entire throughput drop, there could be other modules responsible for the gap. In particular I am guessing there will be an increase in ticks for JIT helpers (JIT dll).

harryyu1994 commented 4 years ago 
PID 661353 38.59    java_254cbb
    MOD 385058 22.47     JITCODE
    MOD 192365 11.23     vmlinux
    MOD  18011  1.05     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9gc29.so
    MOD  12134  0.71     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9vm29.so
    MOD  10022  0.58     [ip_tables]
    MOD   8744  0.51     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9jit29.so
    MOD   7602  0.44     [nf_conntrack]
    MOD   6496  0.38     /usr/lib64/libpthread-2.17.so
    MOD   4571  0.27     /usr/lib64/libc-2.17.so
    MOD   2413  0.14     /home/harryayu2/sdks/java11/lib/compressedrefs/libjclse29.so
    MOD   1798  0.10     /home/harryayu2/sdks/java11/lib/libnet.so
    MOD   1569  0.09     [ip_vs]
    MOD   1099  0.06     [nf_nat_ipv4]
    MOD   1074  0.06     [nf_conntrack_ipv4]
    MOD   1070  0.06     [vdso]
    MOD    849  0.05     [xt_conntrack]
    MOD    591  0.03     [iptable_mangle]
    MOD    578  0.03     [nf_nat]
    MOD    547  0.03     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9prt29.so
    MOD    476  0.03     [iptable_raw]
    MOD    435  0.03     [iptable_nat]
    MOD    392  0.02     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9thr29.so
    MOD    371  0.02     [iptable_filter]
    MOD    364  0.02     [nf_defrag_ipv4]
    MOD    362  0.02     [iptable_security]
    MOD    340  0.02     /home/harryayu2/sdks/java11/lib/server/libjvm.so
    MOD    287  0.02     /home/harryayu2/sdks/java11/lib/libnio.so
    MOD    277  0.02     /home/harryayu2/sdks/java11/lib/compressedrefs/libjvm.so
    MOD    269  0.02     /usr/lib64/libm-2.17.so
    MOD    257  0.01     /usr/lib64/libcrypto.so.1.0.2k
    MOD    228  0.01     [br_netfilter]
    MOD    221  0.01     [nf_conntrack_netlink]
    MOD    162  0.01     /home/harryayu2/sdks/java11/lib/libjava.so
    MOD    129  0.01     [nfnetlink]
    MOD     63  0.00     /opt/pi-75050cffff_retry/Dpiperf/lib/libperfutil.so
    MOD     61  0.00     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9trc29.so
    MOD     25  0.00     /home/harryayu2/sdks/java11/lib/libjncrypto.so
    MOD     21  0.00     /usr/lib64/ld-2.17.so
    MOD      7  0.00     [igb]
    MOD      5  0.00     NoModule
    MOD      4  0.00     /opt/pi-75050cffff_retry/Dpiperf/lib/libjprof.so
    MOD      3  0.00     [xfs]
    MOD      1  0.00     /usr/lib64/libgcc_s-4.8.5-20150702.so.1
    MOD      1  0.00     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9jvmti29.so
    MOD      1  0.00     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9hookable29.so
harryyu1994 commented 4 years ago
mpirvu commented 4 years ago

Could you please detail those 3 dlls?

harryyu1994 commented 4 years ago

JAVA 8

VM DLL

MOD   9999  0.57     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9vm29.so
     SYM   1962  0.11      VM_BytecodeInterpreter::run(J9VMThread*)
     SYM   1940  0.11      Fast_java_lang_J9VMInternals_primitiveClone
     SYM   1244  0.07      Fast_java_lang_J9VMInternals_identityHashCode
     SYM    984  0.06      objectMonitorExit
     SYM    676  0.04      objectMonitorEnterNonBlocking
     SYM    465  0.03      setArrayRegion
     SYM    453  0.03      getIntField
     SYM    330  0.02      getObjectField
     SYM    231  0.01      getArrayRegion
     SYM    181  0.01      Fast_java_lang_System_currentTimeMillis
     SYM    137  0.01      exceptionCheck
     SYM    126  0.01      Fast_java_lang_Class_getComponentType
     SYM    119  0.01      bytecodeLoop
     SYM    116  0.01      Fast_java_lang_reflect_Array_newArrayImpl
     SYM     98  0.01      Fast_java_lang_Class_getModifiersImpl
     SYM     88  0.01      c_cInterpreter
     SYM     65  0.00      Fast_java_lang_Thread_isInterruptedImpl
     SYM     64  0.00      walkFrame
     SYM     61  0.00      walkStackFrames
     SYM     57  0.00      classHashEqualFn
     SYM     52  0.00      <plt>
     SYM     45  0.00      internalEnterVMFromJNI
     SYM     42  0.00      mapLocalSet.isra.0
     SYM     40  0.00      getSimpleNameForROMClass
     SYM     29  0.00      j9jni_createLocalRef
     SYM     25  0.00      hashTableFind
     SYM     21  0.00      copyStringToUTF8Helper
     SYM     18  0.00      bcvCheckClassNameInLoading
     SYM     17  0.00      searchClassForMethodCommon
     SYM     16  0.00      copyStringToUTF8WithMemAlloc
     SYM     16  0.00      cInterpGetStackClassJEP176Iterator
     SYM     15  0.00      classHashFn
     SYM     15  0.00      internalExitVMToJNI
     SYM     15  0.00      j9localmap_LocalBitsForPC
     SYM     14  0.00      instanceOfOrCheckCast
     SYM     13  0.00      verifyQualifiedName
     SYM     13  0.00      allocate_dimension
     SYM     13  0.00      javaLookupMethodImpl
     SYM     12  0.00      helperMultiANewArray
     SYM     10  0.00      acquireExclusiveVMAccess
     SYM      9  0.00      Fast_java_lang_Object_notifyAll
     SYM      9  0.00      hashClassTableAtString
     SYM      8  0.00      getPrimitiveArrayCritical
     SYM      6  0.00      checkVisibility
     SYM      6  0.00      pushArguments
     SYM      6  0.00      internalFindClassString
     SYM      5  0.00      javaCheckAsyncMessages
     SYM      5  0.00      newObject
     SYM      5  0.00      Fast_java_lang_Class_forNameImpl

JIT DLL

 MOD   5669  0.33     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9jit29.so
     SYM    898  0.05      old_fast_jitLookupInterfaceMethod
     SYM    834  0.05      fast_jitInstanceOf
     SYM    481  0.03      sixteencharsTO
     SYM    326  0.02      jitLookupInterfaceMethod
     SYM    246  0.01      fast_jitMonitorExit
     SYM    219  0.01      jitGetExceptionTableFromPC
     SYM    199  0.01      fast_jitCheckCast
     SYM    164  0.01      jitMonitorExit
     SYM    163  0.01      IPicLookupDispatch
     SYM    112  0.01      jitGetMapsFromPC
     SYM    102  0.01      fast_jitMethodMonitorEntry
     SYM     95  0.01      fast_jitMonitorEntry
     SYM     93  0.01      hash_jit_artifact_search
     SYM     93  0.01      jitCheckCast
     SYM     90  0.01      mergeIPicLookupDispatch
     SYM     87  0.01      jitMethodMonitorExit
     SYM     87  0.01      jitWalkStackFrames
     SYM     80  0.00      fast_jitMethodMonitorExit
     SYM     75  0.00      fast_jitWriteBarrierStoreGenerational
     SYM     74  0.00      jitMethodMonitorEntry
     SYM     71  0.00      TR_IPMethodHashTableEntry::add(TR_OpaqueMethodBlock*,-TR_OpaqueMethodBlock*,-unsigned-int)
     SYM     69  0.00      jitMonitorEntry
     SYM     66  0.00      fast_jitTypeCheckArrayStoreWithNullCheck
     SYM     64  0.00      jitWriteBarrierStoreGenerational
     SYM     50  0.00      walkJITFrameSlots.isra.5
     SYM     43  0.00      samplerThreadProc
     SYM     38  0.00      TR_IProfiler::findOrCreateEntry(int,-unsigned-long,-bool)
     SYM     37  0.00      TR_IProfiler::findOrCreateMethodEntry(J9Method*,-J9Method*,-bool,-unsigned-int)
     SYM     31  0.00      returnFromJIT1
     SYM     30  0.00      fast_jitCheckAssignable
     SYM     27  0.00      fast_jitNewObject
     SYM     25  0.00      jitReferenceArrayCopy
     SYM     24  0.00      avl_jit_artifact_searchCompare
     SYM     24  0.00      arrayTranslateTRTO
     SYM     22  0.00      avl_search
     SYM     22  0.00      TR::DefaultCompilationStrategy::processJittedSample(TR_MethodEvent*)
     SYM     21  0.00      TR_IProfiler::parseBuffer(J9VMThread*,-unsigned-char-const*,-unsigned-long,-bool)
     SYM     21  0.00      jitExceptionHandlerSearch
     SYM     20  0.00      returnFromJIT0
     SYM     20  0.00      old_slow_jitAMultiNewArray
     SYM     17  0.00      jitExitInterpreterJ
     SYM     15  0.00      jitWalkFrame
     SYM     14  0.00      getJitTotalFrameSize
     SYM     14  0.00      returnFromJITJ
     SYM     13  0.00      j2iTransition
     SYM     12  0.00      jitMethodSampleInterrupt
     SYM     11  0.00      fast_jitCheckIfFinalizeObject
     SYM     11  0.00      jitAddSpilledRegisters
     SYM      9  0.00      jitNewArray

JCL DLL

   MOD    210  0.01     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libjclse29.so
     SYM    104  0.01      updateNonHeapMemoryPoolSizes.isra.2
     SYM     55  0.00      Java_java_lang_Class_getEnclosingObjectClass
     SYM     23  0.00      getEnclosingMethodForROMClass
     SYM     10  0.00      getClassContextIterator
     SYM      7  0.00      latestUserDefinedLoaderIterator
     SYM      3  0.00      JVM_LatestUserDefinedLoader_Impl
     SYM      2  0.00      JVM_GetClassContext_Impl
     SYM      2  0.00      Java_sun_misc_Unsafe_setMemory__Ljava_lang_Object_2JJB
     SYM      1  0.00      gcStartEvent
     SYM      1  0.00      Java_com_ibm_lang_management_internal_SysinfoCpuTime_getCpuUtilizationImpl
     SYM      1  0.00      Java_java_lang_Class_getMethodImpl
     SYM      1  0.00      Java_sun_misc_Unsafe_allocateDBBMemory

JAVA 11

VM DLL

MOD  12134  0.71     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9vm29.so
     SYM   1927  0.11      Fast_java_lang_J9VMInternals_primitiveClone
     SYM   1876  0.11      VM_BytecodeInterpreter::run(J9VMThread*)
     SYM   1248  0.07      Fast_java_lang_J9VMInternals_identityHashCode
     SYM    915  0.05      objectMonitorExit
     SYM    766  0.04      objectMonitorEnterNonBlocking
     SYM    733  0.04      walkStackFrames
     SYM    501  0.03      getIntField
     SYM    469  0.03      getObjectField
     SYM    399  0.02      setArrayRegion
     SYM    373  0.02      walkFrame
     SYM    342  0.02      instanceOfOrCheckCast
     SYM    280  0.02      internalEnterVMFromJNI
     SYM    268  0.02      Fast_java_lang_System_currentTimeMillis
     SYM    239  0.01      j9jni_createLocalRef
     SYM    183  0.01      getArrayRegion
     SYM    170  0.01      exceptionCheck
     SYM    159  0.01      internalExitVMToJNI
     SYM    153  0.01      Fast_java_lang_reflect_Array_newArrayImpl
     SYM    150  0.01      Fast_java_lang_Class_getComponentType
     SYM    141  0.01      bytecodeLoop
     SYM     96  0.01      Fast_java_lang_Class_getModifiersImpl
     SYM     83  0.00      <plt>
     SYM     69  0.00      classHashEqualFn
     SYM     67  0.00      c_cInterpreter
     SYM     60  0.00      getSimpleNameForROMClass
     SYM     50  0.00      mapLocalSet.isra.0
     SYM     26  0.00      copyStringToUTF8Helper
     SYM     25  0.00      searchClassForMethodCommon
     SYM     23  0.00      bcvCheckClassNameInLoading
     SYM     23  0.00      cInterpGetStackClassJEP176Iterator
     SYM     19  0.00      hashTableFind
     SYM     17  0.00      javaLookupMethodImpl
     SYM     16  0.00      getPrimitiveArrayCritical
     SYM     14  0.00      verifyQualifiedName
     SYM     14  0.00      allocate_dimension
     SYM     14  0.00      copyStringToUTF8WithMemAlloc
     SYM     13  0.00      helperMultiANewArray
     SYM     13  0.00      Fast_java_lang_Thread_isInterruptedImpl
     SYM     13  0.00      j9localmap_LocalBitsForPC
     SYM     12  0.00      Fast_java_lang_Class_forNameImpl
     SYM     10  0.00      javaCheckAsyncMessages
     SYM     10  0.00      hashClassTableAtString
     SYM     10  0.00      Fast_java_lang_Object_notifyAll
     SYM      7  0.00      monitorTableAt
     SYM      7  0.00      runCallInMethod

JIT DLL

MOD   8744  0.51     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9jit29.so
     SYM   1403  0.08      jitGetMapsFromPC
     SYM    902  0.05      jitGetExceptionTableFromPC
     SYM    854  0.05      old_fast_jitLookupInterfaceMethod
     SYM    829  0.05      fast_jitInstanceOf
     SYM    793  0.05      jitWalkStackFrames
     SYM    461  0.03      sixteencharsTO
     SYM    334  0.02      jitLookupInterfaceMethod
     SYM    245  0.01      fast_jitMonitorExit
     SYM    195  0.01      fast_jitCheckCast
     SYM    157  0.01      fast_jitMethodMonitorEntry
     SYM    148  0.01      getJitTotalFrameSize
     SYM    138  0.01      getFirstInlinedCallSiteWithByteCodeInfo
     SYM    136  0.01      IPicLookupDispatch
     SYM    135  0.01      fast_jitMethodMonitorExit
     SYM    134  0.01      hash_jit_artifact_search
     SYM    127  0.01      jitMethodMonitorExit
     SYM    118  0.01      jitMonitorExit
     SYM     97  0.01      jitCheckCast
     SYM     96  0.01      jitMethodMonitorEntry
     SYM     86  0.01      fast_jitWriteBarrierStoreGenerational
     SYM     73  0.00      jitMonitorEntry
     SYM     66  0.00      TR_IPMethodHashTableEntry::add(TR_OpaqueMethodBlock*,-TR_OpaqueMethodBlock*,-unsigned-int)
     SYM     63  0.00      mergeIPicLookupDispatch
     SYM     57  0.00      fast_jitMonitorEntry
     SYM     47  0.00      jitWriteBarrierStoreGenerational
     SYM     44  0.00      samplerThreadProc
     SYM     43  0.00      fast_jitTypeCheckArrayStoreWithNullCheck
     SYM     42  0.00      TR_IProfiler::findOrCreateEntry(int,-unsigned-long,-bool)
     SYM     41  0.00      returnFromJIT1
     SYM     40  0.00      getFirstInlinedCallSite
     SYM     40  0.00      TR_IProfiler::findOrCreateMethodEntry(J9Method*,-J9Method*,-bool,-unsigned-int)
     SYM     38  0.00      walkJITFrameSlots.isra.5
     SYM     37  0.00      avl_jit_artifact_searchCompare
     SYM     35  0.00      fast_jitNewObject
     SYM     32  0.00      avl_search
     SYM     29  0.00      TR::DefaultCompilationStrategy::processJittedSample(TR_MethodEvent*)
     SYM     28  0.00      fast_jitCheckAssignable
     SYM     26  0.00      jitWalkFrame
     SYM     25  0.00      arrayTranslateTRTO
     SYM     24  0.00      jitReferenceArrayCopy
     SYM     22  0.00      TR_IProfiler::parseBuffer(J9VMThread*,-unsigned-char-const*,-unsigned-long,-bool)
     SYM     20  0.00      getJitInlinedCallInfo
     SYM     20  0.00      jitExitInterpreterJ
     SYM     18  0.00      returnFromJITJ
     SYM     15  0.00      old_slow_jitAMultiNewArray

jclse29 DLL

    MOD   2413  0.14     /home/harryayu2/sdks/java11/lib/compressedrefs/libjclse29.so
     SYM   1046  0.06      getCallerClassJEP176Iterator
     SYM    571  0.03      JVM_GetCallerClass_Impl
     SYM    505  0.03      Java_sun_misc_Unsafe_copyMemory__Ljava_lang_Object_2JLjava_lang_Object_2JJ
     SYM    138  0.01      updateNonHeapMemoryPoolSizes.isra.2
     SYM     74  0.00      Java_java_lang_Class_getEnclosingObjectClass
     SYM     21  0.00      getEnclosingMethodForROMClass
     SYM     17  0.00      <plt>
     SYM     16  0.00      JVM_GetClassAccessFlags_Impl
     SYM     12  0.00      getClassContextIterator
     SYM      4  0.00      latestUserDefinedLoaderIterator
     SYM      3  0.00      Java_java_lang_Class_getMethodImpl
     SYM      2  0.00      Java_sun_misc_Unsafe_setMemory__Ljava_lang_Object_2JJB
     SYM      1  0.00      Java_sun_misc_Unsafe_park
     SYM      1  0.00      managementLocalGCStart
     SYM      1  0.00      JVM_LatestUserDefinedLoader_Impl
     SYM      1  0.00      Java_sun_misc_Unsafe_allocateDBBMemory
harryyu1994 commented 4 years ago

Summary of VM, JIT and JCL DLL Differences

jit

jitGetMapsFromPC
jitGetExceptionTableFromPC
jitWalkStackFrames

jcl

getCallerClassJEP176Iterator
JVM_GetCallerClass_Impl
Java_sun_misc_Unsafe_copyMemory__Ljava_lang_Object_2JLjava_lang_Object_2JJ
fjeremic commented 4 years ago

Looks like we are doing more stack walking on Java 11 for some reason. It could be due to increased GCs but could also result from things like exceptions being thrown.

harryyu1994 commented 4 years ago

Latest Build

Results for JDK=/home/harryayu2/sdks/java8 jvmOpts=-Xmx1G -Xnoaot -Xshareclasses:none -Xjit:initialOptLevel=cold,inhibitRecompilation Throughput avg=2077.04 min=2021.00 max=2104.30 stdDev=35.2 maxVar=4.12% confInt=1.61% samples= 5 Intermediate results: Run 0 198.5 1987.4 2085.0 2104.3 Avg=2104 CPU=21546 ms Footprint=535184 KB Run 1 132.1 1996.6 2078.8 2102.3 Avg=2102 CPU=21593 ms Footprint=505600 KB Run 2 188.8 1994.8 2093.6 2064.4 Avg=2064 CPU=21546 ms Footprint=517052 KB Run 3 198.7 2007.3 2089.6 2093.2 Avg=2093 CPU=21613 ms Footprint=523504 KB Run 4 187.0 1950.9 2046.9 2021.0 Avg=2021 CPU=22065 ms Footprint=512092 KB CompTime avg=21672.60 min=21546.00 max=22065.00 stdDev=221.3 maxVar=2.41% confInt=0.97% samples= 5 Footprint avg=518686.40 min=505600.00 max=535184.00 stdDev=11322.4 maxVar=5.85% confInt=2.08% samples= 5

Results for JDK=/home/harryayu2/sdks/java11 jvmOpts=-Xmx1G -Xnoaot -Xshareclasses:none -Xjit:initialOptLevel=cold,inhibitRecompilation Throughput avg=2002.30 min=1982.50 max=2022.10 stdDev=28.0 maxVar=2.00% confInt=6.24% samples= 2 Intermediate results: Run 0 178.6 1900.8 2016.3 1982.5 Avg=1982 CPU=22021 ms Footprint=515560 KB Run 1 175.1 1883.2 2008.2 2022.1 Avg=2022 CPU=22589 ms Footprint=521840 KB CompTime avg=22305.00 min=22021.00 max=22589.00 stdDev=401.6 maxVar=2.58% confInt=8.04% samples= 2 Footprint avg=518700.00 min=515560.00 max=521840.00 stdDev=4440.6 maxVar=1.22% confInt=3.82% samples= 2

Results for JDK=/home/harryayu2/sdks/java11 jvmOpts=-Xmx1G -Xnoaot -Xshareclasses:none -Xjit:initialOptLevel=cold,inhibitRecompilation Throughput avg=1999.25 min=1985.60 max=2012.90 stdDev=19.3 maxVar=1.37% confInt=4.31% samples= 2 Intermediate results: Run 0 182.7 1901.4 1954.7 2012.9 Avg=2013 CPU=22176 ms Footprint=526152 KB Run 1 192.8 1914.4 2008.2 1985.6 Avg=1986 CPU=22266 ms Footprint=521652 KB CompTime avg=22221.00 min=22176.00 max=22266.00 stdDev=63.6 maxVar=0.41% confInt=1.28% samples= 2 Footprint avg=523902.00 min=521652.00 max=526152.00 stdDev=3182.0 maxVar=0.86% confInt=2.71% samples= 2

Results for JDK=/home/harryayu2/sdks/java11 jvmOpts=-Xmx1G -Xnoaot -Xshareclasses:none -Xjit:initialOptLevel=cold,inhibitRecompilation Throughput avg=1988.32 min=1965.20 max=2017.00 stdDev=23.3 maxVar=2.64% confInt=1.12% samples= 5 Intermediate results: Run 0 191.6 1881.5 1989.3 1969.4 Avg=1969 CPU=22192 ms Footprint=517284 KB Run 1 186.9 1872.5 1994.3 2008.6 Avg=2009 CPU=22261 ms Footprint=520500 KB Run 2 174.0 1879.3 1971.4 1981.4 Avg=1981 CPU=21970 ms Footprint=527312 KB Run 3 152.9 1893.6 1981.6 1965.2 Avg=1965 CPU=22197 ms Footprint=528852 KB Run 4 179.9 1911.9 1994.1 2017.0 Avg=2017 CPU=22231 ms Footprint=539948 KB CompTime avg=22170.20 min=21970.00 max=22261.00 stdDev=115.3 maxVar=1.32% confInt=0.50% samples= 5 Footprint avg=526779.20 min=517284.00 max=539948.00 stdDev=8769.0 maxVar=4.38% confInt=1.59% samples= 5


- 4% gap
harryyu1994 commented 4 years ago

TProf for Latest Build

Java 8

Level=1 numComp=14548
Run 1 Throughput=2044.3 WS=518380 CPU=22280 Errors=0
Results for JDK=/home/harryayu2/sdks/java8 jvmOpts=-Xmx1G -Xnoaot -Xshareclasses:none -Xjit:initialOptLevel=cold,inhibitRecompilation -agentlib:jprof=tprof,logpath=/home/harryayu2/scripts
Throughput  avg=2044.30 min=2044.30 max=2044.30 stdDev=0.0  maxVar=0.00%    confInt=0.00%   samples= 1
Intermediate results:
Run 0   160.1   1955.7  2033.1  2044.3  Avg=2044    CPU=22280 ms  Footprint=518380 KB
CompTime    avg=22280.00    min=22280.00    max=22280.00    stdDev=0.0  maxVar=0.00%    confInt=0.00%   samples= 1
Footprint   avg=518380.00   min=518380.00   max=518380.00   stdDev=0.0  maxVar=0.00%    confInt=0.00%   samples= 1

    )) Process
   ================================

   LAB    TKS   %%%     NAMES

   PID 857775 49.27    SystemProcess_0000
   PID 670887 38.54    java_170023
   PID 162686  9.35    db2sysc_16ff83
   PID  42259  2.43    java_170998
   PID   4006  0.23    swtrace_170974

PID 670887 38.54    java_170023
    MOD 393180 22.59     JITCODE
    MOD 197202 11.33     vmlinux
    MOD  18422  1.06     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9gc29.so
    MOD  10911  0.63     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9vm29.so
    MOD  10684  0.61     [ip_tables]
    MOD   8206  0.47     [nf_conntrack]
    MOD   6852  0.39     /usr/lib64/libpthread-2.17.so
    MOD   5880  0.34     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9jit29.so
    MOD   4600  0.26     /usr/lib64/libc-2.17.so
    MOD   2160  0.12     /home/harryayu2/sdks/java8/jre/lib/amd64/libnet.so

 MOD  18422  1.06     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9gc29.so
     SYM   6992  0.40      MM_Scavenger::incrementalScanCacheBySlot(MM_EnvironmentStandard*,-MM_CopyScanCacheStandard*)
     SYM   2022  0.12      GC_ObjectHeapIteratorAddressOrderedList::nextObjectNoAdvance()
     SYM   1988  0.11      GC_ObjectModelDelegate::calculateObjectDetailsForCopy(MM_EnvironmentBase*,-MM_ForwardedHeader*,-unsigned-long*,-unsigned-long*,-unsigned-long*)
     SYM   1304  0.07      MM_ScavengerDelegate::getObjectScanner(MM_EnvironmentStandard*,-J9Object*,-void*,-unsigned-long)
     SYM    827  0.05      MM_ForwardedHeader::setForwardedObjectInternal(J9Object*,-unsigned-long)
     SYM    470  0.03      GC_ObjectHeapIteratorAddressOrderedList::shouldReturnCurrentObject()
     SYM    305  0.02      MM_Scavenger::scavengeRememberedSetList(MM_EnvironmentStandard*)
     SYM    268  0.02      MM_Scavenger::getArraySplitAmount(MM_EnvironmentStandard*,-unsigned-long)
     SYM    232  0.01      MM_ForwardedHeader::getForwardedObject()
     SYM    179  0.01      MM_ConcurrentGC::localMark(MM_EnvironmentBase*,-unsigned-long)
     SYM    158  0.01      GC_ArrayletObjectModelBase::getSpineSizeWithoutHeader(GC_ArrayletObjectModelBase::ArrayLayout,-unsigned-long,-unsigned-long,-bool)
     SYM    142  0.01      MM_ScavengerStats::getFlipHistory(unsigned-long)
     SYM    132  0.01      MM_Scavenger::splitIndexableObjectScanner(MM_EnvironmentStandard*,-GC_ObjectScanner*,-unsigned-long,-J9Object**)
     SYM    120  0.01      OMR_GC_AllocateObject(OMR_VMThread*,-MM_AllocateInitialization*)
     SYM     92  0.01      MM_Scavenger::getNextScanCache(MM_EnvironmentStandard*)

MOD  10911  0.63     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9vm29.so
     SYM   1925  0.11      Fast_java_lang_J9VMInternals_primitiveClone
     SYM   1827  0.10      VM_BytecodeInterpreterCompressed::run(J9VMThread*)
     SYM   1198  0.07      objectMonitorExit
     SYM   1191  0.07      Fast_java_lang_J9VMInternals_identityHashCode
     SYM   1022  0.06      objectMonitorEnterNonBlocking
     SYM    660  0.04      getIntField
     SYM    520  0.03      getObjectField
     SYM    484  0.03      setArrayRegion
     SYM    322  0.02      Fast_java_lang_System_currentTimeMillis
     SYM    195  0.01      getArrayRegion
     SYM    154  0.01      exceptionCheck
     SYM    124  0.01      bytecodeLoopCompressed
     SYM    118  0.01      Fast_java_lang_Class_getModifiersImpl
     SYM    110  0.01      Fast_java_lang_reflect_Array_newArrayImpl
     SYM    110  0.01      c_cInterpreter

 MOD   5880  0.34     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libj9jit29.so
     SYM    867  0.05      fast_jitInstanceOf
     SYM    761  0.04      old_fast_jitLookupInterfaceMethod
     SYM    462  0.03      sixteencharsTO
     SYM    365  0.02      IPicLookupDispatch
     SYM    280  0.02      jitLookupInterfaceMethod
     SYM    245  0.01      fast_jitMonitorExit
     SYM    233  0.01      jitGetExceptionTableFromPC
     SYM    209  0.01      fast_jitCheckCast
     SYM    189  0.01      jitMonitorExit
     SYM    136  0.01      fast_jitMonitorEntry
     SYM    134  0.01      jitGetMapsFromPC
     SYM    121  0.01      fast_jitMethodMonitorEntry
     SYM    107  0.01      jitMethodMonitorExit
     SYM    107  0.01      fast_jitMethodMonitorExit
     SYM     97  0.01      hash_jit_artifact_search
     SYM     96  0.01      jitCheckCast
     SYM     91  0.01      jitWalkStackFrames
     SYM     90  0.01      jitMethodMonitorEntry
     SYM     84  0.00      mergeIPicLookupDispatch

 MOD    220  0.01     /home/harryayu2/sdks/java8/jre/lib/amd64/compressedrefs/libjclse29.so
     SYM    105  0.01      updateNonHeapMemoryPoolSizes.isra.2
     SYM     70  0.00      Java_java_lang_Class_getEnclosingObjectClass
     SYM     22  0.00      getEnclosingMethodForROMClass
     SYM     14  0.00      getClassContextIterator
     SYM      5  0.00      latestUserDefinedLoaderIterator
     SYM      2  0.00      unsafeAllocateDBBMemory
     SYM      1  0.00      Java_java_security_AccessController_getAccSnapshot
     SYM      1  0.00      Java_java_lang_Class_getMethodImpl

Java 11

Run 1 Throughput=1953.4 WS=551508 CPU=22273 Errors=0
Results for JDK=/home/harryayu2/sdks/java11 jvmOpts=-Xmx1G -Xnoaot -Xshareclasses:none -Xjit:initialOptLevel=cold,inhibitRecompilation -agentlib:jprof=tprof,logpath=/home/harryayu2/scripts
Throughput  avg=1953.40 min=1953.40 max=1953.40 stdDev=0.0  maxVar=0.00%    confInt=0.00%   samples= 1
Intermediate results:
Run 0   170.2   1855.0  1941.1  1953.4  Avg=1953    CPU=22273 ms  Footprint=551508 KB
CompTime    avg=22273.00    min=22273.00    max=22273.00    stdDev=0.0  maxVar=0.00%    confInt=0.00%   samples= 1
Footprint   avg=551508.00   min=551508.00   max=551508.00   stdDev=0.0  maxVar=0.00%    confInt=0.00%   samples= 1

 )) Process
   ================================

   LAB    TKS   %%%     NAMES

   PID 845935 49.42    SystemProcess_0000
   PID 670665 39.18    java_16d3f3
   PID 149936  8.76    db2sysc_16d34f
   PID  38462  2.25    java_16dd79
   PID   3839  0.22    swtrace_16dd55

PID 670665 39.18    java_16d3f3
    MOD 398511 23.28     JITCODE
    MOD 186268 10.88     vmlinux
    MOD  16804  0.98     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9gc29.so
    MOD  12584  0.74     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9vm29.so
    MOD  10414  0.61     [ip_tables]
    MOD   8809  0.51     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9jit29.so
    MOD   8367  0.49     [nf_conntrack]
    MOD   6839  0.40     /usr/lib64/libpthread-2.17.so
    MOD   4645  0.27     /usr/lib64/libc-2.17.so
    MOD   2499  0.15     /home/harryayu2/sdks/java11/lib/compressedrefs/libjclse29.so
    MOD   1989  0.12     /home/harryayu2/sdks/java11/lib/libnet.so

MOD  16804  0.98     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9gc29.so
     SYM   6153  0.36      MM_Scavenger::incrementalScanCacheBySlot(MM_EnvironmentStandard*,-MM_CopyScanCacheStandard*)
     SYM   1722  0.10      GC_ObjectHeapIteratorAddressOrderedList::nextObjectNoAdvance()
     SYM   1673  0.10      GC_ObjectModelDelegate::calculateObjectDetailsForCopy(MM_EnvironmentBase*,-MM_ForwardedHeader*,-unsigned-long*,-unsigned-long*,-unsigned-long*)
     SYM   1156  0.07      MM_ScavengerDelegate::getObjectScanner(MM_EnvironmentStandard*,-J9Object*,-void*,-unsigned-long)
     SYM    733  0.04      MM_ForwardedHeader::setForwardedObjectInternal(J9Object*,-unsigned-long)
     SYM    433  0.03      GC_ObjectHeapIteratorAddressOrderedList::shouldReturnCurrentObject()
     SYM    326  0.02      MM_ConcurrentGC::localMark(MM_EnvironmentBase*,-unsigned-long)
     SYM    268  0.02      MM_Scavenger::scavengeRememberedSetList(MM_EnvironmentStandard*)
     SYM    249  0.01      MM_Scavenger::getArraySplitAmount(MM_EnvironmentStandard*,-unsigned-long)
     SYM    225  0.01      MM_ForwardedHeader::getForwardedObject()
     SYM    157  0.01      GC_ArrayletObjectModelBase::getSpineSizeWithoutHeader(GC_ArrayletObjectModelBase::ArrayLayout,-unsigned-long,-unsigned-long,-bool)
     SYM    122  0.01      MM_ScavengerStats::getFlipHistory(unsigned-long)

MOD  12584  0.74     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9vm29.so
     SYM   1866  0.11      Fast_java_lang_J9VMInternals_primitiveClone
     SYM   1803  0.11      VM_BytecodeInterpreterCompressed::run(J9VMThread*)
     SYM   1390  0.08      Fast_java_lang_J9VMInternals_identityHashCode
     SYM   1108  0.06      objectMonitorExit
     SYM    956  0.06      objectMonitorEnterNonBlocking
     SYM    707  0.04      walkStackFrames
     SYM    513  0.03      getIntField
     SYM    464  0.03      instanceOfOrCheckCast
     SYM    461  0.03      setArrayRegion
     SYM    457  0.03      getObjectField
     SYM    330  0.02      internalEnterVMFromJNI
     SYM    310  0.02      walkFrame
     SYM    304  0.02      Fast_java_lang_System_currentTimeMillis
     SYM    205  0.01      getArrayRegion
     SYM    198  0.01      j9jni_createLocalRef
     SYM    166  0.01      internalExitVMToJNI
     SYM    152  0.01      exceptionCheck
     SYM    140  0.01      Fast_java_lang_reflect_Array_newArrayImpl
     SYM    126  0.01      Fast_java_lang_Class_getComponentType
     SYM    122  0.01      bytecodeLoopCompressed
     SYM    122  0.01      Fast_java_lang_Class_getModifiersImpl

MOD   8809  0.51     /home/harryayu2/sdks/java11/lib/compressedrefs/libj9jit29.so
     SYM   1346  0.08      jitGetMapsFromPC
     SYM    904  0.05      fast_jitInstanceOf
     SYM    868  0.05      jitGetExceptionTableFromPC
     SYM    745  0.04      old_fast_jitLookupInterfaceMethod
     SYM    738  0.04      jitWalkStackFrames
     SYM    508  0.03      sixteencharsTO
     SYM    288  0.02      jitLookupInterfaceMethod
     SYM    269  0.02      fast_jitMonitorExit
     SYM    250  0.01      IPicLookupDispatch
     SYM    232  0.01      fast_jitCheckCast
     SYM    201  0.01      getFirstInlinedCallSiteWithByteCodeInfo
     SYM    169  0.01      jitMethodMonitorExit
     SYM    157  0.01      jitMonitorExit
     SYM    152  0.01      getJitTotalFrameSize
     SYM    148  0.01      jitMethodMonitorEntry
     SYM    137  0.01      fast_jitMethodMonitorExit
     SYM    120  0.01      fast_jitMethodMonitorEntry
     SYM    108  0.01      hash_jit_artifact_search

MOD   2499  0.15     /home/harryayu2/sdks/java11/lib/compressedrefs/libjclse29.so
     SYM   1187  0.07      getCallerClassJEP176Iterator
     SYM    590  0.03      JVM_GetCallerClass_Impl
     SYM    506  0.03      Java_sun_misc_Unsafe_copyMemory__Ljava_lang_Object_2JLjava_lang_Object_2JJ
     SYM     84  0.00      updateNonHeapMemoryPoolSizes.isra.2
     SYM     57  0.00      Java_java_lang_Class_getEnclosingObjectClass
     SYM     30  0.00      <plt>
     SYM     22  0.00      getEnclosingMethodForROMClass
     SYM     11  0.00      getClassContextIterator
     SYM      3  0.00      Java_java_lang_Class_getMethodImpl
     SYM      3  0.00      latestUserDefinedLoaderIterator
     SYM      2  0.00      unsafeAllocateDBBMemory
     SYM      1  0.00      JVM_LatestUserDefinedLoader_Impl
     SYM      1  0.00      JVM_GetClassContext_Impl
     SYM      1  0.00      Java_sun_misc_Unsafe_setMemory__Ljava_lang_Object_2JJB
     SYM      1  0.00      Java_sun_misc_Unsafe_allocateDBBMemory
DanHeidinga commented 4 years ago 
MOD   2499  0.15     /home/harryayu2/sdks/java11/lib/compressedrefs/libjclse29.so
     SYM   1187  0.07      getCallerClassJEP176Iterator
     SYM    590  0.03      JVM_GetCallerClass_Impl

This is interesting as we have special handling for sun.reflect.Reflection.getCallerClass() in the JIT. In JDK 9+, this moved to jdk.internal.reflect.Reflection.getCallerClass().

I did a very quick scan of the code and don't see a mapping to have the JIT treat jdk.internal.reflect the same as sun.reflect.

fjeremic commented 4 years ago

I did a very quick scan of the code and don't see a mapping to have the JIT treat jdk.internal.reflect the same as sun.reflect.

It is aliased: https://github.com/eclipse/openj9/blob/0050bf34de88eac5bbf1cb9643c41f5e983bc42e/runtime/compiler/env/j9method.cpp#L4303 https://github.com/eclipse/openj9/blob/0050bf34de88eac5bbf1cb9643c41f5e983bc42e/runtime/compiler/env/j9method.cpp#L4395

I'm not sure why we are not inlining the calls in Java 11. It may be worth collecting a callgraph and figuring out which method those ticks are coming from and getting a trace log of it. It seems we are calling out to the natives in Java 11 and not in Java 8.

mpirvu commented 4 years ago

I'm not sure why we are not inlining the calls in Java 11

It should be noted that the experiments used cold compilations that have a low inlining budget which could easily be overrun.

andrewcraik commented 4 years ago

The time in the stack walker which could be exceptions is something @BeverlyXu and I are looking at. Will update once we get to the bottom of it.