JVM agents and JIT

So... one day I notice a JVM hanging at the startup in one of our servers. It has not logged anything after it has started. `jstack` showed that the process is executing some `premain` function

Jstack

# jstack 24692

...

"main" #1 prio=5 os_prio=0 tid=0x00007f228000a000 nid=0x6075 runnable [0x00007f2287823000]
   java.lang.Thread.State: RUNNABLE
        at sun.security.provider.SHA2.implCompress(SHA2.java:201)
        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:335)
        at com.sun.crypto.provider.HmacCore.engineUpdate(HmacCore.java:161)
        at javax.crypto.Mac.update(Mac.java:485)
        at com.sun.crypto.provider.PBKDF2KeyImpl.deriveKey(PBKDF2KeyImpl.java:178)
        at com.sun.crypto.provider.PBKDF2KeyImpl.<init>(PBKDF2KeyImpl.java:113)
        at com.sun.crypto.provider.PBKDF2Core.engineGenerateSecret(PBKDF2Core.java:69)
        at javax.crypto.SecretKeyFactory.generateSecret(SecretKeyFactory.java:336)
        at com.mmp.jvmtiperf.MyAgent.decrypt(MyAgent.java:17)
        at com.mmp.jvmtiperf.MyAgent.premain(MyAgent.java:28)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at sun.instrument.InstrumentationImpl.loadClassAndStartAgent(InstrumentationImpl.java:386)
        at sun.instrument.InstrumentationImpl.loadClassAndCallPremain(InstrumentationImpl.java:401)

I also profiled the JVM, and this was the most common stack

--- 10001689 ns (0.04%), 1 sample
  [ 0] sun.misc.Unsafe.getInt
  [ 1] sun.security.provider.ByteArrayAccess.b2iBig64
  [ 2] sun.security.provider.SHA2.implCompress
  [ 3] sun.security.provider.SHA2.implDigest
  [ 4] sun.security.provider.DigestBase.engineDigest
  [ 5] sun.security.provider.DigestBase.engineDigest
  [ 6] java.security.MessageDigest$Delegate.engineDigest
  [ 7] java.security.MessageDigest.digest
  [ 8] com.sun.crypto.provider.HmacCore.engineDoFinal
  [ 9] javax.crypto.Mac.doFinal
  [10] javax.crypto.Mac.doFinal
  [11] com.sun.crypto.provider.PBKDF2KeyImpl.deriveKey
  [12] com.sun.crypto.provider.PBKDF2KeyImpl.<init>
  [13] com.sun.crypto.provider.PBKDF2Core.engineGenerateSecret
  [14] javax.crypto.SecretKeyFactory.generateSecret
  [15] com.mmp.jvmtiperf.MyAgent.decrypt
  [16] com.mmp.jvmtiperf.MyAgent.premain
  [17] sun.reflect.NativeMethodAccessorImpl.invoke0
  [18] sun.reflect.NativeMethodAccessorImpl.invoke
  [19] sun.reflect.DelegatingMethodAccessorImpl.invoke
  [20] java.lang.reflect.Method.invoke
  [21] sun.instrument.InstrumentationImpl.loadClassAndStartAgent
  [22] sun.instrument.InstrumentationImpl.loadClassAndCallPremain

          ns  percent  samples  top
  ----------  -------  -------  ---
 13747492952   52.44%     1374  sun.security.provider.SHA2.lf_S
  1920993571    7.33%      192  sun.security.provider.SHA2.implCompress
  1801015904    6.87%      180  sun.security.provider.SHA2.lf_R
  1190642160    4.54%      119  sun.security.provider.SHA2.lf_maj
  1160569433    4.43%      116  sun.security.provider.SHA2.lf_ch
  1040701461    3.97%      104  Interpreter
  1010585056    3.86%      101  sun.security.provider.SHA2.lf_sigma0
   560312244    2.14%       56  sun.security.provider.SHA2.lf_sigma1
   560302440    2.14%       56  sun.security.provider.SHA2.lf_delta1
   560296929    2.14%       56  sun.security.provider.SHA2.lf_delta0
   300184334    1.15%       30  java.lang.Integer.reverseBytes
   170088977    0.65%       17  java.util.Arrays.fill
   160085552    0.61%       16  sun.security.provider.DigestBase.engineUpdate
   150083336    0.57%       15  sun.security.provider.ByteArrayAccess.b2iBig64

Agents are common in Java world and premain is a function implemented by a java agent. So I checked the agent attached to this JVM. It was a silly little code, which used to compute some secret and set it as a JVM argument. Since I can't share the complete code here, I extracted a MVCE out of it which is given below

$ cat MyAgent.java

package com.mmp.jvmtiperf;

import javax.crypto.spec.*;
import java.lang.instrument.Instrumentation;
import java.security.spec.*;
import java.util.Base64;
import javax.crypto.*;

public class MyAgent {

