Difficulty profiling a Java application: Missing method in profiling results despite disabling optimizations. YourKit trivial method

huangapple go评论70阅读模式
英文:

Difficulty profiling a Java application: Missing method in profiling results despite disabling optimizations. YourKit trivial method

问题

以下是您提供的代码的翻译部分:

"Not so far ago I had been profiling an application and noticed an interesting optimization that applies to the compiled byte code.

Here is my program:

public class InstanceOnly {

    public static void main(final String[] args) throws InterruptedException {
        int sum = 0;
        for (int i = 0; i < Integer.MAX_VALUE; ++i) {
            Book b = new Discounted(new Prime(i));
            sum += b.price();
            Thread.sleep(10);
        }
        System.out.printf("Total: %d\n", sum);
    }

    interface Book {
        int price();
    }

    static class Discounted implements Book {
        private final Book book;

        Discounted(final Book b) {
            this.book = b;
        }

        @Override
        public int price() {
            return this.book.price() / 2;
        }
    }

    static class Prime implements Book {
        private final int usd;

        Prime(final int u) {
            this.usd = u;
        }

        @Override
        public int price() {
            return this.usd * 3;
        }
    }
}

As you might notice it is rather simple - we just use decorator pattern here in order to calculate the total price of all books. The application will run very long time, so I have enough time to profile it. I’m using YourKit java profiling which use bytecode instrumentation in order to get precise number of invocations of the each method. I profile the application during one minute and get the next results:

"verification.instances.InstanceOnly.main(String[]) InstanceOnly.java","1"
"java.lang.Thread.sleep(long) Thread.java (native)", "5307"
"verification.instances.InstanceOnly$Prime.<init>(int) InstanceOnly.java", "5307"
"verification.instances.InstanceOnly$Discounted.price() InstanceOnly.java","5307"
"verification.instances.InstanceOnly$Discounted.<init>(InstanceOnly$Book) InstanceOnly.java","5307"

But where is the verification.instances.InstanceOnly$Prime.price() call? I can see that we only invoke the Prime constructor. I initially suspected that it might be a problem with JIT optimizations, where the method gets inlined. To address this, I disabled all optimizations by using the -Djava.compiler=NONE Java parameter. However, even with this configuration, the targeted method is still missing from the profiling results

I also attempted to add a dummy statement like System.out.println:

@Override
public int price() {
   System.out.println("Dummy println");
   return this.usd * 3;
}

And only in this case did I finally observe the desired method:

InstanceOnly$Prime.price() 

So, I'm completely confused because I can't understand who is actually performing the optimization and how I can disable it to see the InstanceOnly$Prime.price() in the profiling results without adding dummy statements. Does anyone know what this could be?"

英文:

Not so far ago I had been profiling an application and noticed an interesting optimization that applies to the compiled byte code.

Here is my program:

public class InstanceOnly {

    public static void main(final String[] args) throws InterruptedException {
        int sum = 0;
        for (int i = 0; i < Integer.MAX_VALUE; ++i) {
            Book b = new Discounted(new Prime(i));
            sum += b.price();
            Thread.sleep(10);
        }
        System.out.printf("Total: %d\n", sum);
    }

    interface Book {
        int price();
    }

    static class Discounted implements Book {
        private final Book book;

        Discounted(final Book b) {
            this.book = b;
        }

        @Override
        public int price() {
            return this.book.price() / 2;
        }
    }

    static class Prime implements Book {
        private final int usd;

        Prime(final int u) {
            this.usd = u;
        }

        @Override
        public int price() {
            return this.usd * 3;
        }
    }
}

As you might notice it is rather simple - we just use decorator pattern here in order to calculate the total price of all books. The application will run very long time, so I have enough time to profile it. I’m using YourKit java profiling which use bytecode instrumentation in order to get precise number of invocations of the each method. I profile the application during one minute and get the next results:

"verification.instances.InstanceOnly.main(String[]) InstanceOnly.java","1"
"java.lang.Thread.sleep(long) Thread.java (native)", "5307"
"verification.instances.InstanceOnly$Prime.<init>(int) InstanceOnly.java", "5307"
"verification.instances.InstanceOnly$Discounted.price() InstanceOnly.java","5307"
"verification.instances.InstanceOnly$Discounted.<init>(InstanceOnly$Book) InstanceOnly.java","5307"

But where is the verification.instances.InstanceOnly$Prime.price() call? I can see that we only invoke the Prime constructor. I initially suspected that it might be a problem with JIT optimizations, where the method gets inlined. To address this, I disabled all optimizations by using the -Djava.compiler=NONE Java parameter. However, even with this configuration, the targeted method is still missing from the profiling results

I also attempted to add a dummy statement like System.out.println:

@Override
public int price() {
   System.out.println("Dummy println");
   return this.usd * 3;
}

And only in this case did I finally observe the desired method:

InstanceOnly$Prime.price() 

