search

dragonwell-project / dragonwell8

Alibaba Dragonwell8 JDK
http://dragonwell-jdk.io
GNU General Public License v2.0
4.21k stars 496 forks source link

[upstream][dragonwell8][fastdebug][nightly]jdk/jfr/event/gc/stacktrace/TestDefNewAllocationPendingStackTrace.java intermittent fails java.lang.AssertionError: No matching stack trace found #677

Open sendaoYan opened 2 months ago

sendaoYan commented 2 months ago

https://tone.aliyun-inc.com/ws/xesljfzh/test_result/358036?tab=1
【环境准备】

BINARY_URL=oss://compiler-ci-bucket/dragonwell8/CI/tar/20240822-112257-354-#521-linux.x86_64.fastdebug.master-afffb54106e85c2ea36a26422d920fa94fb7c0ad.tar.gz
JTREG_URL=oss://compiler-ci-bucket/jdk/tools/jtreg5.1-b01.zip
JDK_REPO=https://github.com/dragonwell-project/dragonwell8.git
JDK_BRANCH=master
cd ~/tone/tone-matrix-compiler/common;./ossutil.bin_$(arch) -i;cd -
alias oss="~/tone/tone-matrix-compiler/common/ossutil.bin_$(arch) -e oss-cn-hangzhou.aliyuncs.com -u jvm_dev-b  ~/tone/tone-matrix-compiler/common/ossutil_bin/ossutil -o download -f -r"