    public static String decrypt(String strToDecrypt, String secret) {
        try {
            byte[] iv = new byte[16];
            IvParameterSpec ivspec = new IvParameterSpec(iv);
            SecretKeyFactory factory = SecretKeyFactory.getInstance("PBKDF2WithHmacSHA256");
            KeySpec spec = new PBEKeySpec(secret.toCharArray(), "hello@123".getBytes(), 65536, 256);
            SecretKey tmp = factory.generateSecret(spec);
            SecretKeySpec secretKey = new SecretKeySpec(tmp.getEncoded(), "AES");
            Cipher cipher = Cipher.getInstance("AES/CBC/PKCS5PADDING");
            cipher.init(2, secretKey, ivspec);
            return new String(cipher.doFinal(Base64.getDecoder().decode(strToDecrypt)));
        } catch (Exception e) {
            return null;
        }
    }

    public static void premain(String agentArgs, Instrumentation inst) {
        System.setProperty("mySecretProp",

           decrypt("89/LaUAGfN8VMrUew8wuylMyzgcCxC6Af4DVLROEouw=", "supersecret"));
    }
}

To compile and package this, run the below commands

$ javac MyAgent.java

$ mkdir -p com/mmp/jvmtiperf

$ cp MyAgent.class com/mmp/jvmtiperf

$ mkdir META-INF

$ echo "Manifest-Version: 1.0
Implementation-Title:   myagent
Premain-Class: com.mmp.jvmtiperf.MyAgent
Implementation-Version: 1.0.0" > META-INF/MANIFEST.MF

$ jar cvf myagent.jar com/mmp/jvmtiperf

$ zip myagent.jar META-INF/MANIFEST.MF

Now to run this, we need a test program

$ cat test.java
class test {
        public static void main(String a[]) {
                if(a.length > 0 && a[0].equals("-runPremain"))
                        com.mmp.jvmtiperf.MyAgent.premain(a[0], null);
                System.out.println("exitting");
        }
}

Just running this code (using the below command) runs real quick

$ javac test.java

$ time java  -cp . test -runPremain
exitting

real    0m0.629s
user    0m1.282s
sys     0m0.083s

This is confusing, because the app used to spend most of its time here in the agent. Only difference here is the code is executed from the `main`, while in our hung application, it was called from `premain`, so we need to test it in the same way.

$ time java -javaagent:myagent.jar -cp . test
exitting

real    0m32.057s
user    0m32.020s
sys     0m0.054s

Ok, we were able to reproduce the issue, but why the function called from `premain` was slower than the function called from the `main`? Let's profile this fast JVM to understand this

$ java -cp . -agentpath:/root/perf/async-profiler-master/build/libasyncProfiler.so=start,file=foo test -runPremain

$ cat perf

....

          ns  percent  samples  top
  ----------  -------  -------  ---
   140071867   23.33%       14  sun.security.provider.SHA2.implCompress
   110105345   18.34%       11  Method::make_jmethod_id(ClassLoaderData*, Method*)
    20016638    3.33%        2  Rewriter::scan_method(Method*, bool, bool*)
    20009898    3.33%        2  __malloc
    19997059    3.33%        2  sun.security.provider.SHA.implCompress
    10022555    1.67%        1  _raw_spin_unlock_irqrestore_[k]
    10016146    1.67%        1  __do_page_fault_[k]
    10011639    1.67%        1  __GI___pthread_mutex_lock
    10011504    1.67%        1  java_lang_String::equals(oopDesc*, unsigned short*, int)
    10011372    1.67%        1  Interpreter
    10009534    1.67%        1  java.io.ByteArrayInputStream.available
    10009404    1.67%        1  __pthread_getspecific
...

If we compare the profile results, the JVM's Interpreter is executed more times in slow JVM than the faster one

Slower one

  1160569433    4.43%      116  sun.security.provider.SHA2.lf_ch
  1040701461    3.97%      104  Interpreter
  1010585056    3.86%      101  sun.security.provider.SHA2.lf_sigma0

Faster one

    10011504    1.67%        1  java_lang_String::equals(oopDesc*, unsigned short*, int)
    10011372    1.67%        1  Interpreter
    10009534    1.67%        1  java.io.ByteArrayInputStream.available

So, something related to the bytecode interpreter is wrong (104 is the number of times it appered on the stack). So, let's see what is going on inside the JVM. Let's use

Compilation in fast JVM (Refer the images at the end to see all the compiled packages.)

$ java -XX:+UnlockDiagnosticVMOptions -XX:+PrintCompilation  -cp . test -runPremain | grep 'sun.security.provider.SHA2.'

    ...

    192  206       3       sun.security.provider.SHA2::lf_S (11 bytes)

    193  207       3       sun.security.provider.SHA2::lf_R (4 bytes)
    193  209       3       sun.security.provider.SHA2::lf_sigma1 (21 bytes)
    193  210       3       sun.security.provider.SHA2::lf_ch (10 bytes)
    193  211       3       sun.security.provider.SHA2::lf_sigma0 (20 bytes)

    ...

Compilation in fast JVM (Nothing from sun.security was compiled)

$ java -XX:+UnlockDiagnosticVMOptions -XX:+PrintCompilation -javaagent:myagent.jar -cp . test   | grep 'sun.security.provider.SHA2::lf_S'

$

So, it was the JIT compiler who was not compiling the crypto packages and letting them run on the Interpreter. Solution? I still need to find it :P

Images

(Snapshot from JITWatch for fast JVM)

(Snapshot from JITWatch for slow JVM)