3 Replies Latest reply on Dec 10, 2008 9:17 PM by jesper.pedersen

Profiler Not Recording Time

wstrater1 Dec 8, 2008 3:45 PM

I am having troubles getting output. I tried Beta3 and SVN revision 517.

I exported and built the code:

[webuser@bri-devweb01 tmp]$ svn export http://anonsvn.jboss.org/repos/jbossprofiler/branches/JBossProfiler2
[webuser@bri-devweb01 tmp]$ svn info http://anonsvn.jboss.org/repos/jbossprofiler/branches/JBossProfiler2
Path: JBossProfiler2
URL: http://anonsvn.jboss.org/repos/jbossprofiler/branches/JBossProfiler2
Repository Root: http://anonsvn.jboss.org/repos/jbossprofiler
Repository UUID: 98652012-b443-0410-9899-d25f17a0cfe6
Revision: 517
Node Kind: directory
Last Changed Author: jesper.pedersen
Last Changed Rev: 517
Last Changed Date: 2008-12-04 20:55:20 -0500 (Thu, 04 Dec 2008)

I copied the jars and properties to the bin directory:

[webuser@bri-devweb01 jboss-profiler]$ ls -l /usr/local/jboss/bin/jboss-profiler*
-rw-r--r-- 1 webuser webuser 61650 Dec 5 14:19 /usr/local/jboss/bin/jboss-profiler.jar
-rw-r--r-- 1 webuser webuser 5125 Dec 5 14:19 /usr/local/jboss/bin/jboss-profiler-plugins.jar
-rw-r--r-- 1 webuser webuser 486 Dec 8 10:47 /usr/local/jboss/bin/jboss-profiler.properties
[webuser@bri-devweb01 jboss-profiler]$ ls -l /usr/local/jboss/bin/javas*
-rw-r--r-- 1 webuser webuser 471005 Dec 8 09:51 /usr/local/jboss/bin/javassist.jar
[tomcat@bri-devweb01 jboss-profiler]$ ls -l /usr/local/jboss/server/default/deploy/jboss-prof*
-rw-r--r-- 1 webuser webuser 11107 Dec 5 14:25 /usr/local/jboss/server/default/deploy/jboss-profiler.sar
[webuser@bri-devweb01 jboss-profiler]$ cat /usr/local/jboss/bin/jboss-profiler.properties
enable=yes
cpu=yes
memory=yes
includes=com.company.*
excludes=*
visibility=private
save=yes
startup=yes
repository=no
remote=yes
store=memory
location=/home2/weblogs/profiler
host=localhost
port=5400
ejb=no
servlet=yes
jsf=no
jmx=no
rmi=yes
corba=no
plugin.1=org.jboss.profiler.plugins.Hibernate
plugin.2=org.jboss.profiler.plugins.Seam
[webuser@bri-devweb01 jboss-profiler]$

I update the run.conf.

[webuser@bri-devweb01 jboss-profiler]$ grep PROFILE /usr/local/jboss/bin/run.conf
PROFILER="/usr/local/jboss/bin/jboss-profiler.properties"

The following is from the console log upon startup. You can see the profiler is configured as an agent in the JAVA_OPTS.

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

JBoss Bootstrap Environment

JBOSS_HOME: /usr/local/jboss

JAVA: /usr/local/java/bin/java

JAVA_OPTS: -Dprogram.name=run.sh -server -javaagent:/usr/local/jboss/bin/jboss-profiler.jar -Djboss-profiler.properties=/usr/local/jboss/bin/jboss-profiler.properties -Dcom.sun.management.jmxremote.port=9004 -Djava.net.preferIPv4Stack=true

CLASSPATH: /usr/local/jboss/bin/run.jar:/usr/local/java/lib/tools.jar

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

JBOSS_HOME: /usr/local/jboss
JBoss Profiler 2.0.Beta4 (Sun Microsystems Inc. 1.5.0_03)
JBoss Profiler depends on external communication module
11:30:29,143 INFO [Server] Starting JBoss (MX MicroKernel)...
11:30:29,144 INFO [Server] Release ID: JBoss [Trinity] 4.2.3.GA (build: SVNTag=JBoss_4_2_3_GA date=200807181417)
11:30:29,146 INFO [Server] Home Dir: /usr/local/jboss-4.2.3.GA
11:30:29,146 INFO [Server] Home URL: file:/usr/local/jboss-4.2.3.GA/
11:30:29,147 INFO [Server] Patch URL: null
11:30:29,147 INFO [Server] Server Name: default
11:30:29,147 INFO [Server] Server Home Dir: /usr/local/jboss-4.2.3.GA/server/default
11:30:29,148 INFO [Server] Server Home URL: file:/usr/local/jboss-4.2.3.GA/server/default/
11:30:29,148 INFO [Server] Server Log Dir: /usr/local/jboss-4.2.3.GA/server/default/log
11:30:29,148 INFO [Server] Server Temp Dir: /usr/local/jboss-4.2.3.GA/server/default/tmp
11:30:29,148 INFO [Server] Root Deployment Filename: jboss-service.xml
11:30:29,564 INFO [ServerInfo] Java version: 1.5.0_03,Sun Microsystems Inc.
11:30:29,564 INFO [ServerInfo] Java VM: Java HotSpot(TM) Server VM 1.5.0_03-b07,Sun Microsystems Inc.
11:30:29,565 INFO [ServerInfo] OS-System: Linux 2.4.21-57.ELsmp,i386

