JBoss Profiler 2 in JBoss AS 4.2.2 - Does not gather any sta

[justinwalsh]

Hi,

I'm running JBoss profiler version 2 in JBoss 4.2.2. I have followed the instructions in the README.txt verbatim, but cannot get it to 'log' any method calls.

My setup is as follows:
- Windows XP machine
- Compiled JBoss Profiler version 2 from svn (at version 423) using the build file - resulted in dist dir from which all artefacts are taken
- Copied jboss-profiler.jar to JBOSS_HOME/bin
- Copied jboss-profiler.properties to JBOSS_HOME/bin
- Copied jboss-profiler-plugins.jar to JBOSS_HOME/bin
- Copied jboss-profiler.sar to JBOSS_HOME/server/default/deploy
- Edited run.bat to include the following line:
set JAVA_OPTS=%JAVA_OPTS% -javaagent:jboss-profiler.jar -Djboss-profiler.properties=jboss-profiler.properties


My jboss-profiler.properties file looks as follows:

core=javassist
enable=yes
cpu=yes
memory=yes
includes=com.sadalbari.demo.ejb3.*
excludes=*
visibility=private
save=yes
startup=yes
repository=no
remote=yes
store=memory
location=.
host=localhost
port=5400
ejb=yes
servlet=yes
jsf=yes
jmx=yes
rmi=yes
corba=yes
plugin.1=org.jboss.profiler.plugins.Hibernate

I then boot jboss. I notice the following lines on the console which indicate to me that I have configured 'correctly':

D:\servers\jboss\jboss-4.2.2.GA\bin>run -b 127.0.0.1
===============================================================================

 JBoss Bootstrap Environment

 JBOSS_HOME: D:\servers\jboss\jboss-4.2.2.GA

 JAVA: C:\dev\java\jdk1.5.0_14\bin\java

 JAVA_OPTS: -Xdebug -Xrunjdwp:transport=dt_socket,address=8787,server=y,suspend=n -Dprogram.name=run.bat -server -Dsun.rmi.dgc.c
lient.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 -Dewage.configuration-name=justin -Dorg.apache.tapestry.disable-c
aching=true -Xms64m -Xmx256m -XX:MaxPermSize=128m -javaagent:jboss-profiler.jar -Djboss-profiler.properties=jboss-profiler.propert
ies

 CLASSPATH: C:\dev\java\jdk1.5.0_14\lib\tools.jar;D:\servers\jboss\jboss-4.2.2.GA\bin\run.jar

===============================================================================

JBoss Profiler 2.0.CR9 (Sun Microsystems Inc. 1.5.0_14)
JBoss Profiler depends on external communication module
Listening for transport dt_socket at address: 8787
21:38:08,187 INFO [Server] Starting JBoss (MX MicroKernel)...
...
...

etc etc

There are no errors in my log file.

I also have a simple EJB3 session bean which I wish to profile, which starts up correctly. The bean implementation class is in the package com.sadalbari.demo.ejb3

I then invoke my bean a number of times from a test client. The bean creates 1000 instances of a POJO class, SomeClass (in the same package) during its invocation.

I then shutdown the server (shutdown.bat -S), at which point the server exits gracefully leaving my with a timestamped .jps file

I then run the command:
java -Xmx512m -Djboss-profiler-client.properties=jboss-profiler-client.properties -jar jboss-profiler-client.jar load <file-name>.jps
on the file, which produces a directory.

A directory with the timestamped name is created containing the files:
classes.txt
hotspots.txt
methods.txt
overview.txt

and two directories:
classes
threads

The classed directory contains 2 files:
com.sadalbari.demo.ejb3.EJB3SessionBean.txt
com.sadalbari.demo.ejb3.SomeClass.txt

None of these files contain any evidence of a method invocation/thread usage. For example, overview.txt:

From: 17 April 2008 21:38:07:875
To : 17 April 2008 21:44:02:812

Threads:
========

Most time:
==========
Count Ms % Method

Hotspots:
=========
Count Ms Avg % Method

Classes:
========
com.sadalbari.demo.ejb3.EJB3SessionBean EJB_SESSION 0.00 ms
com.sadalbari.demo.ejb3.SomeClass POJO 0.00 ms

com.sadalbari.demo.ejb3.SomeClass.txt is as follows:

com.sadalbari.demo.ejb3.SomeClass POJO
Total time: 0.00 ms
 Wait time: 0.00 ms

Methods:
========
Count Ms % (C) % (T) Method

Hotspots:
=========
Count Ms Avg % Method

I've done a bit of digging/messing and my feeling is that there is something wrong with the MANIFEST of the jboss-profiler.jar file.