部署二进制：
oss $BINARY_URL -l ${BINARY_URL##*/}
mkdir bin-dragonwell8;tar -xf ${BINARY_URL##*/} -C bin-dragonwell8

部署jtreg工具：
oss $JTREG_URL -l ${JTREG_URL##*/};unzip ${JTREG_URL##*/}

部署用例repo
git clone -b $JDK_BRANCH $JDK_REPO jdk-repo-dragonwell8

执行以下命令：
cd bin-dragonwell8/j2sdk-image && export JAVA_HOME=$PWD ; export PATH=$JAVA_HOME/bin:$PATH ; export TEST_JDK_HOME=$JAVA_HOME && cd -
cd jtreg ;export JT_HOME=$PWD ; export PATH=$PWD/bin:$PATH;cd -

jtreg  -nr -v:fail,error -w tmp  -Xmixed  jdk-repo-dragonwell8/jdk/test/jdk/jfr/event/gc/stacktrace/TestDefNewAllocationPendingStackTrace.java

失败率9/3w，复现命令 

function runJtreg() { jtreg -Xmixed  -ea -esa  -timeoutFactor:4 -v:fail,error,time,nopass -nr -w $dir/index-$1 $test &> $dir/$1.log ; if [[ 0 -ne $? ]] ; then echo -n "$1 " ; else rm -rf $dir/index-$1 $dir/$1.log ; fi ; } ; export -f runJtreg ; export dir="tmp-jtreg-"`basename
${test##* } .java | sed "s|#|_|"` ; rm -rf $dir ; mkdir -p $dir ; time seq 30000 | xargs -i -n 1 -P 16 bash -c "runJtreg {}" ; echo total fail number: `ls $dir/*.log 2> /dev/null | wc | awk '{print $1}'`
1435 7068 8441 9354 13989 17655 18010 18024 19404
real    521m1.829s
user    14379m51.955s
sys     1686m6.555s
total fail number: 9

【对比测试】
openjdk8 fastdebug 同样问题
531.log
jdk8u-dev-binary-x86_64-fastdebug.tar.xz 

[dongzhichun@CompilerTest-x64-5 bin]$ ./java -version;./java -Xinternalversion
openjdk version "1.8.0_432-internal-fastdebug"
OpenJDK Runtime Environment (build 1.8.0_432-internal-fastdebug-_2024_08_06_03_18-b00)
OpenJDK 64-Bit Server VM (build 25.432-b00-fastdebug, mixed mode)
OpenJDK 64-Bit Server VM (25.432-b00-fastdebug) for linux-amd64 JRE (1.8.0_432-internal-_2024_08_06_03_18-b00), built on Aug  6 2024 03:19:49 by "dongzhichun" with gcc 10.2.1 20210130 (Red Hat 10.2.1-11)

【用例日志】
1435.log
index-1435.rar

STDOUT:
[GC (Allocation Failure) [DefNew: 540224K->2503K(607680K), 0.0855304 secs] 540224K->2503K(1958016K), 0.0913313 secs] [Times: user=0.17 sys=0.00, real=0.09 secs] 
Allocation num: 41701
GC detected: 1
JFR GC events found: 1
Event: jdk.AllocationRequiringGC {
  startTime = 13:58:40.618
  gcId = 0
  size = 24 bytes
  eventThread = "JFR Periodic Tasks" (javaThreadId = 25)
  stackTrace = [
    java.util.concurrent.CopyOnWriteArrayList.iterator() line: 1082
    jdk.jfr.internal.RequestEngine.run_requests(Collection) line: 216
    jdk.jfr.internal.RequestEngine.doPeriodic() line: 187
    jdk.jfr.internal.PlatformRecorder.periodicTask() line: 441
    jdk.jfr.internal.PlatformRecorder.lambda$startDiskMonitor$1() line: 388
    ...
  ]
}

Attempt: 0 out of 5: no matching stack trace found.
[GC (Allocation Failure) [DefNew: 542727K->2561K(607680K), 0.0550803 secs] 542727K->2561K(1958016K), 0.0562089 secs] [Times: user=0.06 sys=0.00, real=0.06 secs] 
Allocation num: 49888
GC detected: 2
JFR GC events found: 1
Event: jdk.AllocationRequiringGC {
  startTime = 13:58:41.221
  gcId = 1
  size = 24 bytes
  eventThread = "JFR Periodic Tasks" (javaThreadId = 25)
  stackTrace = [
    java.util.concurrent.CopyOnWriteArrayList.iterator() line: 1082
    jdk.jfr.internal.RequestEngine.run_requests(Collection) line: 216
    jdk.jfr.internal.RequestEngine.doPeriodic() line: 187
    jdk.jfr.internal.PlatformRecorder.periodicTask() line: 441
    jdk.jfr.internal.PlatformRecorder.lambda$startDiskMonitor$1() line: 388
    ...
  ]
}

Attempt: 1 out of 5: no matching stack trace found.
[GC (Allocation Failure) [DefNew: 542785K->2568K(607680K), 0.0535861 secs] 542785K->2568K(1958016K), 0.0538423 secs] [Times: user=0.07 sys=0.00, real=0.06 secs] 
Allocation num: 51463
GC detected: 3
JFR GC events found: 1
Event: jdk.AllocationRequiringGC {
  startTime = 13:58:41.474
  gcId = 2
  size = 24 bytes
  eventThread = "JFR Periodic Tasks" (javaThreadId = 25)
  stackTrace = [
    java.util.concurrent.CopyOnWriteArrayList.iterator() line: 1082
    jdk.jfr.internal.RequestEngine.run_requests(Collection) line: 216
    jdk.jfr.internal.RequestEngine.doPeriodic() line: 187
    jdk.jfr.internal.PlatformRecorder.periodicTask() line: 441
    jdk.jfr.internal.PlatformRecorder.lambda$startDiskMonitor$1() line: 388
    ...
  ]
}

Attempt: 2 out of 5: no matching stack trace found.
[GC (Allocation Failure) [DefNew: 542792K->2570K(607680K), 0.0729983 secs] 542792K->2570K(1958016K), 0.0737920 secs] [Times: user=0.07 sys=0.00, real=0.07 secs] 
Allocation num: 51455
GC detected: 4
JFR GC events found: 1
Event: jdk.AllocationRequiringGC {
  startTime = 13:58:41.719
  gcId = 3
  size = 24 bytes
  eventThread = "JFR Periodic Tasks" (javaThreadId = 25)
  stackTrace = [
    java.util.concurrent.CopyOnWriteArrayList.iterator() line: 1082
    jdk.jfr.internal.RequestEngine.run_requests(Collection) line: 216
    jdk.jfr.internal.RequestEngine.doPeriodic() line: 187
    jdk.jfr.internal.PlatformRecorder.periodicTask() line: 441
    jdk.jfr.internal.PlatformRecorder.lambda$startDiskMonitor$1() line: 388
    ...
  ]
}

Attempt: 3 out of 5: no matching stack trace found.
[GC (Allocation Failure) [DefNew: 542794K->2573K(607680K), 0.0673860 secs] 542794K->2573K(1958016K), 0.0680504 secs] [Times: user=0.07 sys=0.00, real=0.07 secs] 
Allocation num: 50955
GC detected: 5
JFR GC events found: 1
Event: jdk.AllocationRequiringGC {
  startTime = 13:58:41.922
  gcId = 4
  size = 24 bytes
  eventThread = "JFR Periodic Tasks" (javaThreadId = 25)
  stackTrace = [
    java.util.concurrent.CopyOnWriteArrayList.iterator() line: 1082
    jdk.jfr.internal.RequestEngine.run_requests(Collection) line: 216
    jdk.jfr.internal.RequestEngine.doPeriodic() line: 187
    jdk.jfr.internal.PlatformRecorder.periodicTask() line: 441
    jdk.jfr.internal.PlatformRecorder.lambda$startDiskMonitor$1() line: 388
    ...
  ]
}

Attempt: 4 out of 5: no matching stack trace found.
Heap
 def new generation   total 607680K, used 36533K [0x0000000080200000, 0x00000000a9550000, 0x0000000300150000)
  eden space 540224K,   6% used [0x0000000080200000, 0x0000000082329d60, 0x00000000a1190000)
  from space 67456K,   3% used [0x00000000a5370000, 0x00000000a55f36a8, 0x00000000a9550000)
  to   space 67456K,   0% used [0x00000000a1190000, 0x00000000a1190000, 0x00000000a5370000)
 tenured generation   total 1350336K, used 0K [0x0000000300150000, 0x0000000352800000, 0x0000000800000000)
   the space 1350336K,   0% used [0x0000000300150000, 0x0000000300150000, 0x0000000300150200, 0x0000000352800000)
 Metaspace       used 12382K, capacity 12834K, committed 13056K, reserved 1060864K
  class space    used 1325K, capacity 1448K, committed 1536K, reserved 1048576K
STDERR:
java.lang.AssertionError: No matching stack trace found
    at jdk.jfr.event.gc.stacktrace.AllocationStackTrace.testAllocEvent(AllocationStackTrace.java:398)
    at jdk.jfr.event.gc.stacktrace.AllocationStackTrace.testDefNewAllocEvent(AllocationStackTrace.java:178)
    at jdk.jfr.event.gc.stacktrace.TestDefNewAllocationPendingStackTrace.main(TestDefNewAllocationPendingStackTrace.java:39)
    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 com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
    at java.lang.Thread.run(Thread.java:855)

JavaTest Message: Test threw exception: java.lang.AssertionError: No matching stack trace found
JavaTest Message: shutting down test

【版本信息】

[dongzhichun@CompilerTest-x64-3 dragonwell8-debug]$ uname -a ; cat /etc/os-release ; free -h ; lscpu | head -n 25 ; java -version ; java -Xinternalversion
Linux CompilerTest-x64-3 5.10.134-16.1.al8.x86_64 #1 SMP Thu Dec 7 14:11:24 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux
NAME="Alibaba Cloud Linux"
VERSION="3 (Soaring Falcon)"
ID="alinux"
ID_LIKE="rhel fedora centos anolis"
VERSION_ID="3"
UPDATE_ID="9"
PLATFORM_ID="platform:al8"
PRETTY_NAME="Alibaba Cloud Linux 3 (Soaring Falcon)"
ANSI_COLOR="0;31"
HOME_URL="https://www.aliyun.com/"

              total        used        free      shared  buff/cache   available
Mem:          123Gi       1.1Gi       120Gi       111Mi       1.7Gi       121Gi
Swap:            0B          0B          0B
Architecture:        x86_64
CPU op-mode(s):      32-bit, 64-bit
Byte Order:          Little Endian
CPU(s):              32
On-line CPU(s) list: 0-31
Thread(s) per core:  2
Core(s) per socket:  16
Socket(s):           1
NUMA node(s):        1
Vendor ID:           GenuineIntel
CPU family:          6
Model:               106
Model name:          Intel(R) Xeon(R) Platinum 8369B CPU @ 2.70GHz
Stepping:            6
CPU MHz:             3509.740
BogoMIPS:            5399.99
Hypervisor vendor:   KVM
Virtualization type: full
L1d cache:           48K
L1i cache:           32K
L2 cache:            1280K
L3 cache:            49152K
NUMA node0 CPU(s):   0-31
Flags:               fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush mmx fxsr sse sse2 ss ht syscall nx pdpe1gb rdtscp lm constant_tsc rep_good nopl nonstop_tsc cpuid aperfmperf tsc_known_freq pni pclmulqdq monitor ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt aes xsave avx f16c rdrand hypervisor lahf_lm abm 3dnowprefetch cpuid_fault invpcid_single ibrs_enhanced fsgsbase tsc_adjust bmi1 avx2 smep bmi2 erms invpcid avx512f avx512dq rdseed adx smap avx512ifma clflushopt clwb avx512cd sha_ni avx512bw avx512vl xsaveopt xsavec xgetbv1 xsaves wbnoinvd arat avx512vbmi pku ospke avx512_vbmi2 gfni vaes vpclmulqdq avx512_vnni avx512_bitalg avx512_vpopcntdq rdpid fsrm arch_capabilities
openjdk version "1.8.0_372-fastdebug"
OpenJDK Runtime Environment (Alibaba Dragonwell Extended Edition 8.19.20) (build 1.8.0_372-fastdebug-b01)
OpenJDK 64-Bit Server VM (Alibaba Dragonwell Extended Edition 8.19.20) (build 25.372-b01-fastdebug, mixed mode)
OpenJDK 64-Bit Server VM (25.372-b01-fastdebug) for linux-amd64 JRE (1.8.0_372-b01), built on Aug 22 2024 03:25:00 by "" with gcc 4.8.2 20140120 (Red Hat 4.8.2-15)
[dongzhichun@CompilerTest-x64-3 dragonwell8-debug]$
sendaoYan commented 2 months ago

https://code.alibaba-inc.com/os-quality/tone-matrix-compiler/codereview/18075264

sendaoYan commented 2 months ago

https://bugs.openjdk.org/browse/JDK-8148052

dzchun commented 2 months ago

加上-XX:FlightRecorderOptions:stackdepth=256 -XX:NewSize=5M选项之后没问题

sendaoYan commented 2 months ago

加上-XX:FlightRecorderOptions:stackdepth=256 -XX:NewSize=5M选项之后没问题

@dzchun 帮我确认下TestG1HumongousAllocationPendingStackTrace.java这个用例，加上选项之前和加上选项之后的测试结果

dzchun commented 2 months ago

加上-XX:FlightRecorderOptions:stackdepth=256 -XX:NewSize=5M选项之后没问题

@dzchun 帮我确认下TestG1HumongousAllocationPendingStackTrace.java这个用例，加上选项之前和加上选项之后的测试结果

加上之前和加上之后都没问题