JDK-8261844 : serviceability/sa/ClhsdbFindPC.java#id1 failed with "'In code in NMethod for LingeredAppWithTrivialMain.main' missing from stdout/stderr"
  • Type: Bug
  • Component: hotspot
  • Sub-Component: svc-agent
  • Affected Version: 17
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • OS: linux_ubuntu
  • CPU: x86_64
  • Submitted: 2021-02-16
  • Updated: 2021-02-16
  • Resolved: 2021-02-16
Related Reports
Duplicate :  
JDK-8261702 - ClhsdbFindPC can fail due to PointerFinder incorrectly thinking an address is in a .so
Relates :  
JDK-8247514 - Improve clhsdb 'findpc' ability to determine what an address points to by improving PointerFinder and PointerLocation classes
Description
The following test failed on my Ubuntu 16.04 server with JDK17 bits:

serviceability/sa/ClhsdbFindPC.java#id1

Here's a snippet from the log file:

----------System.err:(32/2016)----------
 stdout: [ + findpc 0x00002b28f0f2a284
Address 0x00002b28f0f2a284: /work/shared/mirrors/src_clones/jdk/jdk_baseline.git/build/linux-x86_64-normal-server-fastdebug/images/jdk/lib/server/libjvm.so + 0xff50284
];
 stderr: [ + findpc 0x00002b28f0f2a284
Address 0x00002b28f0f2a284: /work/shared/mirrors/src_clones/jdk/jdk_baseline.git/build/linux-x86_64-normal-server-fastdebug/images/jdk/lib/server/libjvm.so + 0xff50284
]
 exitValue = -1

java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: 'In code in NMethod for LingeredAppWithTrivialMain.main' missing from stdout/stderr

        at ClhsdbFindPC.testFindPC(ClhsdbFindPC.java:242)
        at ClhsdbFindPC.main(ClhsdbFindPC.java:264)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
        at java.base/java.lang.Thread.run(Thread.java:831)
Caused by: java.lang.RuntimeException: 'In code in NMethod for LingeredAppWithTrivialMain.main' missing from stdout/stderr

        at jdk.test.lib.process.OutputAnalyzer.shouldMatch(OutputAnalyzer.java:325)
        at ClhsdbLauncher.runCmd(ClhsdbLauncher.java:163)
        at ClhsdbLauncher.runOnCore(ClhsdbLauncher.java:222)
        at ClhsdbFindPC.runTest(ClhsdbFindPC.java:254)
        at ClhsdbFindPC.testFindPC(ClhsdbFindPC.java:167)
        ... 7 more

JavaTest Message: Test threw exception: java.lang.RuntimeException: Test ERROR java.lang.RuntimeException: 'In code in NMethod for LingeredAppWithTrivialMain.main' missing from stdout/stderr

I checked the JDK17 CI for today and this is what the output should
look like:

