拦截 monitorEnter - 生成的字节码无法 JIT 编译答案

【问题标题】：Intercepting monitorEnter - Resulting byte code cannot be JIT compiled拦截 monitorEnter - 生成的字节码无法 JIT 编译
【发布时间】：2019-05-15 23:28:20
【问题描述】：

在我的代理中，我正在拦截 monitorEnter 事件。到目前为止，拦截器函数什么都不做，只是立即返回。由于我面临一些重大的性能影响，我试图找出问题所在。

我目前的理解是修改后的字节码可以工作，但 JIT 在编译它时有问题。我还不确定为什么以及解决此问题的最佳方法是什么。

拦截所有monitorEnter 的天真方法是DUP 监视器，执行monitorenter，然后是INVOKESTATIC 到我的拦截器传递监视器对象。这样做有时会导致IllegalMonitorStateException。（还不知道为什么）。然后我将代码序列更改为monitorEnter、ALOAD、INVOKESTATIC 到我的拦截器。虽然我没有再次遇到异常，但生成的代码无法 JIT 编译（实际上 DUP 版本也不能）。

这里是导致问题的方法的示例字节代码（类com.mysql.jdbc.ResultSetImpl）。我添加的唯一代码是 12 和 13 处的说明：

  protected final void checkColumnBounds(int) throws java.sql.SQLException;
    descriptor: (I)V
    flags: ACC_PROTECTED, ACC_FINAL
    Code:
      stack=5, locals=4, args_size=2
         0: aload_0
         1: invokevirtual #319                // Method checkClosed:()Lcom/mysql/jdbc/MySQLConnection;
         4: invokeinterface #323,  1          // InterfaceMethod com/mysql/jdbc/MySQLConnection.getConnectionMutex:()Ljava/lang/Object;
         9: dup
        10: astore_2
        11: monitorenter
        12: aload_2
        13: invokestatic  #329                // Method com/test/bootstrap/Interceptor.monitorEntered:(Ljava/lang/Object;)V
        16: iload_1
        17: iconst_1
        18: if_icmpge     60
        21: ldc_w         #516                // String ResultSet.Column_Index_out_of_range_low
        24: iconst_2
        25: anewarray     #121                // class java/lang/Object
        28: dup
        29: iconst_0
        30: iload_1
        31: invokestatic  #470                // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
        34: aastore
        35: dup
        36: iconst_1
        37: aload_0
        38: getfield      #236                // Field fields:[Lcom/mysql/jdbc/Field;
        41: arraylength
        42: invokestatic  #470                // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
        45: aastore
        46: invokestatic  #519                // Method com/mysql/jdbc/Messages.getString:(Ljava/lang/String;[Ljava/lang/Object;)Ljava/lang/String;
        49: ldc_w         #521                // String S1009
        52: aload_0
        53: invokevirtual #506                // Method getExceptionInterceptor:()Lcom/mysql/jdbc/ExceptionInterceptor;
        56: invokestatic  #512                // Method com/mysql/jdbc/SQLError.createSQLException:(Ljava/lang/String;Ljava/lang/String;Lcom/mysql/jdbc/ExceptionInterceptor;)Ljava/sql/SQLException;
        59: athrow
        60: iload_1
        61: aload_0
        62: getfield      #236                // Field fields:[Lcom/mysql/jdbc/Field;
        65: arraylength
        66: if_icmple     108
        69: ldc_w         #523                // String ResultSet.Column_Index_out_of_range_high
        72: iconst_2
        73: anewarray     #121                // class java/lang/Object
        76: dup
        77: iconst_0
        78: iload_1
        79: invokestatic  #470                // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
        82: aastore
        83: dup
        84: iconst_1
        85: aload_0
        86: getfield      #236                // Field fields:[Lcom/mysql/jdbc/Field;
        89: arraylength
        90: invokestatic  #470                // Method java/lang/Integer.valueOf:(I)Ljava/lang/Integer;
        93: aastore
        94: invokestatic  #519                // Method com/mysql/jdbc/Messages.getString:(Ljava/lang/String;[Ljava/lang/Object;)Ljava/lang/String;
        97: ldc_w         #521                // String S1009
       100: aload_0
       101: invokevirtual #506                // Method getExceptionInterceptor:()Lcom/mysql/jdbc/ExceptionInterceptor;
       104: invokestatic  #512                // Method com/mysql/jdbc/SQLError.createSQLException:(Ljava/lang/String;Ljava/lang/String;Lcom/mysql/jdbc/ExceptionInterceptor;)Ljava/sql/SQLException;
       107: athrow
       108: aload_0
       109: getfield      #196                // Field profileSql:Z
       112: ifne          122
       115: aload_0
       116: getfield      #214                // Field useUsageAdvisor:Z
       119: ifeq          131
       122: aload_0
       123: getfield      #164                // Field columnUsed:[Z
       126: iload_1
       127: iconst_1
       128: isub
       129: iconst_1
       130: bastore
       131: aload_2
       132: monitorexit
       133: goto          141
       136: astore_3
       137: aload_2
       138: monitorexit
       139: aload_3
       140: athrow
       141: return
      Exception table:
         from    to  target type
            16   133   136   any
           136   139   136   any
      LocalVariableTable:
        Start  Length  Slot  Name   Signature
            0     142     0  this   Lcom/mysql/jdbc/ResultSetImpl;
            0     142     1 columnIndex   I
      LineNumberTable:
        line 760: 0
        line 761: 16
        line 762: 21
        line 766: 60
        line 767: 69
        line 773: 108
        line 774: 122
        line 776: 131
        line 777: 141
      StackMapTable: number_of_entries = 6
        frame_type = 252 /* append */
          offset_delta = 60
          locals = [ class java/lang/Object ]
        frame_type = 47 /* same */
        frame_type = 13 /* same */
        frame_type = 8 /* same */
        frame_type = 68 /* same_locals_1_stack_item */
          stack = [ class java/lang/Throwable ]
        frame_type = 4 /* same */
    Exceptions:
      throws java.sql.SQLException