So, I'm completely confused because I can't understand who is actually performing the optimization and how I can disable it to see the InstanceOnly$Prime.price() in the profiling results without adding dummy statements. Does anyone know what this could be?

答案1

得分: 1

Here is the translated content:

首先,我要对 Holgerboneill 表达我的感激之情,感谢他们在找出原始问题和确定问题根本原因方面的帮助。

实际问题并不在于 JIT 编译器或构建优化。Holger 的评论提供了一个清晰而简洁的解释:
> 这不是 JIT 编译器的工作方式。在分析器注入代码之后,它成为方法的一部分,内联该方法意味着保留整个代码的行为,包括注入的代码。

因此,问题显然出在 YourKit 分析器,它引入了“trivial methods”(平凡方法)的概念。这些方法在 CPU 追踪模式下故意被忽略,以减少分析开销:
> CPU 分析:排除了诸如 getter 和 setter 这类平凡方法的 CPU 追踪仪器,以考虑性能。现在它包括字节码满足以下条件的方法:
> - 不超过 32 字节;
> - 不包含循环;
> - 仅包含以下指令:加载、存储和其他堆栈操作、字段访问、位和算术操作、比较操作、返回。特别是这意味着这些方法不能调用其他方法,也不能创建对象。

你可以在 YourKit 分析器文档 中找到更多信息。

如果我们仔细检查我们方法生成的字节码,我们会发现以下语句:

  public price()I
   L0
    LINENUMBER 44 L0
    ALOAD 0
    GETFIELD verification/instances/InstanceOnly$Prime.usd : I
    ICONST_3
    IMUL
    IRETURN
   L1
    LOCALVARIABLE this Lverification/instances/InstanceOnly$Prime; L0 L1 0
    MAXSTACK = 2
    MAXLOCALS = 1

这与“平凡方法”的特征完全吻合。因此,在分析期间没有对 price() 方法进行仪器化。要禁用此行为,您可以在 YourKit 分析中使用 _instrument_all_methods 选项。根据官方文档:

> 注意:要强制对这些方法进行仪器化,请指定启动选项 _instrument_all_methods

在我的情况下,我正在使用 CLI API 来启动分析。因此,我正在使用以下命令来指定所需的启动选项:

java -agentpath:$PROFILER_AGENT_PATH=_instrument_all_methods -jar $APPLICATION_JAR

您可以在 这里 找到有关指定 YourKit 启动选项的更多信息。

英文:

Firstly, I would like to express my gratitude to Holger and boneill for their help in pinpointing the original problem and in identifying the root cause of the issue.

The actual problem lies not with the JIT compiler or build optimizations. Holger's comment provides a clear and concise explanation of it:
> This is not how a JIT compiler works. After the profiler injected the code, it is part of the method and inlining the method implies retaining the behaviour of the entire code, including the injected code.

So, the issue clearly lies with the YourKit profiler, which incorporates a concept of "trivial methods". These methods are intentionally ignored during profiling in CPU tracing mode as a means to reduce profiling overhead:

> CPU profiling: the range of trivial methods like getters and setters excluded from CPU tracing instrumentation for performance consideration has been extended. Now it includes methods whose bytecode satisfies the following conditions:
> - does not exceed 32 bytes;
> - does not contain cycles;
> - contains only these instructions: load, store and other stack operations, field access, bit and arithmetic operations, comparison operations, return. In particular, this means that these methods cannot call other methods nor create objects.

You can find more information about this in the YourKit profiler documentation.

If we closely examine the generated bytecode of our method, we will come across the following statements:

  public price()I
   L0
    LINENUMBER 44 L0
    ALOAD 0
    GETFIELD verification/instances/InstanceOnly$Prime.usd : I
    ICONST_3
    IMUL
    IRETURN
   L1
    LOCALVARIABLE this Lverification/instances/InstanceOnly$Prime; L0 L1 0
    MAXSTACK = 2
    MAXLOCALS = 1

Which perfectly aligns with the characteristics of a "trivial method". As a result, the price() method was not instrumented during profiling. To disable this behavior, you can utilize the _instrument_all_methods option in YourKit profiling. From the official docs:

> Note: to force instrumentation of these methods specify startup option _instrument_all_methods

In my case, I am using the CLI API to initiate profiling. Therefore, I am employing the following command to specify the desired startup option:

java -agentpath:$PROFILER_AGENT_PATH=_instrument_all_methods -jar $APPLICATION_JAR

You can find further information on specifying YourKit startup options here.

huangapple
  • 本文由 发表于 2023年7月4日 22:01:26
  • 转载请务必保留本文链接:https://go.coder-hub.com/76613424.html
匿名

发表评论

匿名网友

:?: :razz: :sad: :evil: :!: :smile: :oops: :grin: :eek: :shock: :???: :cool: :lol: :mad: :twisted: :roll: :wink: :idea: :arrow: :neutral: :cry: :mrgreen:

确定