It should be noted that /usr/local/jboss and /usr/local/jboss-profile are symbolic links to /usr/local/jboss-4.2.3.GA and /usr/local/jboss-profiler-2.0.svn-517.

The following are the entries in the JBoss console output.

[webuser@bri-devweb01 jboss-profiler]$ grep Profiler /home2/weblogs/jboss_console.log
JBoss Profiler 2.0.Beta4 (Sun Microsystems Inc. 1.5.0_03)
JBoss Profiler depends on external communication module
11:30:39,218 INFO [Profiler] JBoss Profiler: ProfilerMBean started
11:30:39,219 INFO [Communicator] JBoss Profiler: Communicator for JBoss Profiler 2.0.Beta4
11:30:39,228 INFO [Communicator] JBoss Profiler: Socket=0.0.0.0:5400

The following from the JBoss server log.

[webuser@bri-devweb01 jboss-profiler]$ grep Profiler /home2/weblogs/jboss_server.log
[webuser@bri-devweb01 jboss-profiler]$

I ran the following client commands. (The last grep is the opposite of the previous to confirm the pattern.)

[webuser@bri-devweb01 jboss-profiler]$ java -jar jboss-profiler-client.jar list
com.company.*
org.apache.jsp.*
[webuser@bri-devweb01 jboss-profiler]$ java -jar jboss-profiler-client.jar startProfiler
[webuser@bri-devweb01 jboss-profiler]$ java -jar jboss-profiler-client.jar stopProfiler
[webuser@bri-devweb01 jboss-profiler]$ java -jar jboss-profiler-client.jar listSnapshots
1: 08 December 2008 11:31:33:778 -> 08 December 2008 11:32:27:890
[webuser@bri-devweb01 jboss-profiler]$ java -jar jboss-profiler-client.jar getSnapshot 1
[webuser@bri-devweb01 jboss-profiler]$ ls -l 20081208113133778-20081208113227890
total 1224
drwxrwxr-x 2 webuser webuser 4096 Dec 8 11:32 caller
drwxrwxr-x 2 webuser webuser 405504 Dec 8 11:32 classes
-rw-rw-r-- 1 webuser webuser 404426 Dec 8 11:32 classes.txt
-rw-rw-r-- 1 webuser webuser 42 Dec 8 11:32 hotspots.txt
-rw-rw-r-- 1 webuser webuser 40 Dec 8 11:32 methods.txt
-rw-rw-r-- 1 webuser webuser 404629 Dec 8 11:32 overview.txt
-rw-rw-r-- 1 webuser webuser 33 Dec 8 11:32 packages.txt
drwxrwxr-x 2 webuser webuser 4096 Dec 8 11:32 threads
-rw-rw-r-- 1 webuser webuser 49 Dec 8 11:32 waittime.txt
[webuser@bri-devweb01 jboss-profiler]$ grep -v '0.00 ms' 20081208113133778-20081208113227890/overview.txt
From : 08 December 2008 11:31:33:778
To : 08 December 2008 11:32:27:890

Total: 54112.00 ms

Threads:
========

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

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

Classes:
========
[webuser@bri-devweb01 jboss-profiler]$ grep '0.00 ms' 20081208113133778-20081208113227890/overview.txt | head
com.company.common.datastructures.Account POJO 0.00 ms
com.company.common.datastructures.Account$JaxbAccessorF_accountId POJO 0.00 ms
com.company.common.datastructures.Account$JaxbAccessorF_accountStatus POJO 0.00 ms
com.company.common.datastructures.Account$JaxbAccessorF_backendAccountIdentifier POJO 0.00 ms
com.company.common.datastructures.Account$JaxbAccessorF_backendAccountType POJO 0.00 ms
com.company.common.datastructures.Account$JaxbAccessorF_branchNumber POJO 0.00 ms
com.company.common.datastructures.Account$JaxbAccessorF_cards POJO 0.00 ms
com.company.common.datastructures.Account$JaxbAccessorF_employeeType POJO 0.00 ms
com.company.common.datastructures.AccountActionCode POJO 0.00 ms
com.company.common.datastructures.AccountId POJO 0.00 ms
[webuser@bri-devweb01 jboss-profiler]$ cat 20081208113133778-20081208113227890/methods.txt
Methods:
--------
Count Ms Avg % Method
[webuser@bri-devweb01 jboss-profiler]$