方法visitor中使用的asm代码是这样的：

        if (opcode == MONITORENTER)
        {
//          super.visitInsn(DUP); // in the beginning I used DUP followed, now ALOAD
            super.visitInsn(opcode);
            super.visitVarInsn(ALOAD, lastAStoreIndex);
            super.visitMethodInsn(INVOKESTATIC, Type.getInternalName(Interceptor.class), "monitorEntered", "(Ljava/lang/Object;)V", false);
        }

因此，该方法似乎与 JIT 不兼容。 -XX:+PrintCompilation 显示：

  21938  619   !   3       com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)
  21938  619   !   3       com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   COMPILE SKIPPED: invalid parsing (retry at different tier)
               !m             @ 6   com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   not compilable (disabled)
               !m             @ 13   com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   not compilable (disabled)
  22105  716   !   4       com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)
  22105  716   !   4       com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   COMPILE SKIPPED: cannot parse method (not retryable)
               !m             @ 6   com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   not compilable (disabled)
               !m             @ 13   com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   not compilable (disabled)
               !m             @ 62   com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   not compilable (disabled)
               !m             @ 13   com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   not compilable (disabled)
               !m             @ 6   com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   not compilable (disabled)
               !m                   @ 13   com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   not compilable (disabled)
               !m                   @ 13   com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   not compilable (disabled)
               !m             @ 6   com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   not compilable (disabled)
               !m             @ 62   com.mysql.jdbc.ResultSetImpl::checkColumnBounds (142 bytes)   not compilable (disabled)

我知道我添加的指令不会生成 javac，但由于它是有效的字节码（至少我这么认为并且示例有效），我假设 JIT 可以处理它。然而，JIT 似乎正在寻找一些众所周知的模式。我想知道其他基于 JVM 的语言如何处理这个问题。他们是否总是需要生成与javac 将生成的相同/相似的字节码？