hsdb> hsdb> + verbose true
hsdb> + findpc 0x00007f5f2dee5184
Address 0x00007f5f2dee5184: In code in NMethod for LingeredAppWithTrivialMain.main([Ljava/lang/String;)V content: [0x00007f5f2dee5140, 0x00007f5f2dee5268),  code: [0x00007f5f2dee5140, 0x00007f5f2dee5268),  data: [0x00007f5f2dee5268, 0x00007f5f2dee52f0),  oops: [0x00007f5f2dee5268, 0x00007f5f2dee5270),  frame size: 64
hsdb> + quit
Comments
I've attached the log files for the failures I just reproduced with 8247514 as the HEAD of the repo: $ unzip -l jdk-17-20210216_linux.zip Archive: jdk-17-20210216_linux.zip Length Date Time Name --------- ---------- ----- ---- 24040 2021-02-16 15:26 test_failures.2021-02-16-152536/ClhsdbFindPC_id3.jtr.fastdebug 133155 2021-02-16 15:26 test_failures.2021-02-16-152536/hs_err_pid30236.log 25274 2021-02-16 15:34 test_failures.2021-02-16-153317/ClhsdbFindPC_id1.jtr.fastdebug 24010 2021-02-16 15:34 test_failures.2021-02-16-153317/ClhsdbFindPC_id3.jtr.fastdebug 140557 2021-02-16 15:34 test_failures.2021-02-16-153317/hs_err_pid1445.log 133186 2021-02-16 15:34 test_failures.2021-02-16-153317/hs_err_pid1468.log --------- ------- 480222 6 files
16-02-2021
I setup a repo with the open HEAD here: $ git log HEAD^! commit e29c560a11c4cbc261bdd04db5d24170fb9f12b6 (HEAD) Author: Chris Plummer <cjplummer@openjdk.org> Date: Fri Feb 12 22:01:43 2021 +0000 8247514: Improve clhsdb 'findpc' ability to determine what an address points to by improving PointerFinder and PointerLocation classes Reviewed-by: ysuenaga, kevinw and serviceability/sa/ClhsdbFindPC.java starts failing: $ do_java_test serviceability/sa/ClhsdbFindPC.java 2>&1 | tee do_java_test.8247514.log INFO: GNUMAKE=make INFO: GNUMAKE version is: GNU Make 4.1 INFO: JTREG options: INFO: JOBS=16 INFO: TEST_MODE=othervm INFO: EXTRA_PROBLEM_LISTS=ProblemList-extra.txt INFO: VM_OPTIONS= INFO: test_val=serviceability/sa/ClhsdbFindPC.java Test Config: linux-x86_64-normal-server-release INFO: TIMEOUT_FACTOR=4 Done testing Test Run linux-x86_64-normal-server-release time: 0.54 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/hotspot/jtreg/serviceability/sa/ClhsdbFindPC.java >> 4 3 1 0 << 1 failure(s) found in log=do_java_test.linux-x86_64-normal-server-release.log TEST: serviceability/sa/ClhsdbFindPC.java#id3 ERROR: Failed to instantiate timeout handler: jdk.test.failurehandler.jtreg.GatherProcessInfoTimeoutHandler: file does not exist Test Config: linux-x86_64-normal-server-fastdebug INFO: TIMEOUT_FACTOR=6 Done testing Test Run linux-x86_64-normal-server-fastdebug time: 0.93 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/hotspot/jtreg/serviceability/sa/ClhsdbFindPC.java >> 4 3 1 0 << 1 failure(s) found in log=do_java_test.linux-x86_64-normal-server-fastdebug.log TEST: serviceability/sa/ClhsdbFindPC.java#id3 LOG: build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id3.jtr Saving build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id3.jtr as /work/shared/bug_hunt/8261844_for_jdk17.git/test_failures.2021-02-16-152536/ClhsdbFindPC_id3.jtr.fastdebug Saving /work/shared/bug_hunt/8261844_for_jdk17.git/build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id3/hs_err_pid30236.log as /work/shared/bug_hunt/8261844_for_jdk17.git/test_failures.2021-02-16-152536/hs_err_pid30236.log Moving /work/shared/bug_hunt/8261844_for_jdk17.git/build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id3/core to /work/shared/bug_hunt/8261844_for_jdk17.git/test_failures.2021-02-16-152536/core.30236 Test Config: linux-x86_64-normal-server-slowdebug INFO: TIMEOUT_FACTOR=12 Done testing Test Run linux-x86_64-normal-server-slowdebug time: 3.31 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/hotspot/jtreg/serviceability/sa/ClhsdbFindPC.java 4 4 0 0 Total test time: 4.79 minutes. I did a second run to check for reproducibility: $ do_java_test serviceability/sa/ClhsdbFindPC.java 2>&1 | tee -a do_java_test.8247514.log INFO: GNUMAKE=make INFO: GNUMAKE version is: GNU Make 4.1 INFO: JTREG options: INFO: JOBS=16 INFO: TEST_MODE=othervm INFO: EXTRA_PROBLEM_LISTS=ProblemList-extra.txt INFO: VM_OPTIONS= INFO: test_val=serviceability/sa/ClhsdbFindPC.java Test Config: linux-x86_64-normal-server-release INFO: TIMEOUT_FACTOR=4 Done testing Test Run linux-x86_64-normal-server-release time: 0.50 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/hotspot/jtreg/serviceability/sa/ClhsdbFindPC.java >> 4 3 1 0 << 1 failure(s) found in log=do_java_test.linux-x86_64-normal-server-release.log TEST: serviceability/sa/ClhsdbFindPC.java#id3 ERROR: Failed to instantiate timeout handler: jdk.test.failurehandler.jtreg.GatherProcessInfoTimeoutHandler: file does not exist Test Config: linux-x86_64-normal-server-fastdebug INFO: TIMEOUT_FACTOR=6 Done testing Test Run linux-x86_64-normal-server-fastdebug time: 0.88 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/hotspot/jtreg/serviceability/sa/ClhsdbFindPC.java >> 4 2 2 0 << 2 failure(s) found in log=do_java_test.linux-x86_64-normal-server-fastdebug.log TEST: serviceability/sa/ClhsdbFindPC.java#id3 LOG: build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id3.jtr Saving build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id3.jtr as /work/shared/bug_hunt/8261844_for_jdk17.git/test_failures.2021-02-16-153317/ClhsdbFindPC_id3.jtr.fastdebug Saving /work/shared/bug_hunt/8261844_for_jdk17.git/build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id3/hs_err_pid1468.log as /work/shared/bug_hunt/8261844_for_jdk17.git/test_failures.2021-02-16-153317/hs_err_pid1468.log Moving /work/shared/bug_hunt/8261844_for_jdk17.git/build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id3/core to /work/shared/bug_hunt/8261844_for_jdk17.git/test_failures.2021-02-16-153317/core.1468 TEST: serviceability/sa/ClhsdbFindPC.java#id1 LOG: build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id1.jtr Saving build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id1.jtr as /work/shared/bug_hunt/8261844_for_jdk17.git/test_failures.2021-02-16-153317/ClhsdbFindPC_id1.jtr.fastdebug Saving /work/shared/bug_hunt/8261844_for_jdk17.git/build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id1/hs_err_pid1445.log as /work/shared/bug_hunt/8261844_for_jdk17.git/test_failures.2021-02-16-153317/hs_err_pid1445.log Moving /work/shared/bug_hunt/8261844_for_jdk17.git/build/linux-x86_64-normal-server-fastdebug/test-support/jtreg_open_test_hotspot_jtreg_serviceability_sa_ClhsdbFindPC_java/serviceability/sa/ClhsdbFindPC_id1/core to /work/shared/bug_hunt/8261844_for_jdk17.git/test_failures.2021-02-16-153317/core.1445 Test Config: linux-x86_64-normal-server-slowdebug INFO: TIMEOUT_FACTOR=12 Done testing Test Run linux-x86_64-normal-server-slowdebug time: 4.24 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/hotspot/jtreg/serviceability/sa/ClhsdbFindPC.java 4 4 0 0 Total test time: 5.61 minutes. I have not seen a failure like the 'release' bits failure mode before: TEST: serviceability/sa/ClhsdbFindPC.java#id3 ERROR: Failed to instantiate timeout handler: jdk.test.failurehandler.jtreg.GatherProcessInfoTimeoutHandler: file does not exist And it looks like I get a couple of different subtests failing with 'fastdebug' bits. In both 'slowdebug' runs, all subtests passed.
16-02-2021
I setup a repo with the open HEAD set here: $ git log HEAD^! commit dc46aa85c6e16cb904d1c40a4577b5e48c56a3d4 (HEAD) Author: Christoph Langer <clanger@openjdk.org> Date: Fri Feb 12 20:58:22 2021 +0000 8261534: Test sun/security/pkcs11/KeyAgreement/IllegalPackageAccess.java fails on platforms where no nsslib artifacts are defined Reviewed-by: mbaesken and serviceability/sa/ClhsdbFindPC.java passes all four sub tests: $ do_java_test serviceability/sa/ClhsdbFindPC.java 2>&1 | tee do_java_test.8261534.log INFO: GNUMAKE=make INFO: GNUMAKE version is: GNU Make 4.1 INFO: JTREG options: INFO: JOBS=16 INFO: TEST_MODE=othervm INFO: EXTRA_PROBLEM_LISTS=ProblemList-extra.txt INFO: VM_OPTIONS= INFO: test_val=serviceability/sa/ClhsdbFindPC.java Test Config: linux-x86_64-normal-server-release INFO: TIMEOUT_FACTOR=4 Done testing Test Run linux-x86_64-normal-server-release time: 0.36 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/hotspot/jtreg/serviceability/sa/ClhsdbFindPC.java 4 4 0 0 Test Config: linux-x86_64-normal-server-fastdebug INFO: TIMEOUT_FACTOR=6 Done testing Test Run linux-x86_64-normal-server-fastdebug time: 0.75 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/hotspot/jtreg/serviceability/sa/ClhsdbFindPC.java 4 4 0 0 Test Config: linux-x86_64-normal-server-slowdebug INFO: TIMEOUT_FACTOR=12 Done testing Test Run linux-x86_64-normal-server-slowdebug time: 2.82 minutes. TEST TOTAL PASS FAIL ERROR jtreg:open/test/hotspot/jtreg/serviceability/sa/ClhsdbFindPC.java 4 4 0 0 Total test time: 3.94 minutes.
16-02-2021
I attached the logs for the failures that I observed in my auto-build-n-test setup on 2021.02.14 and 2021.02.15: $ unzip -l jdk-17-20210214,5_linux.zip Archive: jdk-17-20210214,5_linux.zip Length Date Time Name --------- ---------- ----- ---- 25035 2021-02-14 23:45 test_failures.2021-02-14-233423/ClhsdbFindPC_id1.jtr.fastdebug 140695 2021-02-14 23:45 test_failures.2021-02-14-233423/hs_err_pid8329.log 25041 2021-02-15 23:42 test_failures.2021-02-15-233033/ClhsdbFindPC_id1.jtr.fastdebug 140714 2021-02-15 23:41 test_failures.2021-02-15-233033/hs_err_pid24893.log --------- ------- 331485 4 files
16-02-2021
I'm pretty sure this is the same as JDK-8261702, which is caused by my recent JDK-8247514 changes. I noticed it on a local test run, but only once, and I couldn't reproduce it. However, I'm pretty sure I understand why it happened and have a fix which has been reviewed. I'll push it today after a bit more sanity testing.
16-02-2021