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)

Language support for "Conditional Method Call"

While going through the Hadoop HDFS code, I saw three lines of code repeated everywhere when a debug statement must printed (see below).

    if (DFSClient.LOG.isDebugEnabled()) {
        DFSClient.LOG.debug("...");
    }


Well everything is correct in this code. But when you start to see this first line repeating everywhere in the code it gets really annoying. There is a workaround but it has some cost. Let's see it.

Workaround 1.
Create a Logger class which has log level set. And checks whether it should emit the log to output stream.

    class Logger {
        public static final int DEBUG = 0;
        public static final int LOW = 1;
        public static final int MEDIUM = 2;
        public static final int HIGH = 3;

        private int level;
        private PrintStream strm;

        public Logger(PrintStream strm, int level) {
            this.level = level;
            this.strm = strm;
        }

         public void debug(String s) {
            if(level <= DEBUG)
                strm.println(s);
            }
        }
        ...
    }

To use this.
    Logger LOG = new Logger(strm, Logger.DEBUG);
    LOG.debug("Hello world!");


But this is going to affect the performance as the evaluation of the arguments happen before the level value is checked. If someone does a computation for printing then it would be wasted if log level is not set. Instead I propose a language support for this condition check before making a function call and evaluation of the arguments.

For language such as Java I propose a keyword preval which can used to mark the argument (must be boolean). Only this argument must be evaluated before doing the further argument processing. So the debug code may look something like.

    public void debug(String s, preval boolean shouldPrint) {
        strm.println(s);
    }

And should be used as
    DFSClient.LOG.debug("...", DFSClient.LOG.isDebugEnabled());

Well this is also annoying as you have to pass this boolean argument everytime you make call to debug. There is further room for improvement for languages which support methods with default arguments (with evaluation). Then the debug method could be written as

    public void debug(String s, 
        preval boolean shouldPrint=(this.level<=DEBUG)) {
        strm.println(s);
    }

To use this method we can either pass the argument explicitly or write
    DFSClient.LOG.debug("...");

This makes the code really crisp and cute (without those annoying if checks everywhere). If any Java language developer ever see this blogpost please try to implement this. (I couldn't find any place to suggest modifications to Java language)