我现在想到的唯一理论上的解决方案是尝试提出javac 之类的字节码，这当然比我在这里尝试做的更棘手，因为我需要将监视器对象存储在一个新的局部变量，然后在monitorEnter 之前从那里加载它，并在调用我的拦截器之前再次执行相同的操作。所以我要么需要更改为 asm 树 API（以便再次返回），要么看看我是否可以缓冲指令以便在遇到monitorEnter 时仍然能够做出相应的反应。还有其他可能更容易实施的建议吗？

【问题讨论】：

看起来代码的检测方式确实存在问题，但是如果没有看到实际的字节码就很难说。这些症状表明 JIT 编译可能存在问题。尝试-XX:+PrintCompilation、-XX:+PrintInlining 或更重的-XX:LogCompilation 和-XX:+PrintAssembly。 JITWatch 是分析 HotSpot 编译器结果的好工具。
-XX:+PrintCompilation 确实显示了一些问题。我用更多细节更新了这个问题。
一些未编译的方法得到“不可编译（不平衡的监视器）”。我发现此语句“..具有非结构化锁定的方法未编译并回退到解释器”here。我还不确定为什么我的更改可能会导致这种情况。
“非结构化锁定”意味着代码不保证monitorenter 和monitorexit 总是成对的。如果在持有锁时发生异常，则会有一个异常处理程序调用monitorexit。您注入的代码（对Interceptor.monitorEntered(…) 的调用）在持有锁时被调用，但未被异常处理程序覆盖，因此如果该方法抛出异常，则不会调用monitorexit。
我不确定您是否正确。我 am 指的是您发布的字节码。指令序列可能看起来与javac 生成的代码相同，但异常处理程序的受保护范围是从 16 到 133，而它应该是 12 到 133，以覆盖您注入的代码，或者，正如 JVM 所看到的那样，它应该涵盖从monitorenter 到monitorexit 之后的所有内容。

标签： java performance jvm jit jvm-hotspot

【解决方案1】：

如果您想监控锁争用，您可以使用 Flight Recorder，当涉及超过 10-20 毫秒的争用时，它几乎没有开销。

JDK 11：

java -XX:StartFlightRecording:filename=recording.jfr ...

早期版本还需要 -XX:+UnlockCommercialFeatures 标志，并且只能免费用于开发。

如果您想分析更短的延迟，您可以使用 Java Mission Control（窗口 -> 模板管理器）创建自定义配置文件，即 locks.jfc，或使用以下配置。如果不使用自定义配置，默认阈值为 20 毫秒。

事件的名称 (jdk.JavaMonitorEnter) 在不同版本之间发生了变化，但这是 fpr JDK 11 或更高版本。

<?xml version="1.0" encoding="UTF-8"?>
<configuration version="2.0">
  <event name="jdk.JavaMonitorEnter">
    <setting name="enabled">true</setting>
    <setting name="stackTrace">true</setting>
    <setting name="threshold">20 ms</setting>
  </event>
</configuration>

阈值可以降低，但如果低于 1 毫秒，开销会急剧增加。大多数开销是由于获取堆栈跟踪，这仅在延迟长于阈值时才会发生。

java -XX:StartFlightRecording:filename=recording.jfr,settings=locks.jfc

锁检测发生在 JVM 内部，延迟的持续时间是使用不变的 TSC 测量的，该 TSC 仅花费大约 10-15 ns。

录音可以在JMC中打开 https://openjdk.java.net/projects/jmc/7/

或者可以通过编程方式访问结果：

try(Recording file : new RecordingFile(Path.of("recording.jfr")) {
  while (file.hasMoreEvents()) {
    System.out.println(file.readEvent());
  }
}

【讨论】：

对不起，但这根本没有回答原始问题，看起来更像 JFR 广告。请注意，问题不是关于竞争锁分析，而是关于检测 all monitorenter 指令（包括非竞争）。目的不是查找锁争用问题，而是调查为什么插桩代码比非插桩代码运行得慢。