search

oracle / visualvm

VisualVM is an All-in-One Java Troubleshooting Tool
https://visualvm.github.io/
Other
2.83k stars 298 forks source link

[Sporadic] CPU Profiler ArrayIndexOutOfBoundsException #285

Open pavlus opened 3 years ago

pavlus commented 3 years ago

Describe the bug

Relevant stack trace snippet:

Caused by: java.lang.ArrayIndexOutOfBoundsException: Index 6200 out of bounds for length 6200
    at org.graalvm.visualvm.lib.jfluid.server.ProfilerRuntimeCPUFullInstr.methodEntry(ProfilerRuntimeCPUFullInstr.java:180)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:662)

Observed when connecting to local Spring Boot application.

When profiling is stopped there is no exception.

CPU Profiler configuration contains only part of all application classes. (app.package.root.service.something**)

Can't reproduce.

Expected behavior No exception coming from profiler code.

Desktop:

Additional context

This is seems to be the offending line: https://github.com/oracle/visualvm/blob/master/visualvm/libs.profiler/lib.profiler/src/org/graalvm/visualvm/lib/jfluid/server/ProfilerRuntimeCPUFullInstr.java#L180 

            if (ti.stackDepth <= stackDepthLimit) {
                // See comment marked with (***)
                int methodIdInt = methodId&0xff;
                methodIdInt |= methodId&0xff00;

                // Now check if it's the first invocation of this method, and if so, perform instrumentation of nearest callees
                if (!instrMethodInvoked[methodIdInt]) { // <-- thrown from here
                    instrMethodInvoked[methodIdInt] = true; // Mark this method as invoked
                    firstTimeMethodInvoke(ti, methodId);
                }

Bit manipulation here looks correct, so I've quickly checked where instrMethodInvoked comes from, and it may be the case that it's size calculation is slightly wrong at:

https://github.com/oracle/visualvm/blob/fce6d08e92fdafd9d4fb0f0bf35d9b8f1afc60b1/visualvm/libs.profiler/lib.profiler/src/org/graalvm/visualvm/lib/jfluid/global/ProfilingSessionStatus.java#L377

or some other problem with concurrency.

Since I'm no JVM internals expert, I'm not sure about it and how to narrow it down more.

Visual VM Log

-------------------------------------------------------------------------------
>Log Session: Monday, March 22, 2021 at 12:33:22 PM Eastern European Standard Time
>System Info: 
  Product Version         = VisualVM 2.0.6
  Operating System        = Linux version 5.10.0-4-amd64 running on amd64
  Java; VM; Vendor        = 11.0.11-ea; OpenJDK 64-Bit Server VM 11.0.11-ea+4-post-Debian-1; Debian
  Runtime                 = OpenJDK Runtime Environment 11.0.11-ea+4-post-Debian-1
  Java Home               = /usr/lib/jvm/java-11-openjdk-amd64
  System Locale; Encoding = en_US (visualvm); UTF-8
  Home Directory          = /home/pavel
  Current Directory       = /home/pavel
  User Directory          = /home/pavel/.visualvm/2.0.6
  Cache Directory         = /home/pavel/.cache/visualvm/2.0.6
  Installation            = /usr/share/visualvm/visualvm
                            /usr/share/visualvm/platform
  Boot & Ext. Classpath   = 
  Application Classpath   = /usr/share/visualvm/platform/lib/boot.jar:/usr/share/visualvm/platform/lib/org-openide-modules.jar:/usr/share/visualvm/platform/lib/org-openide-util.jar:/usr/share/visualvm/platform/lib/org-openide-util-lookup.jar:/usr/share/visualvm/platform/lib/org-openide-util-ui.jar
  Startup Classpath       = /usr/share/visualvm/platform/core/asm-8.0.1.jar:/usr/share/visualvm/platform/core/asm-commons-8.0.1.jar:/usr/share/visualvm/platform/core/asm-tree-8.0.1.jar:/usr/share/visualvm/platform/core/core-base.jar:/usr/share/visualvm/platform/core/core.jar:/usr/share/visualvm/platform/core/org-netbeans-libs-asm.jar:/usr/share/visualvm/platform/core/org-openide-filesystems-compat8.jar:/usr/share/visualvm/platform/core/org-openide-filesystems.jar:/usr/share/visualvm/visualvm/core/org-graalvm-visualvm-modules-startup.jar:/usr/share/visualvm/visualvm/core/locale/core_visualvm.jar
-------------------------------------------------------------------------------
WARNING [org.netbeans.core.projects.cache]: layer jar:file:/usr/share/visualvm/visualvm/modules/org-graalvm-visualvm-jfr.jar!/org/graalvm/visualvm/jfr/resources/layer.xml contains duplicate folders named Actions/Other
INFO [org.netbeans.core.startup.NbEvents]: Turning on modules:
    org.openide.util.lookup [8.43 20201005-debian-12.1]
    org.openide.util [9.16 20201005-debian-12.1]
    org.openide.util.ui [9.17 20201005-debian-12.1]
    org.openide.modules [7.57 20201005-debian-12.1]
    org.netbeans.api.annotations.common/1 [1.36 20201005-debian-12.1]
    org.openide.filesystems [9.19 20201005-debian-12.1]
    org.openide.awt [7.77 20201005-debian-12.1]
    org.netbeans.api.progress/1 [1.56 20201005-debian-12.1]
    org.netbeans.api.progress.nb [1.56 20201005-debian-12.1]
    org.openide.dialogs [7.51 20201005-debian-12.1]
    org.openide.nodes [7.54 20201005-debian-12.1]
    org.openide.windows [6.86 20201005-debian-12.1]
    org.netbeans.modules.editor.mimelookup/1 [1.49 20201005-debian-12.1]
    org.openide.text [6.76 20201005-debian-12.1]
    org.netbeans.api.scripting [1.6 20201005-debian-12.1]
    org.netbeans.swing.tabcontrol [1.65 20201005-debian-12.1]
    org.netbeans.swing.outline [1.43 20201005-debian-12.1]
    org.openide.explorer [6.71 20201005-debian-12.1]
    org.openide.actions [6.48 20201005-debian-12.1]
    org.netbeans.modules.queries/1 [1.52 20201005-debian-12.1]
    org.netbeans.api.templates [1.17 20201005-debian-12.1]
    org.openide.filesystems.nb [9.19 20201005-debian-12.1]
    org.openide.loaders [7.77 20201005-debian-12.1]
    org.netbeans.api.intent [1.11 20201005-debian-12.1]
    org.netbeans.api.io [1.12 20201005-debian-12.1]
    org.openide.io [1.58 20201005-debian-12.1]
    org.openide.filesystems.compat8 [9.18 20201005-debian-12.1]
    org.netbeans.swing.plaf [1.51 20201005-debian-12.1]
    org.netbeans.spi.quicksearch [1.36 20201005-debian-12.1]
    org.netbeans.libs.asm [5.12 20201005-debian-12.1]
    org.netbeans.bootstrap/1 [2.87 20201005-debian-12.1]
    org.netbeans.core.startup.base [1.71.0.1 1 20201005-debian-12.1]
    org.netbeans.core.startup/1 [1.71.0.1 20201005-debian-12.1]
    org.netbeans.modules.settings/1 [1.58 20201005-debian-12.1]
    org.netbeans.modules.sendopts/2 [2.45 20201005-debian-12.1]
    org.netbeans.modules.sampler [1.23 20201005-debian-12.1]
    org.netbeans.modules.progress.ui [1.42 20201005-debian-12.1]
    org.netbeans.modules.keyring [1.33 20201005-debian-12.1]
    org.netbeans.core/2 [3.60 20201005-debian-12.1]
    org.netbeans.modules.options.api/1 [1.54 20201005-debian-12.1]
    org.netbeans.modules.options.keymap [1.46 20201005-debian-12.1]
    org.netbeans.modules.masterfs/2 [2.64.0.2 2 20201005-debian-12.1]
    org.netbeans.modules.masterfs.ui [2.12.0.2 20201005-debian-12.1]
    org.netbeans.modules.masterfs.nio2 [1.24 20201005-debian-12.1]
    org.netbeans.libs.jna/2 [2.4 20201005-debian-12.1]
    org.netbeans.modules.masterfs.linux [1.22 20201005-debian-12.1]
    org.netbeans.modules.keyring.fallback [1.17 20201005-debian-12.1]
    org.netbeans.modules.keyring.impl [1.33 20201005-debian-12.1]
    org.netbeans.modules.editor.mimelookup.impl/1 [1.41 20201005-debian-12.1]
    org.netbeans.modules.autoupdate.services [1.64 20201005-debian-12.1]
    org.netbeans.modules.autoupdate.ui [1.55 20201005-debian-12.1]
    org.netbeans.modules.autoupdate.cli [1.22 20201005-debian-12.1]
    org.netbeans.libs.jna.platform/2 [2.4 20201005-debian-12.1]
    org.netbeans.core.windows/2 [2.94 20201005-debian-12.1]
    org.netbeans.core.ui/1 [1.54 20201005-debian-12.1]
    org.netbeans.core.network [1.21 20201005-debian-12.1]
    org.netbeans.core.nativeaccess/1 [1.40 20201005-debian-12.1]
    org.netbeans.core.multitabs/1 [1.21.0.1 1 20201005-debian-12.1]
    org.netbeans.core.io.ui/1 [1.39 20201005-debian-12.1]
    org.graalvm.visualvm.lib.jfluid/2 [2.5 691217]
    org.graalvm.visualvm.lib.charts/2 [2.0 691217]
    org.graalvm.visualvm.lib.common/2 [2.2 691217]
    org.graalvm.visualvm.lib.profiler.api/2 [2.1 691217]
    org.graalvm.visualvm.lib.ui/2 [2.2 691217]
    org.graalvm.visualvm.uisupport/2 [2.0 691217]
    org.graalvm.visualvm.core/2 [2.2 691217]
    org.graalvm.visualvm.host/2 [2.0 691217]
    org.graalvm.visualvm.application/2 [2.0 691217]
    org.graalvm.visualvm.tools/2 [2.0 691217]
    org.graalvm.visualvm.coredump/2 [2.0 691217]
    org.graalvm.visualvm.threaddump/2 [2.0 691217]
    org.graalvm.visualvm.lib.profiler.utilities/2 [2.0 691217]
    org.graalvm.visualvm.lib.profiler.attach/2 [2.0 691217]
    org.graalvm.visualvm.lib.profiler/2 [2.2 691217]
    org.graalvm.visualvm.lib.profiler.snaptracer/2 [2.0 691217]
    org.graalvm.visualvm.profiling/2 [2.2 691217]
    org.graalvm.visualvm.lib.profiler.oql/2 [2.0 691217]
    org.graalvm.visualvm.lib.profiler.heapwalker/2 [2.0 691217]
    org.graalvm.visualvm.heapviewer/2 [2.3 691217]
    org.graalvm.visualvm.heapdump/2 [2.0 691217]
    org.graalvm.visualvm.sampler.truffle/2 [2.0 691217]
    org.graalvm.visualvm.sampler/2 [2.0 691217]
    org.graalvm.visualvm.sa/2 [2.0 691217]
    org.graalvm.visualvm.modules.startup/2 [2.1 691217]
    org.graalvm.visualvm.profiler/2 [2.0 691217]
    org.graalvm.visualvm.charts/2 [2.0 691217]
    org.graalvm.visualvm.application.views/2 [2.0 691217]
    org.graalvm.visualvm.modules.graalvm/2 [2.0 691217]
    org.graalvm.visualvm.modules.appui/2 [2.1 691217]
    org.graalvm.visualvm.jvmstat/2 [2.0 691217]
    org.graalvm.visualvm.jvm/2 [2.0 691217]
    org.graalvm.visualvm.jmx/2 [2.1 691217]
    org.graalvm.visualvm.jfr/2 [2.1 691217]
    org.graalvm.visualvm.host.views/2 [2.0 691217]
    org.graalvm.visualvm.host.remote/2 [2.0 691217]
    org.graalvm.visualvm.heapviewer.truffle/2 [2.0 691217]
    org.graalvm.visualvm.heapviewer.console/2 [2.0 691217]
    org.graalvm.visualvm.attach/2 [2.0 691217]
INFO [org.netbeans.core.network.proxy.NetworkProxyReloader]: System network proxy resolver: no suitable found, using fallback.
INFO [org.netbeans.core.network.proxy.fallback.FallbackNetworkProxy]: Fallback system proxy resolver: no http_proxy variable found
INFO [org.netbeans.core.network.proxy.NetworkProxyReloader]: System network proxy reloading succeeded.
INFO [org.netbeans.core.network.proxy.NetworkProxyReloader]: System network proxy - mode: direct
INFO [org.netbeans.core.network.proxy.NetworkProxyReloader]: System network proxy: fell to default (correct if direct mode went before)
INFO [org.netbeans.ui.metrics.laf]: USG_LOOK_AND_FEEL
Exception "java.lang.ClassNotFoundException: com/intellij/codeInsight/editorActions/FoldingData"while constructing DataFlavor for: application/x-java-jvm-local-objectref; class=com.intellij.codeInsight.editorActions.FoldingData
INFO [null]: Last record repeated again.
Exception "java.lang.ClassNotFoundException: com/intellij/codeInsight/editorActions/ReferenceData"while constructing DataFlavor for: application/x-java-jvm-local-objectref; class=com.intellij.codeInsight.editorActions.ReferenceData
INFO [null]: Last record repeated again.
Diagnostic information
Input arguments:
    -Djdk.home=/usr/lib/jvm/java-11-openjdk-amd64
    -Dnetbeans.default_userdir_root=/home/pavel/.visualvm
    -Dnetbeans.dirs=/usr/share/visualvm/visualvm:
    -Dnetbeans.home=/usr/share/visualvm/platform
    -Xms24m
    -Xmx768m
    -Dnetbeans.accept_license_class=org.graalvm.visualvm.modules.startup.AcceptLicense
    -Dnetbeans.importclass=org.graalvm.visualvm.modules.startup.ImportSettings
    -Dsun.jvmstat.perdata.syncWaitMs=10000
    -Dsun.java2d.noddraw=true
    -Dsun.java2d.d3d=false
    -Dorg.netbeans.core.TimeableEventQueue.quantum=360000
    -Dpolyglot.js.nashorn-compat=true
    -Dsun.misc.URLClassPath.disableJarChecking=true
    --add-exports=java.desktop/sun.awt=ALL-UNNAMED
    --add-exports=jdk.internal.jvmstat/sun.jvmstat.monitor.event=ALL-UNNAMED
    --add-exports=jdk.internal.jvmstat/sun.jvmstat.monitor=ALL-UNNAMED
    --add-exports=java.desktop/sun.swing=ALL-UNNAMED
    --add-exports=jdk.attach/sun.tools.attach=ALL-UNNAMED
    --add-opens=java.base/java.net=ALL-UNNAMED
    --add-opens=java.base/java.lang.ref=ALL-UNNAMED
    --add-opens=java.base/java.lang=ALL-UNNAMED
    --add-opens=java.desktop/javax.swing=ALL-UNNAMED
    --add-opens=java.desktop/javax.swing.plaf.basic=ALL-UNNAMED
    -XX:+IgnoreUnrecognizedVMOptions
    -XX:+HeapDumpOnOutOfMemoryError
    -XX:HeapDumpPath=/home/pavel/.visualvm/2.0.6/var/log/heapdump.hprof
Compiler: HotSpot 64-Bit Tiered Compilers
Heap memory usage: initial 24.0MB maximum 768.0MB
Non heap memory usage: initial 7.3MB maximum -1b
Garbage collector: G1 Young Generation (Collections=19 Total time spent=0s)
Garbage collector: G1 Old Generation (Collections=0 Total time spent=0s)
Classes: loaded=6870 total loaded=6879 unloaded 9
INFO [org.netbeans.core.ui.warmup.DiagnosticTask]: Total memory 67,410,419,712
INFO [null]: Total physical memory 67,410,419,712
WARNING [org.openide.filesystems.Ordering]: Found same position 1,500 for both VisualVM/ExplorerPopupSelection/org-graalvm-visualvm-application-RemoveFinishedApplicationsAction-selectionAware.instance and VisualVM/ExplorerPopupSelection/org-graalvm-visualvm-application-snapshot-ApplicationSnapshotAction.shadow
INFO [org.netbeans.modules.autoupdate.updateprovider.AutoupdateCatalogParser]: Unpaired license 36ED1425 without any module.
WARNING [org.netbeans.modules.keyring.fallback.MasterPasswordEncryption]: Falling back to master password encryption; add -J-Dorg.netbeans.modules.keyring.level=0 to netbeans.conf to see why native keyrings could not be loaded
thurka commented 3 years ago

Thanks for the report. It would be great if you can come up with the steps how to reproduce this problem. There are some strange things in the log file - it looks like this is not official VisualVM 2.0.6 build from visualvm.github.io. It would be great if you can use official build (just to be sure) and see if you can reproduce it.

pavlus commented 3 years ago

I couldn't reproduce it even with the same build.

Here is a list of patches used to build this version: https://sources.debian.org/patches/visualvm/2.0.6+dfsg-1/