RFR: 8178287: AsyncGetCallTrace fails to traverse valid Java stacks [v4]

David Holmes dholmes at openjdk.java.net
Mon Aug 23 11:00:36 UTC 2021


On Mon, 23 Aug 2021 10:28:36 GMT, Jaroslav Bachorik <jbachorik at openjdk.org> wrote:

>> Ludovic Henry has updated the pull request with a new target base due to a merge or a rebase. The incremental webrev excludes the unrelated changes brought in by the merge/rebase. The pull request contains eight additional commits since the last revision:
>> 
>>  - Remove FrameParser and the required allocation
>>    
>>    The need for the allocation would be it non async-safe. However,
>>    AsyncGetCallTrace is async-safe and thus can't allow for allocations.
>>  - Merge branch 'master' of https://github.com/openjdk/jdk into fix-8178287
>>  - Fix comments
>>  - Disable checks in FrameParser when known to be safe
>>  - Allow AsyncGetCallTrace and JFR to unwind stack from vtable stub
>>    
>>    The program is the following:
>>    
>>    ```
>>    import java.util.function.Supplier;
>>    
>>    public class Prof2 {
>>    
>>        public static void main(String[] args) {
>>            var rand = new java.util.Random(0);
>>            Supplier[] suppliers = {
>>                    () -> 0,
>>                    () -> 1,
>>                    () -> 2,
>>                    () -> 3,
>>            };
>>    
>>            long sum = 0;
>>            for (int i = 0; i >= 0; i++) {
>>                sum += (int)suppliers[i % suppliers.length].get();
>>            }
>>        }
>>    }
>>    ```
>>    
>>    The results are as follows:
>>    
>>    - Baseline (from previous commit):
>>    
>>    Flat Profile (by method):
>>                (t 39.3,s 39.3) AGCT::Unknown Java[ERR=-5]
>>                (t 40.3,s 36.1) Prof2::main
>>                (t  6.4,s  5.3) Prof2$$Lambda$28.0x0000000800081000::get
>>                (t  6.1,s  5.1) Prof2$$Lambda$29.0x0000000800081220::get
>>                (t  6.0,s  5.0) Prof2$$Lambda$27.0x0000000800080c28::get
>>                (t  6.1,s  5.0) Prof2$$Lambda$26.0x0000000800080a08::get
>>                (t  1.1,s  1.1) Prof2::lambda$main$2
>>                (t  1.1,s  1.1) Prof2::lambda$main$0
>>                (t  1.0,s  1.0) Prof2::lambda$main$1
>>                (t  0.9,s  0.9) Prof2::lambda$main$3
>>                (t  0.1,s  0.1) AGCT::Unknown not Java[ERR=-3]
>>    
>>    - With unwind from vtable stub
>>    
>>    Flat Profile (by method):
>>            (t 74.1,s 70.3) Prof2::main
>>            (t  6.5,s  5.5) Prof2$$Lambda$29.0x0000000800081220::get
>>            (t  6.6,s  5.4) Prof2$$Lambda$28.0x0000000800081000::get
>>            (t  5.7,s  5.0) Prof2$$Lambda$26.0x0000000800080a08::get
>>            (t  5.9,s  5.0) Prof2$$Lambda$27.0x0000000800080c28::get
>>            (t  4.9,s  4.9) AGCT::Unknown Java[ERR=-5]
>>            (t  1.2,s  1.2) Prof2::lambda$main$2
>>            (t  0.9,s  0.9) Prof2::lambda$main$3
>>            (t  0.9,s  0.9) Prof2::lambda$main$1
>>            (t  0.7,s  0.7) Prof2::lambda$main$0
>>            (t  0.1,s  0.1) AGCT::Unknown not Java[ERR=-3]
>>    
>>    We attribute the vtable stub to the caller and not the callee, which is
>>    already an improvement from the existing case.
>>  - Allow AsyncGetCallTrace and JFR to unwind stack from nmethod's prolog
>>    
>>    When sampling hits the prolog of a method, Hotspot assumes it's unable
>>    to parse the frame. This change allows to parse such frame on x86 by
>>    specializing which instruction it's hitting in the prolog.
>>    
>>    The results are as follows:
>>    
>>    - Baseline:
>>    
>>    Flat Profile (by method):
>>            (t 60.7,s 60.7) AGCT::Unknown Java[ERR=-5]
>>            (t 39.2,s 35.2) Prof2::main
>>            (t  1.4,s  1.4) Prof2::lambda$main$3
>>            (t  1.0,s  1.0) Prof2::lambda$main$2
>>            (t  0.9,s  0.9) Prof2::lambda$main$1
>>            (t  0.7,s  0.7) Prof2::lambda$main$0
>>            (t  0.1,s  0.1) AGCT::Unknown not Java[ERR=-3]
>>            (t  0.0,s  0.0) java.lang.Thread::exit
>>            (t  0.9,s  0.0) Prof2$$Lambda$2.0x0000000800c00c28::get
>>            (t  1.0,s  0.0) Prof2$$Lambda$3.0x0000000800c01000::get
>>            (t  1.4,s  0.0) Prof2$$Lambda$4.0x0000000800c01220::get
>>            (t  0.7,s  0.0) Prof2$$Lambda$1.0x0000000800c00a08::get
>>    
>>    - With incomplete frame parsing:
>>    
>>    Flat Profile (by method):
>>            (t 39.3,s 39.3) AGCT::Unknown Java[ERR=-5]
>>            (t 40.3,s 36.1) Prof2::main
>>            (t  6.4,s  5.3) Prof2$$Lambda$28.0x0000000800081000::get
>>            (t  6.1,s  5.1) Prof2$$Lambda$29.0x0000000800081220::get
>>            (t  6.0,s  5.0) Prof2$$Lambda$27.0x0000000800080c28::get
>>            (t  6.1,s  5.0) Prof2$$Lambda$26.0x0000000800080a08::get
>>            (t  1.1,s  1.1) Prof2::lambda$main$2
>>            (t  1.1,s  1.1) Prof2::lambda$main$0
>>            (t  1.0,s  1.0) Prof2::lambda$main$1
>>            (t  0.9,s  0.9) Prof2::lambda$main$3
>>            (t  0.1,s  0.1) AGCT::Unknown not Java[ERR=-3]
>>            (t  0.0,s  0.0) java.util.Locale::getInstance
>>            (t  0.0,s  0.0) AGCT::Not walkable Java[ERR=-6]
>>            (t  0.0,s  0.0) jdk.internal.loader.BuiltinClassLoader::loadClassOrNull
>>            (t  0.0,s  0.0) java.lang.ClassLoader::loadClass
>>            (t  0.0,s  0.0) sun.net.util.URLUtil::urlNoFragString
>>            (t  0.0,s  0.0) java.lang.Class::forName0
>>            (t  0.0,s  0.0) java.util.Locale::initDefault
>>            (t  0.0,s  0.0) jdk.internal.loader.BuiltinClassLoader::loadClass
>>            (t  0.0,s  0.0) jdk.internal.loader.URLClassPath::getLoader
>>            (t  0.0,s  0.0) jdk.internal.loader.URLClassPath::getResource
>>            (t  0.0,s  0.0) java.lang.String::toLowerCase
>>            (t  0.0,s  0.0) sun.launcher.LauncherHelper::loadMainClass
>>            (t  0.0,s  0.0) sun.launcher.LauncherHelper::checkAndLoadMain
>>            (t  0.0,s  0.0) java.util.Locale::<clinit>
>>            (t  0.0,s  0.0) jdk.internal.loader.BuiltinClassLoader::findClassOnClassPathOrNull
>>            (t  0.0,s  0.0) jdk.internal.loader.ClassLoaders$AppClassLoader::loadClass
>>            (t  0.0,s  0.0) java.lang.Class::forName
>>    
>>    The program is as follows:
>>    
>>    ```
>>    import java.util.function.Supplier;
>>    
>>    public class Prof2 {
>>    
>>        public static void main(String[] args) {
>>            var rand = new java.util.Random(0);
>>            Supplier[] suppliers = {
>>                    () -> 0,
>>                    () -> 1,
>>                    () -> 2,
>>                    () -> 3,
>>            };
>>    
>>            long sum = 0;
>>            for (int i = 0; i >= 0; i++) {
>>                sum += (int)suppliers[i % suppliers.length].get();
>>            }
>>        }
>>    }
>>    ```
>>    
>>    We see that the results are particularely useful in this case as the
>>    methods are very short (it only returns an integer), and the probability
>>    of hitting the prolog is then very high.
>>  - Allow AsyncGetCallTrace and JFR to walk a stub frame
>>    
>>    When the signal sent for AsyncGetCallTrace or JFR would land on a stub
>>    (like arraycopy), it wouldn't be able to detect the sender (caller)
>>    frame because `_cb->frame_size() == 0`.
>>    
>>    Because we fully control how the prolog and epilog of stub code is
>>    generated, we know there are two cases:
>>    1. A stack frame is allocated via macroAssembler->enter(), and consists
>>    in `push rbp; mov rsp, rbp;`.
>>    2. No stack frames are allocated and rbp is left unchanged and rsp is
>>    decremented with the `call` instruction that push the return `pc` on the
>>    stack.
>>    
>>    For case 1., we can easily know the sender frame by simply looking at
>>    rbp, especially since we know that all stubs preserve the frame pointer
>>    (on x86 at least).
>>    
>>    For case 2., we end up returning the sender's sender, but that already
>>    gives us more information than what we have today.
>>    
>>    The results are as follows:
>>    
>>    - Baseline:
>>    
>>    Flat Profile (by method):
>>            (t 99.4,s 99.4) AGCT::Unknown Java[ERR=-5]
>>            (t  0.5,s  0.2) Prof1::main
>>            (t  0.2,s  0.2) java.lang.AbstractStringBuilder::append
>>            (t  0.1,s  0.1) AGCT::Unknown not Java[ERR=-3]
>>            (t  0.0,s  0.0) java.lang.AbstractStringBuilder::ensureCapacityInternal
>>            (t  0.0,s  0.0) java.lang.AbstractStringBuilder::shift
>>            (t  0.0,s  0.0) java.lang.String::getBytes
>>            (t  0.0,s  0.0) java.lang.AbstractStringBuilder::putStringAt
>>            (t  0.0,s  0.0) java.lang.StringBuilder::delete
>>            (t  0.2,s  0.0) java.lang.StringBuilder::append
>>            (t  0.0,s  0.0) java.lang.AbstractStringBuilder::delete
>>            (t  0.0,s  0.0) java.lang.AbstractStringBuilder::putStringAt
>>    
>>    - With StubRoutinesBlob::FrameParser
>>    
>>    Flat Profile (by method):
>>            (t 98.7,s 98.7) java.lang.AbstractStringBuilder::ensureCapacityInternal
>>            (t  0.9,s  0.9) java.lang.AbstractStringBuilder::delete
>>            (t 99.8,s  0.2) Prof1::main
>>            (t  0.1,s  0.1) AGCT::Unknown not Java[ERR=-3]
>>            (t  0.0,s  0.0) AGCT::Unknown Java[ERR=-5]
>>            (t 98.8,s  0.0) java.lang.AbstractStringBuilder::append
>>            (t 98.8,s  0.0) java.lang.StringBuilder::append
>>            (t  0.9,s  0.0) java.lang.StringBuilder::delete
>>    
>>    The program is as follows:
>>    
>>    ```
>>    public class Prof1 {
>>    
>>        public static void main(String[] args) {
>>            StringBuilder sb = new StringBuilder();
>>            for (int i = 0; i < 1000000; i++) {
>>                sb.append("ab");
>>                sb.delete(0, 1);
>>            }
>>            System.out.println(sb.length());
>>        }
>>    }
>>    ```
>>    
>>    We now account for the arraycopy stub which is called by
>>    AbstractStringBuilder::ensureCapacityInternal. It was previously ignored
>>    because it would not know how to parse the frame for the arraycopy stub
>>    and would fall in the AGCT::Unknown Java[ERR=-5] section.
>>    
>>    However, it still isn't perfect since it doesn't point to the arraycopy stub
>>    directly.
>>  - Extract sender frame parsing to CodeBlock::FrameParser
>>    
>>    Whether and how a frame is setup is controlled by the code generator
>>    for the specific CodeBlock. The CodeBlock is then in the best place to know how
>>    to parse the sender's frame from the current frame in the given CodeBlock.
>>    
>>    This refactoring proposes to extract this parsing out of `frame` and into a
>>    `CodeBlock::FrameParser`. This FrameParser is then specialized in the relevant
>>    inherited children of CodeBlock.
>>    
>>    This change is to largely facilitate adding new supported cases for JDK-8252417
>>    like runtime stubs.
>
> @dcubed-ojdk , @dholmes-ora would you be willing/able to take a look at this change, pretty please?

Sorry @jbachorik  but frames and code-blobs are not an area I know.

David

-------------

PR: https://git.openjdk.java.net/jdk/pull/4436


More information about the hotspot-jfr-dev mailing list