This file contains the following entry (on one line)
Boot-Class-Path: jboss-profiler.jar jboss-profiler-connectors.jar jboss-profiler-plugins.jar asm.jar javassist.jar ../lib/javassist.jar jboss-remoting.jar jboss-common.jar concurrent.jar log4j.jar

o Very few of these jars are resolveable from the location in which the startup script is inited (JBOSS_HOME/bin).
o A number of them don't even exist in jboss (for example jboss-profiler-connectors.jar which _is_ part of the profiler build, but was not mentioned in any setup step)
o Why is asm.jar repeated?

I tried cleaning up as far as possible and pointing to the jars in the jboss installation. As I went along I got a number of NoClassDefFoundError exceptions, which I resolved by adding the jars to the Boot-Class-Path. For example, when I resolved the jboss-remoting.jar correctly (I actually just copied the jar to the bin directory), I got

Caused by: java.lang.NoClassDefFoundError: org/jboss/mx/util/JBossNotificationBroadcasterSupport
at org.jboss.remoting.network.NetworkRegistry.(NetworkRegistry.java:55)

Eventually I got to a point where I got a NPE in the JBoss boot sequence.

Has anybody got the profiler working properly with JBoss 4.2.2? Any help would be appreciated.

----
BTW - there is also an error in /JBossProfiler2/src/etc/jboss-service.xml:
false
is repeated twice, once with true, the second time with the value false

[justinwalsh]

Sorry - that last part was meant to read:
There is also an error in /JBossProfiler2/src/etc/jboss-service.xml:

<attribute name="Socket">false</attribute>

is repeated twice, once with the value true, and then with the value false.

[justinwalsh]

ok - I think I was on a wild good chase with the manifest, although I suspect it does need some tidying up.

Looking at the source for:
org.jboss.profiler.agent.Agent.redefine(Class[] clz, boolean instrument)

This method appears to the be part involved in instrumenting classes. I assume that without instrumentation, we cannot gather stats. Now the confusing part:

redefine is called from the same class at three points:
addClasses()
removeClasses()
setEnabled()

each of which is called from the handler.

I don't want to add and remove classes manually each time, so I'll concern myself with the enabled method call.

Take a look at the method:

public static void setEnabled(boolean e) {
if (isRepository()) {
 List<Class> l = new ArrayList<Class>();

 for (Class c : instrumentation.getAllLoadedClasses()) {
 String className = c.getName().replace(".", "/");

 boolean added = false;
 for (int i = 0; !added && i < includeList.size(); i++) {
 String classes = includeList.get(i);
 if (className.startsWith(classes)) {
 l.add(c);
 added = true;
 }
 }
 }

 Class[] clz = new Class[l.size()];
 for (int i = 0; i < l.size(); i++) {
 clz = l.get(i);
 }

 if (enabled) {
 redefine(clz, true);
 } else {
 redefine(clz, false);
 }
 }
 }

Code will never be instrumented if the repository is disabled (which is the default value)
No instrumentation = no stats.

So I do the following:
configure jboss.profiler.properties with:
core=asm (javaassist doesn't seem to work)
repository=yes

Then:
1) start the application server, and run through my test case. I need to do this to get the classes loaded by the classloader (is there a way to circumvent this?)
2) Using the jmx-console/socket client I enable the profiler. This causes the classes which are in the classloader to be reloaded.
3) I then run my test again.
4) stopProfiler
5) getSnapshot 1

voila

One big caveat - I had to change the logic in :
private static void redefine(Class[] clz, boolean instrument)
to handle exception on a per class basis so that if loading a class fails we don't bail out of the whole operation:

if (clz != null) {
 for (Class c : clz) {
 try {
 byte[] buffer = null;
 if (instrument) {
 buffer = transformer.loadInstrumented(c.getName(), c.getClassLoader());
 } else {
 buffer = transformer.loadNonInstrumented(c.getName(), c.getClassLoader());
 }

 if (buffer != null) {
 ClassDefinition cd = new ClassDefinition(c, buffer);
 l.add(cd);
 }
 }
 catch (Throwable t) {
 System.err.println("Failed to load [" + c.getName() + "]: " + t.getMessage());
 }
 }
 }

Has anyone else had a similar experience or can shed some light on the issues?

[justinwalsh]

I've found the issue.

The byte code enhancement library needs to be in the same directory jboss-profiler.jar (recommended directory is JBOSS_HOME/bin) otherwise the enhancement process fails silently.

[jesper.pedersen]

This have been fixed in the Beta1 release at http://www.jboss.org/jbossprofiler/downloads/.

It now logs a warning about the missing library.