CPU Profiling with (j)visualvm

[Marc van Dongen]

Dear all,


I've been trying to get CPU profiling with (j)visualvm working but for
some reason it doesn't profile my own methods.

When opening a java application I'm using the default settings: the
start profiling from classes box is empty and the profile new
runnables box is ticked. The java application is started from a jar
file.

Any help would be greatly appreciated.

(Please copy any replies to my email address.)

Thanks in advance for your help.

Regards,


Marc van Dongen

 

[John B. Matthews]

I've been trying to get CPU profiling with (j)visualvm working but
for some reason it doesn't profile my own methods.

When opening a java application I'm using the default settings: the
start profiling from classes box is empty and the profile new
runnables box is ticked. The java application is started from a jar
file.

Any help would be greatly appreciated.

You'll see more options when running code that was compiled with debug
enabled. This fairly "busy" simulation uses the corresponding option in
the ant file's "compile" target:

<http://sites.google.com/site/drjohnbmatthews/kineticmodel>

[...]

 

[Marc van Dongen]

[ CPU profiling with visualvm doesn't work ]

You'll see more options when running code that was compiled with debug
enabled. This fairly "busy" simulation uses the corresponding option in
the ant file's "compile" target:

Thanks. I had already tried that and it doesn't work. For example, I
compile my sources with ant using

<target name="Conquer" depends="init" description="Compile Conquer
source">
<javac srcdir="src" destdir="build/classes"
source="1.5" target = "1.5"
debug="on"
/>
</target>

and

<target name="package" depends="compile" description="Generate JAR
file">
<jar destfile="dist/Conquer.jar" basedir="build/classes">
<manifest>
<attribute name="Main-Class" value="Conquer"/>
</manifest>
</jar>
</target>

I then profile the main application, which takes more than 50 seconds.
All visualvm sees is less than 1 second of CPU time worth of the time
spent by the methods java.lang.applicationShutdownHooks.run( ) and
java.io.Console$1$1.run().

Am I overlooking something?

Regards,


Marc van Dongen

 

[John B. Matthews]

[ CPU profiling with visualvm doesn't work ]

You'll see more options when running code that was compiled with
debug enabled. This fairly "busy" simulation uses the corresponding
option in the ant file's "compile" target:

Thanks. I had already tried that and it doesn't work. [...]

debug="on"

[...]
I then profile the main application, which takes more than 50 seconds.
All visualvm sees is less than 1 second of CPU time worth of the time
spent by the methods java.lang.applicationShutdownHooks.run( ) and
java.io.Console$1$1.run().

Am I overlooking something?

I don't know; I don't have your main application. When I run my main
application, I see the expected cpu profile results:

<http://sites.google.com/site/drjohnbmatthews/kineticmodel>
<http://i56.tinypic.com/fxz8eq.png>

What are you seeing?

If I run my main application via some parent process, e.g. an
application launcher or JWS, I see the cpu profile of the parent,
instead. Is that a possibility in your case?

 

[Marc van Dongen]

Hi John,

I don't know; I don't have your main application. When I run my main
application, I see the expected cpu profile results:

<http://sites.google.com/site/drjohnbmatthews/kineticmodel>
<http://i56.tinypic.com/fxz8eq.png>

What are you seeing?

Thanks. I'ts pretty much what I'm seeing:

<http://csweb.ucc.ie/~dongen/visualvm.png>

The java application here took tens of seconds.

If I run my main application via some parent process, e.g. an
application launcher or JWS, I see the cpu profile of the parent,
instead. Is that a possibility in your case?

I'm running visualvm from the command line.

Regards,


Marc van Dongen

 

[John B. Matthews]

Thanks. I'ts pretty much what I'm seeing:

<http://csweb.ucc.ie/~dongen/visualvm.png>

The java application here took tens of seconds.


I'm running visualvm from the command line.

Interesting. I'm guessing you would expect to be seeing entries such as
"edu.dongen.Conquer.myMethod()" etc. Is is possible that some classes
don't have debug data? I wonder if ant's debug="on" switch may need a
full build to touch everything.

In addition, it looks like you're try to profile application startup. Do
you have any way to run your code in NetBeans' profiler?

 

[Marc van Dongen]

Dear John,

Interesting. I'm guessing you would expect to be seeing entries such as
"edu.dongen.Conquer.myMethod()" etc. Is is possible that some classes
don't have debug data? I wonder if ant's debug="on" switch may need a
full build to touch everything.

Before debugging I remove all class files and the jar file. Then I
recompiled eveything.

In addition, it looks like you're try to profile application startup. Do
you have any way to run your code in NetBeans' profiler?

I used to use netbeans to debug the application and it worked fine.
However, I'm a command line man and I don't like having to use
netbeans just for profiing purposes. As soon as I found out visualvm
was also available as a command line tool, I wanted to try it.
Unfortunately, this still hasn't worked.

I just noticed that my visualvm has version 1.1, which is a tad low. I
tried to upgrade but the download site is under maintenance. As soon
as I've installed a more recent version I'll profile a simple
application with just an infinite for loop which kills itself after 60
seconds. I'll get back if I've more news.

Regards,


Marc van Dongen

 

[Marc van Dongen]

I just noticed that my visualvm has version 1.1, which is a tad low. I
tried to upgrade but the download site is under maintenance. As soon
as I've installed a more recent version I'll profile a simple
application with just an infinite for loop which kills itself after 60
seconds. I'll get back if I've more news.

OK. I've done all that, but to no avail. Below I'm attaching the
commands which I carried out so as to profile the java application.
The java application may be downloaded from <http://csweb.ucc.ie:/
~dongen/DebugMe.java>. I've also uploaded two screen captures of the
visualvm session: <http://csweb.ucc.ie:/~dongen/DebugMe1.png> and
<http://csweb.ucc.ie:/~dongen/DebugMe2.png>.

The following are the commands of the visualvm session (it starts with
env so you can see the environment context).

$ env
KDE_MULTIHEAD=false
SSH_AGENT_PID=1685
DM_CONTROL=/var/run/xdmctl
CVIMSYN=/home/dongen/.vim
GPG_AGENT_INFO=/tmp/gpg-SzdjUD/S.gpg-agent:1686:1
TERM=xterm
DESKTOP_STARTUP_ID=
SHELL=/bin/bash
XDG_SESSION_COOKIE=08c57665b518db53e96c701648b53e96-1298196523.409905-1078985881
XDM_MANAGED=method=classic
KONSOLE_DBUS_SERVICE=:
1.28
GTK2_RC_FILES=/etc/gtk-2.0/gtkrc:/home/dongen/.gtkrc-2.0:/home/
dongen/.gtkrc-2.0-kde4:/home/dongen/.kde/share/config/
gtkrc-2.0
GTK_RC_FILES=/etc/gtk/gtkrc:/home/dongen/.gtkrc::/home/dongen/.kde/
share/config/
gtkrc
GS_LIB=/home/
dongen/.fonts
WINDOWID=35651609
GTK_MODULES=canberra-gtk-
module
ANT_HOME=/usr/share/
ant
KDE_FULL_SESSION=true
BRANCH=/home/dongen/Programming/
Branch
USER=dongen
LD_LIBRARY_PATH=/usr/src/jet6.4-pro//lib/x86/
shared:
LS_COLORS=rs=0:di=01;34:ln=01;36:hl=44;37i=40;33:so=01;35:do=01;35:bd=40;33;01:cd=40;33;01r=40;31;01:su=37;41:sg=30;43:ca=30;41:tw=30;42w=34;42:st=37;44:ex=01;32:*.tar=01;31:*.tgz=01;31:*.arj=01;31:*.taz=01;31:*.lzh=01;31:*.lzma=01;31:*.zip=01;31:*.z=01;31:*.Z=01;31:*.dz=01;31:*.gz=01;31:*.bz2=01;31:*.bz=01;31:*.tbz2=01;31:*.tz=01;31:*.deb=01;31:*.rpm=01;31:*.jar=01;31:*.rar=01;31:*.ace=01;31:*.zoo=01;31:*.cpio=01;31:*.
7z=01;31:*.rz=01;31:*.jpg=01;35:*.jpeg=01;35:*.gif=01;35:*.bmp=01;35:*.pbm=01;35:*.pgm=01;35:*.ppm=01;35:*.tga=01;35:*.xbm=01;35:*.xpm=01;35:*.tif=01;35:*.tiff=01;35:*.png=01;35:*.svg=01;35:*.svgz=01;35:*.mng=01;35:*.pcx=01;35:*.mov=01;35:*.mpg=01;35:*.mpeg=01;35:*.m2v=01;35:*.mkv=01;35:*.ogm=01;35:*.mp4=01;35:*.m4v=01;35:*.mp4v=01;35:*.vob=01;35:*.qt=01;35:*.nuv=01;35:*.wmv=01;35:*..asf=01;35:*.rm=01;35:*.rmvb=01;35:*.flc=01;35:*.avi=01;35:*.fli=01;35:*.flv=01;35:*.gl=01;35:*.dl=01;35:*.xcf=01;35:*.xwd=01;35:*.yuv=01;35:*.axv=01;35:*.anx=01;35:*.ogv=01;35:*.ogx=01;35:*.aac=00;36:*.au=00;36:*.flac=00;36:*.mid=00;36:*.midi=00;36:*.mka=00;36:*.mp3=00;36:*.mpc=00;36:*.ogg=00;36:*.ra=00;36:*.wav=00;36:*.axa=00;36:*.oga=00;36:*.spx=00;36:*.xspf=00;36:
XML=/home/dongen/Programming/
XML
GS=gs
SSH_AUTH_SOCK=/tmp/ssh-CcTtCI1638/agent.
1638
SESSION_MANAGER=local/
/tmp/.ICE-unix/
1783,unix/
:/tmp/.ICE-unix/
1783
PATH=/usr/src/jet6.4-pro//bin:/home/dongen/bin/:/usr/local/texlive/
2010/bin/i386-linux:/home/dongen/bin:/usr/local/sbin:/usr/local/bin:/
usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/home/dongen/Programming/
Tool
DESKTOP_SESSION=default
LC_COLLATE=C
PWD=/home/dongen/NetBeansProjects/
Conquer
JAVA_HOME=/usr/local/JDK/
jdk1.6.0_21/
TEX=latex
KDE_SESSION_UID=1000
LANG=en_IE.UTF-8
TEXMFCONFIG=/home/dongen/LaTeX/texmf/2010/texmf-
config
PS1=\! hermitage \w\n
$
KONSOLE_DBUS_SESSION=/Sessions/
4
HISTCONTROL=ignoreboth
PS2=>
JEThome=/usr/src/jet6.4-
pro/
TEXINPUTS=.:/home/dongen/LaTeX/styles//:/home/dongen/LaTeX/mpost/
marc//:
COLORFGBG=0;15
HOME=/home/
dongen
SHLVL=1
LANGUAGE=
KDE_SESSION_VERSION=4
XCURSOR_THEME=oxy-
white
LOGNAME=dongen
CLASSPATH=:/usr/share/java/junit4.jar:.
XDG_DATA_DIRS=/usr/share:/usr/share:/usr/local/share
DBUS_SESSION_BUS_ADDRESS=unix:abstract=/tmp/dbus-
D5Dh16OaBO,guid=6266b3d4c666e95eaec94c3d4d60e82b
LESSOPEN=| /usr/bin/lesspipe %s
TEXMFVAR=/home/dongen/LaTeX/texmf/2010/texmf-var
WINDOWPATH=7
PROFILEHOME=
DISPLAY=:0
TEXMFHOME=/home/dongen/LaTeX/texmf
QT_PLUGIN_PATH=/home/dongen/.kde/lib/kde4/plugins/:/usr/lib/kde4/
plugins/
TEXMFMAIN=/usr/local/texlive/2010/texmf/
LESSCLOSE=/usr/bin/lesspipe %s %s
_=/usr/bin/env
OLDPWD=/home/dongen

$ visualvm &
[1] 2588
$ javac -g DebugMe.java

$ java DebugMe
Profiler Agent: JNI On Load Initializing...
Profiler Agent: JNI OnLoad Initialized successfully
Profiler Agent: Waiting for connection on port 5140 (Protocol version:
10)
Profiler Agent: Established connection with the tool
Profiler Agent: Local accelerated session
Profiler Agent: Connection with agent closed
Profiler Agent: Connection with agent closed
$

As you can see from the second screen capture, visualvm still doesn't
seem to recognise the user-defined java methods.

Any help/suggestions appreciated.

Yours getting desperate,


Marc van Dongen

 

[John B. Matthews]

[...]
Below I'm attaching the commands which I carried out so as to profile
the java application. The java application may be downloaded from
<http://csweb.ucc.ie:/~dongen/DebugMe.java>.
I've also uploaded two screen captures of the visualvm session:
<http://csweb.ucc.ie:/~dongen/DebugMe1.png> and
<http://csweb.ucc.ie:/~dongen/DebugMe2.png>.

I'm nonplussed. Running your example, I see no Logger invocations at all.

Using java.util.Timer as you did, I get the results below. In
particular, I see une, deux and trois invoked in the prescribed ratio
with reasonable self-times. I get comparable results with Ubuntu Linux.

<http://i52.tinypic.com/rlwcd5.png>

package news;

import java.util.*;

public final class DebugMe {

private static Timer timer = createTimer();
private static volatile int counter;

public static void main(String[] args) {
while (true) {
counter++;
}
}

private static Timer createTimer() {
timer = new Timer();
TimerTask task = new TimerTask() {

@Override
public void run() {
une();
deux(); deux();
trois(); trois(); trois();
}

public void une() { counter++; }
public void deux() { counter++; }
private void trois() { counter++; }
};
timer.schedule(task, 1000L, 1000L);
return timer;
}
}

$ jvisualvm &
[1] 54722
$ java -cp build/classes news.DebugMe
Profiler Agent: JNI On Load Initializing...
Profiler Agent: JNI OnLoad Initialized successfully
Profiler Agent: Waiting for connection on port 5140 (Protocol version: 9)
Profiler Agent: Established local connection with the tool
^CProfiler Agent: Connection with agent closed
Profiler Agent: Connection with agent closed

 

[Marc van Dongen]

I'm nonplussed. Running your example, I see no Logger invocations at all.

Using java.util.Timer as you did, I get the results below. In
particular, I see une, deux and trois invoked in the prescribed ratio
with reasonable self-times. I get comparable results with Ubuntu Linux.

<http://i52.tinypic.com/rlwcd5.png>

[ snip ]

Thanks for your time John. Much appreciated.

I think it's time for me to throw in the towel.

Regards,


Marc van Dongen

 

[Marc van Dongen]

Hi John,

I think it's time for me to throw in the towel.

Just when I was about to grab my towel I noticed that your java class
has a package statement. When I add a package statement to my DebugMe
class, profiling does seem to work. Without the import statement it
doesn't.

Nice one.

Regards,


Marc van Dongen

 

[Lew]

Hi John,


Just when I was about to grab my towel I noticed that your java class
has a package statement. When I add a package statement to my DebugMe
class, profiling does seem to work. Without the import statement it
doesn't.

You confused me. Package directives and import directives are different things.

 

[Marc van Dongen]

You confused me.  Package directives and import directives are different things.

I congratulate you (you surely got met there) and nominate you for the
title of [_flll in_] for the year. Well done: this has been the most
constructive posting in this thread....

Regards,


Marc van Dongen

 

[Lew]

Just when I was about to grab my towel I noticed that your java [sic] class
has a package statement. When I add a package statement to my DebugMe
class, profiling does seem to work. Without the import statement it
doesn't.

You confused me. Package directives and import directives are different things.

I congratulate you (you surely got met there) and nominate you for the
title of [_flll in_] for the year. Well done: this has been the most
constructive posting in this thread....

Instead of being snarky, how about you clarify the matter? I don't know why
you feel the need to be mean about it.

Are you always this helpful to people?

Meanwhile, I still have no idea what you did to fix your problem.

 

[John B. Matthews]

Just when I was about to grab my towel I noticed that your java
[sic] class has a package statement. When I add a package
statement to my DebugMe class, profiling does seem to work.
Without the import statement it doesn't.

You confused me. Package directives and import directives are
different things.

I congratulate you (you surely got met there) and nominate you for the
title of [_flll in_] for the year. Well done: this has been the most
constructive posting in this thread....

Instead of being snarky, how about you clarify the matter? I don't
know why you feel the need to be mean about it.

Are you always this helpful to people?

Meanwhile, I still have no idea what you did to fix your problem.[/QUOTE]

I found Lew's question incisive. I get mixed results profiling an
application in the default package. Using this example on my platform,
just some (but not all) methods are profiled:

<http://sites.google.com/site/drjohnbmatthews/buttons>

Using an explicit package is a strongly recommended practice. I didn't
realize that support for unnamed package is implementation specific,
which may explain the variance observed above.

<http://java.sun.com/docs/books/jls/third_edition/html/packages.html#103097>

 

[Marc van Dongen]

Just when I was about to grab my towel I noticed that your java [sic]class
has a package statement. When I add a package statement to my DebugMe
class, profiling does seem to work. Without the import statement it
doesn't.

You confused me.  Package directives and import directives are different things.

I congratulate you (you surely got met there) and nominate you for the
title of [_flll in_] for the year. Well done: this has been the most
constructive posting in this thread....

Instead of being snarky, how about you clarify the matter?  I don't know why
you feel the need to be mean about it.

I am sorry. I misinterpreted your comment.

Are you always this helpful to people?

I am not sure if I understand what being helpful has got to do with
this. You didn't ask for help or an answer....

Meanwhile, I still have no idea what you did to fix your problem.

I thought I had explained this. The only difference is that I added a
package statement at the top of the DebugMe class which I mentioned in
a previous post.

Regards,


Marc van Dongen

 

[Marc van Dongen]

I found Lew's question incisive. I get mixed results profiling an
application in the default package. Using this example on my platform,
just some (but not all) methods are profiled:

<http://sites.google.com/site/drjohnbmatthews/buttons>

Thanks. I also finding that for my main application not all methods
are profiled. This really is very annoying especially because visualvm
doesn't seem to be capable of saving previously specified package
names (the ones that should be profiled).

Do you know if there's a way to configure visualvm in terms of the
packages which it should profile? (I think I've read all the relevant
online documentation (several times) but I have to admit that I prefer
reading a printed manual.)

Using an explicit package is a strongly recommended practice. I didn't
realize that support for unnamed package is implementation specific,
which may explain the variance observed above.

<http://java.sun.com/docs/books/jls/third_edition/html/packages.html#1...>

Thanks. My main application --- the one which made me start this
thread --- is built using several user-defined packages. Since it
didn't make sense to me to write just one package for one main
application, I didn't bother putting the application in a package. Boy
was I punished for that. It has taken me weeks between starting with
(command-line) visualvm and getting some profiling results.
Interestingly, profiling with netbeans _without_ packages has always
worked for me (but I don't want to use netbeans).

Regards,


Marc van Dongen

 

[Lew]

Thanks. My main application --- the one which made me start this
thread --- is built using several user-defined packages. Since it
didn't make sense to me to write just one package for one main
application, I didn't bother putting the application in a package. Boy
was I punished for that. It has taken me weeks between starting with
(command-line) visualvm [sic] and getting some profiling results.
Interestingly, profiling with netbeans [sic] _without_ packages has always
worked for me (but I don't want to use netbeans [sic]).

No less than the JLS itself tells us, right up in the first part of chapter
7: "For small programs and casual development, a package can be unnamed
(§7.4.2) or have a simple name, but if code is to be widely distributed,
unique package names should be chosen (§7.7)."

If the JLS calls something out like that, one knows /a priori/ that it's
perilous to ignore.

The section John linked goes into even more detail.

One learns this particular advice early on in Java training. The basic Java
tutorial, "Learning the Java Language", in its chapter on packages tells us,
"Generally speaking, an unnamed package is only for small or temporary
applications or when you are just beginning the development process.
Otherwise, classes and interfaces belong in named packages."
http://download.oracle.com/javase/tutorial/java/package/createpkgs.html

 

[Lew]

Just when I was about to grab my towel I noticed that your java [sic] class
has a package statement. When I add a package statement to my DebugMe
class, profiling does seem to work. Without the import statement it
doesn't.

You confused me. Package directives and import directives are different things.

I congratulate you (you surely got met there) and nominate you for the
title of [_flll in_] for the year. Well done: this has been the most
constructive posting in this thread....

Instead of being snarky, how about you clarify the matter? I don't know why
you feel the need to be mean about it.

I am sorry. I misinterpreted your comment.

Are you always this helpful to people?

I am not sure if I understand what being helpful has got to do with
this. You didn't ask for help or an answer....

I said I was confused. If that isn't a cry for help, what is?

I thought I had explained this. The only difference is that I added a
package statement at the top of the DebugMe class which I mentioned in
a previous post.

You said "Without the import statement it doesn't [work]." I didn't know
which you meant.

 

[John B. Matthews]

Do you know if there's a way to configure visualvm in terms of the
packages which it should profile? (I think I've read all the relevant
online documentation (several times) but I have to admit that I prefer
reading a printed manual.)

Not that I can see. The man page says you can pass options to the JVM using -J:

<http://www.manpagez.com/man/1/jvisualvm/>

My vendor's startup uses the option and looks something like this:

$ ps -efwww | grep -i visualvm
501 63869 63842 0 0:00.03 ttys000 0:00.05
sh /System/Library/Java/Support/VisualVM.bundle/Contents/Home/bin/...
--jdkhome /System/Library/Frameworks/JavaVM.framework/Versions/1.6/Home
-J-Dcom.apple.mrj.application.apple.menu.about.name=Java VisualVM
-J-Xdock:name=Java VisualVM
-J-Xdock:icon=/System/Library/Java/Support/VisualVM.bundle/Contents/Home/bin/...
....
-J-Xms24m -J-Xmx192m
-J-Dsun.jvmstat.perdata.syncWaitMs=10000