The location is empty but that is probably correct since I am using a memory store.

[webuser@bri-devweb01 jboss-profiler]$ ls -l /home2/weblogs/profiler
total 0

I use JMeter to run a test plan. You can see from the application log file that there was some activity with the classes that matches the includes entry. Also playing around with the includes does change the classes found in the snapshot report directory.

[webuser@bri-devweb01 jboss-profiler]$ grep '11:3' /home2/weblogs/jboss.log | grep commonLogic | grep EXECUTING
11:31:40,786 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 429] VERBOSE [ ] - ***** EXECUTING CLASS: com.company.servlets.Login
11:31:50,183 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 384] VERBOSE [ ] - ***** EXECUTING DISPATCHER: com.company.dispatchers.security.SecurityFSOCheckDispatcher
11:31:51,728 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 384] VERBOSE [ ] - ***** EXECUTING DISPATCHER: com.company.dispatchers.login.LoginPrepareLoginDispatcher
11:31:56,088 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 384] VERBOSE [ ] - ***** EXECUTING DISPATCHER: com.company.dispatchers.login.LoginSigninDispatcher
11:32:00,328 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 384] VERBOSE [ ] - ***** EXECUTING DISPATCHER: com.company.dispatchers.transaction.HistoryLandingDispatcher
11:32:01,563 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 384] VERBOSE [ ] - ***** EXECUTING DISPATCHER: com.company.dispatchers.transfer.TransferHistoryDispatcher
11:32:03,520 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 384] VERBOSE [ ] - ***** EXECUTING DISPATCHER: com.company.dispatchers.relatedservices.HistoryDispatcher
11:32:06,353 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 384] VERBOSE [ ] - ***** EXECUTING DISPATCHER: com.company.dispatchers.card.CardTransactionHistoryDispatcher
11:32:08,352 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 384] VERBOSE [ ] - ***** EXECUTING DISPATCHER: com.company.dispatchers.accounts.ReviewWebsterAccountsDispatcher
11:32:10,172 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 384] VERBOSE [ ] - ***** EXECUTING DISPATCHER: com.company.dispatchers.accountbalances.AccountBalanceDispatcher
11:32:12,138 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 429] VERBOSE [ ] - ***** EXECUTING CLASS: com.company.servlets.Login
11:32:12,210 [ajp-0.0.0.0-9009-2] [com.company.servlets.ServletBase.commonLogic 429] VERBOSE [ ] - ***** EXECUTING CLASS: com.company.servlets.Content
11:32:13,487 [ajp-0.0.0.0-9009-1] [com.company.servlets.ServletBase.commonLogic 429] VERBOSE [ ] - ***** EXECUTING CLASS: com.company.servlets.Content
11:33:02,112 [ajp-0.0.0.0-9009-3] [com.company.servlets.ServletBase.commonLogic 429] VERBOSE [ ] - ***** EXECUTING CLASS: com.company.servlets.Login

I feel I am close but probably missing something obvious. I hope I provided enough info and would appreciate any help.

Wes.

1. Re: Profiler Not Recording Time

jesper.pedersen Dec 9, 2008 9:53 PM (in response to wstrater1)

Mhmm, this does indeed look strange as the JMeter plan clearly shows calls to the methods.

How are your classes packaged ?

Is the example running for you (see README.txt) ?
Actions
2. Re: Profiler Not Recording Time

wstrater1 Dec 10, 2008 11:21 AM (in response to wstrater1)

I was able to run the examples and get results so I went through whole process yet another time.

I ended up doing a diff between files in the build directory and the jboss/bin directory. Everything was looking good except the javassist.jar.

If I remember correctly, I followed the instructions in the Deployment in JBoss Application Server section and got an error about missing javassist when I was testing. Instead of looking in the build directory, I searched the Internet for a jar file.

You may want to add the javassist.jar to the Deployment in JBoss Application Server section in README.txt.

Thanks for your help,
Wes.
Actions
3. Re: Profiler Not Recording Time

jesper.pedersen Dec 10, 2008 9:17 PM (in response to wstrater1)

If you got the SVN downloaded javassist.jar is in the lib/ directory - or dist/ after building the profiler.

There is a small note in the documentation about the need to include javassist.jar in bin/ for EAP 4.x / JBoss AS 4.2 -- see "Core libraries". The documentation could be a lot better - the first task in that direction is the documentation environment scheduled currently for Beta4.

If you could track down why the classes aren't being profiled it would be great -- maybe try inserting some System.out's in agent.ProfilerThreadImpl, agent.Agent and agent.Profiler.

TIA !
Actions

Go to original post