[#BTRACE-1] BTrace VisualVM 0.2.1 Plugin does not trace at all with Apple VisualVM or Sun VisualVM 1.1.1 - Kenai.com JIRA

btrace

BTrace VisualVM 0.2.1 Plugin does not trace at all with Apple VisualVM or Sun VisualVM 1.1.1

Created: 14/Jul/09 07:24 AM Updated: 21/Jul/09 04:21 AM Due: 31/Jul/09 Resolved: 16/Jul/09 02:55 PM

Component/s:

VisualVM Plugin

Affects Version/s:

release-1.0, release-1.0.1, release-1.0.2

Fix Version/s:

None

Time Tracking:

Original Estimate:

Not Specified

Remaining Estimate:

0 minutes

Time Spent:

1 hour

File Attachments:

VisualVM.mov (7.08 MB) 16/Jul/09 02:27 PM - MatthewMcCullough

Image Attachments:

1. Picture 6.png
(171 kB)

Environment:

« Hide

MacOS X

Tags:

mac

Description

« Hide

I have btrace working wonderfully from the command line on Mac with version
1.0.

However, I am still failing using it's plugin variant inside VisualVM on the
Mac (works great on Windows).

When I attempt to trace (using the simplest of memory monitor samples) via the
VisualVM BTrace 0.2.1 plugin, it just hangs (no errors in Console.app nor in
the terminal that I launched it from, etc).

Steps to reproduce:
1) Open VisualVM that is distributed with Mac OSX Java Update 4, or Visual VM
1.1.1 from the Java.net web site.
2) Code a hello world (looping) java app. Start it running.

package com.ambientideas;

public class HelloWorldJava {
public static void main(String[] args) throws Exception { new HelloWorldJava().run(); }

public void run() throws Exception {
while (true) { print(); }
}

public void print() throws Exception { System.out.println("Hello Java World!"); new java.util.ArrayList(1000); Thread.sleep(1000); }
}

3) Right click on the process in VisualVM and choose "trace application..."
4) In the Tracing plugin window, paste the following simple script:

package com.sun.btrace.samples;
import com.sun.btrace.annotations.*;
import static com.sun.btrace.BTraceUtils.*;
@BTrace public class MemoryTracerBTraceScript {
@OnTimer(4000)
public static void printMem() { println("Heap:"); println(heapUsage()); println("Non-Heap:"); println(nonHeapUsage()); }
}

5) The VisualVM window says in the status tray area "Starting BTrace task"
6) It never returns from this status and continually leaves the status message
even after leaving it for 10 minutes.

Matthew McCullough
Ambient Ideas, LLC
matthewm@ambientideas.com

Sort Order:

[ Permalink | « Hide ]

yardus added a comment - 14/Jul/09 07:25 AM

BTrace locked-up in VisualVM

[ Permalink | « Hide ]

yardus added a comment - 14/Jul/09 07:29 AM

It seemed to be just a UI issue. However, after clicking "Start" button again (as recommended by me) Matthew still experiences the problem:
===============================================================
Though I can get further if I click the START button a second time, and I get
some DEBUG: outputs from btrace in the console window where I was running the
HelloWorldJava class, I still get no btracing output.

Example from visualvm:

Hello Java World!
DEBUG: attaching to 3084
DEBUG: attached to 3084
DEBUG: loading /Users/mccm06/Library/Application
Support/visualvm/6u11/modules/ext/btrace-agent.jar
DEBUG: agent args:
port=51673,debug=true,dumpClasses=true,dumpDir=/Users/mccm06/Documents/Temp/Scratch,systemClassPath=/System/Library/Frameworks/JavaVM.framework/Versions/1.6.0/Home/lib/tools.jar,probeDescPath=.
Hello Java World!
Hello Java World!
Hello Java World!
DEBUG: loaded /Users/mccm06/Library/Application
Support/visualvm/6u11/modules/ext/btrace-agent.jar
DEBUG: opening socket to 51673
Hello Java World!
Hello Java World!
Hello Java World!

Whereas if I run the same trace script via the command line, I get:

Hello Java World!
DEBUG: btrace debug mode is set
DEBUG: btrace unsafe mode is set
DEBUG: dumpClasses flag is set
DEBUG: assuming default port 2020
DEBUG: assuming default classpath '.'
DEBUG: compiling TraceAllMethodCalls.java
Hello Java World!
DEBUG: compiled TraceAllMethodCalls.java
DEBUG: attaching to 3223
DEBUG: attached to 3223
DEBUG: loading /Applications/Dev/btrace/build/btrace-agent.jar
MATTHEW
java.class.path=/Applications/Dev/btrace/build/btrace-client.jar:/Applications/Dev/btrace/build/btrace-asm-3.1.jar:/System/Library/Frameworks/JavaVM.framework/Versions/1.6/Classes/classes.jar:/usr/share/lib/java/dtrace.jar
DEBUG: agent args:
port=2020,debug=true,systemClassPath=/System/Library/Frameworks/JavaVM.framework/Versions/1.6/Classes/classes.jar,probeDescPath=.
Hello Java World!
Hello Java World!
Hello Java World!
btrace DEBUG: debugMode is true
btrace DEBUG: unsafeMode is false
btrace DEBUG: dumpClasses is false
btrace DEBUG: probe descriptor path is .
btrace DEBUG: parsed command line arguments
btrace DEBUG: System ClassPath:
/System/Library/Frameworks/JavaVM.framework/Versions/1.6/Classes/classes.jar
btrace DEBUG: starting agent thread
btrace DEBUG: starting server at 2020DEBUG: loaded
/Applications/Dev/btrace/build/btrace-agent.jar

DEBUG: registering shutdown hook
DEBUG: submitting the BTrace program
btrace DEBUG: waiting for clients
DEBUG: opening socket to 2020
btrace DEBUG: client accepted Socket[addr=/127.0.0.1,port=51689,localport=2020]
DEBUG: sending instrument command
DEBUG: entering into command loop
btrace DEBUG: got instrument command
btrace DEBUG: verifying BTrace class
btrace DEBUG: verified 'TraceAllMethodCalls' successfully
btrace DEBUG: created class filter
btrace DEBUG: preprocessing BTrace class TraceAllMethodCalls
btrace DEBUG: preprocessed BTrace class TraceAllMethodCalls
btrace DEBUG: creating BTraceRuntime instance for TraceAllMethodCalls
btrace DEBUG: created BTraceRuntime instance for TraceAllMethodCalls
btrace DEBUG: removing @OnMethod, @OnProbe methods
btrace DEBUG: removed @OnMethod, @OnProbe methods
btrace DEBUG: sending Okay command
btrace DEBUG: client TraceAllMethodCalls: got
com.sun.btrace.comm.OkayCommand@63cd66ea
btrace DEBUG: about to defineClass TraceAllMethodCalls
DEBUG: received com.sun.btrace.comm.OkayCommand@534cbc58
btrace DEBUG: defineClass succeeded for TraceAllMethodCalls
btrace DEBUG: starting client command handler thread
btrace DEBUG: new Client created com.sun.btrace.agent.RemoteClient@62402af3
btrace DEBUG: filtering loaded classes
btrace DEBUG: candidate class java.lang.ClassNotFoundException added
btrace DEBUG: candidate class sun.security.provider.NativePRNG$RandomIO added
btrace DEBUG: candidate class sun.security.util.ManifestDigester added
SNIP
btrace DEBUG: candidate class sun.misc.Launcher$ExtClassLoader$1 added
btrace DEBUG: candidate class java.util.regex.Pattern$Node added
btrace DEBUG: candidate class java.util.zip.InflaterInputStream added
SNIP
btrace DEBUG: client TraceAllMethodCalls: instrumenting
java/lang/StringCoding$StringDecoder
btrace DEBUG: client TraceAllMethodCalls: instrumenting
java/util/concurrent/TimeUnit$2
btrace DEBUG: skipping transform for BTrace class sun/reflect/ConstantPool
btrace DEBUG: client TraceAllMethodCalls: instrumenting java/lang/System$2
btrace DEBUG: client TraceAllMethodCalls: instrumenting java/lang/Double
btrace DEBUG: client TraceAllMethodCalls: instrumenting
sun/text/normalizer/ICUBinary
btrace DEBUG: client TraceAllMethodCalls: instrumenting
java/util/Collections$UnmodifiableRandomAccessList
SNIP
DEBUG: received com.sun.btrace.comm.MessageCommand@3b59d796

- - - - WE'VE ENTERED METHOD: println
        DEBUG: received com.sun.btrace.comm.MessageCommand@758d74b
        
        WE'VE ENTERED A METHOD ON CLASS: com.ambientideas.HelloWorldJava
        DEBUG: received com.sun.btrace.comm.MessageCommand@599e80b1
        
        WE'VE ENTERED METHOD: print
        btrace DEBUG: client TraceAllMethodCalls: got
        com.sun.btrace.comm.MessageCommand@78c62333
        DEBUG: received com.sun.btrace.comm.MessageCommand@3513126e
        
        WE'VE ENTERED A METHOD ON CLASS: com.ambientideas.HelloWorldJava
        Hello Java World!

So this is not a UI-only issue and I'm getting no error flags to tell me where
to hunt down the cause. This is reproducible now on all the four Mac machines
I have access to use. It does not occur for me on Windows, ever. It works
flawlessly without the double click on the start button.

[ Permalink | « Hide ]

yardus added a comment - 14/Jul/09 07:33 AM

Will look closer at this issue - but I will need help from guys owning Mac cause I am no Mac user

[ Permalink | « Hide ]

MatthewMcCullough added a comment - 14/Jul/09 02:11 PM

Will be happy to test it again, or do any type of debug runs. Though you instructed me how to turn on all the debugging output on the command line version of btrace (which is working great for me!) I don't know how to turn on any debug information for visualvm. Let me know and we can add more detail to this easily reproducible bug.

[ Permalink | « Hide ]

jbachorik added a comment - 16/Jul/09 12:55 PM

The problem was that the plugin tried to connect to the target VM while the agent not being initialized completely. The plugin failed silently and corrupted the rest of the UI (never-ending progressbar etc.).

The fix is available in http://kenai.com/projects/btrace/sources/visualvm-plugin/revision/7
The plugin version was bumped to 0.2.2

Also, logging was added that can be activated by adding -J-Dnet.java.btrace.visualvm.level=FINEST as a parameter when launching visualvm.

[ Permalink | « Hide ]

MatthewMcCullough added a comment - 16/Jul/09 02:25 PM

Thank you for such quick work on this. I've tested the latest 0.2.2 plugin and I get different behavior, but it still doesn't trace. I've made a video so you can see everything that is going on. I used the -J-Dnet.java.btrace.visualvm.level=FINEST option, but I don't get any console output from Btrace.

Mac OS X 10.5.7
JDK 1.6.0_13 64 bit
Mac Java Update 4

Attaching video file.

[ Permalink | « Hide ]

MatthewMcCullough added a comment - 16/Jul/09 02:27 PM

This is a video of 0.2.2 still failing, but this time with no progress indicator on the VisualVM window (previously was getting stuck infinitely saying it was starting the tracing).

[ Permalink | « Hide ]

jbachorik added a comment - 16/Jul/09 02:30 PM

The log is available in VisualVM logfile (Help/About/Logfile...)

[ Permalink | « Hide ]

jbachorik added a comment - 16/Jul/09 02:37 PM

Could you try to uninstall and install the BTrace plugin? I had the same behavior in my development environment and I was able to fix it by simple uninstall/install. I thought it was because of my userdir polluted with a lot of testing stuff so I wasn't bothered by that too much

Could you verify that this trick would work for you?

[ Permalink | « Hide ]

MatthewMcCullough added a comment - 16/Jul/09 02:50 PM

The uninstall and reinstall did the trick. I had to do it on both the "Mac JDK" provided version of JVisualVM as well as my standalone downloaded VisualVM 1.1.1. The NFJS audience in Salt Lake City this weekend will love this! Thank you! And I'll have to tell my Austin NFJS crew from last weekend that it works now. I'll put up a blog post about it tonight or tomorrow at http://ambientideas.com/blog/

[ Permalink | « Hide ]

jbachorik added a comment - 16/Jul/09 02:55 PM

Great! Closing the issue

[ Permalink | « Hide ]

Jay Kaluza added a comment - 21/Jul/09 04:21 AM

thanks gentlemen! I have been typically been showing off the command-line tools on the mac for this reason. I'll be speaking at JavaZone in Oslo... they will get the treat of seeing it from the UI as well.