sql statistics not working

266 views
Skip to first unread message

Pieter

unread,
Nov 22, 2010, 1:15:25 PM11/22/10
to javamelody
Great software! I really loved the fact that it worked just out of box
almost without any configuration.

Only the database stuff doesn't work for me. I use glassfish 3.0.1
with jndi datasources.

At first both the sql statistics and the "Database:" section in
"System informations" was empty. I then added a "datasources" init-
param to the filter section in web.xml but still no luck.

Then I added the "javamelody.datasources" context parameter. This
resulted in a filled "DataBase:" section: both my datasources now show
up.

Unfortunately the sql statistics still remain empty :-(

Any ideas before I download the sources and start debugging?

Emeric Vernat

unread,
Nov 22, 2010, 6:11:24 PM11/22/10
to javam...@googlegroups.com
Hi,

Thanks.

First, you should enable the logs for the category "net.bull.javamelody"
and for the level "debug" (in logback, log4j or j.u.l).
See
http://code.google.com/p/javamelody/wiki/UserGuideAdvanced#Debugging_logs
It will speak of your parameters ("datasources" in web.xml should work)
and it will speak of the datasources in jndi.

If the logs are not enough and if you want to debug, you can add a
breakpoint in JdbcWrapper.rebindDataSources:
http://code.google.com/p/javamelody/source/browse/trunk/javamelody-core/src/main/java/net/bull/javamelody/JdbcWrapper.java#371
and you can debug until rewrapDataSource. I have seen this work
successfully, but I admit that it was just a typical glassfish
configuration and it was some time ago already.

Sources for each version of javamelody are in the zip file of each
release or in the maven repository.

bye, Emeric


Le 22/11/2010 19:15, Pieter a �crit :

Pieter

unread,
Nov 23, 2010, 8:48:00 AM11/23/10
to javamelody
I have made some progress.

Logging didn't get me very far so I downloaded the source and took it
from there.

I found two anomalies:
1. Data sources do get wrapped (or rather the connection manager in
the "cm" field gets wrapped), but the ones I get from my jndi lookups
are not wrapped.
2. In my GlassFish installation the actual Connection that needs to be
wrapped (or rather whose "con" field needs to be wrapped) is of type
"com.sun.gjc.spi.jdbc40.ConnectionWrapper40" instead of type
"com.sun.gjc.spi.jdbc40.ConnectionHolder40".

Some details:

Using debug prints I found out that a number of data sources get
wrapped.
For instance, "JavaMelody filter init started" shows up twice in the
log, directly followed
by my prints that indicate both my data sources are wrapped. I print
the actual "System.identityHashCode"
of the data sources that get instrumented, so I won't get confused by
wrapped versions whose toString
is delegated.

These prints show that the data sources I get from my own jndi lookups
are different from the ones JavaMelody receives from its lookups!
Consequently the ones I get are not wrapped.

So I made the class JdbcWrapper and some of its methods public and
explicitly called:
JdbcWrapper.SINGLETON.rewrapDataSource("", dataSource);
just after lookup a dataSource using jndi.

This still didn't work because of anomaly 2. So I patched the
JavaMelody source again:
} else if (glassfish) {
String className = connection.getClass().getName();
if (className.equals("com.sun.gjc.spi.jdbc40.ConnectionHolder40")
||
className.equals("com.sun.gjc.spi.jdbc40.ConnectionWrapper40")) {
in JdbcWrapper (instead of the single test for ConnectionHolder40).

After this I finally got some stats on the monitoring page.

However, this solution requires patching both JavaMelody and my own
code, and making my code dependent on my custom version of JavaMelody
(with the public JdbcWrapper).

- So anyone have any bright ideas why the lookups by JavaMelody and my
own lookups return different data sources?
- Has com.sun.gjc.spi.jdbc40.ConnectionHolder40 been renamed to
com.sun.gjc.spi.jdbc40.ConnectionWrapper40 or is there something else
going on related to the previous point?

On Nov 23, 12:11 am, Emeric Vernat <ever...@free.fr> wrote:
> Hi,
>
> Thanks.
>
> First, you should enable the logs for the category "net.bull.javamelody"
> and for the level "debug" (in logback, log4j or j.u.l).
> Seehttp://code.google.com/p/javamelody/wiki/UserGuideAdvanced#Debugging_...
> It will speak of your parameters ("datasources" in web.xml should work)
> and it will speak of the datasources in jndi.
>
> If the logs are not enough and if you want to debug, you can add a
> breakpoint in JdbcWrapper.rebindDataSources:http://code.google.com/p/javamelody/source/browse/trunk/javamelody-co...

Emeric Vernat

unread,
Nov 23, 2010, 1:12:39 PM11/23/10
to javam...@googlegroups.com
In fact, com.sun.gjc.spi.jdbc40.ConnectionWrapper40 extends com.sun.gjc.spi.jdbc40.ConnectionHolder40.
So which class you get probably depends on your glassfish configuration or on your application.

And I have now included your change for JdbcWrapper.rewrapConnection in trunk of svn for the next release, thanks:
http://code.google.com/p/javamelody/source/browse/trunk/javamelody-core/src/main/java/net/bull/javamelody/JdbcWrapper.java#588

For the first issue, can you post your "net.bull.javamelody" logs?

And if you know that, what jndi name do you use in your application to lookup the datasource? (that is what is x in "new InitialContext().lookup(x)"?)
Do you have a resource-ref in your web.xml, like the following one?
http://code.google.com/p/javamelody/source/browse/trunk/javamelody-core/src/test/test-webapp/WEB-INF/web.xml#73

bye, Emeric


Le 23/11/2010 14:48, Pieter a �crit :

Pieter

unread,
Nov 24, 2010, 3:51:02 AM11/24/10
to javamelody

I have two resource-refs (one for each data source), but I think my
own application would not be able to find any data sources without it.

I included the relevant part of the logs. Note that I patched melody
logging to also print to stderr and used "grep SEVERE server.log" to
extract both the prints in my own code and the melody log output in a
single pass.

I have used 'sed' to cleanup the log output and decrease the line
length a little.

Besides the standard melody debug log output you will find some "<PO>
prefixed log output: these are entries I have added in my patched
version to gather some more information. The numbers you find are the
result of "System.identityHashCode" so I could identify instances
without getting confused by wrapped versions calling the original
"toString".

So the output "MELODY DEBUG: looking up java:comp/env/jdbc/Games4AllDB
resulted in: 27218591"
means that melody looked up the data source with name "java:comp/env/
jdbc/Games4AllDB" and this resulted in a data source with identity
hash code 27218591.

Note that successive lookups by melody actually deliver different data
sources! So melody wraps three different pairs of data sources: two in
the initialisation of the listeners and one pair in the initialisation
of the filter.
I only declare the melody listener and filter once in my web.xml.

The output without "MELODY DEBUG" in front of it is output from my own
application. Again each data source lookup results in a different
instance.

I'm probably doing something incredibly stupid, but it sure seems like
lookups of the same object in jndi returns different instances each
time. To make sure of this I even added code to lookup 20 data sources
in a row: it returned 20 different instances!

[#|2010-11-24T09:11:43.209|thread=27,Thread-1;|MELODY DEBUG:
JavaMelody listener init started|#]
[#|2010-11-24T09:11:43.250|thread=27,Thread-1;|MELODY DEBUG: <PO>
looking up java:comp/env/jdbc/Games4AllDB resulted in: 27218591|#]
[#|2010-11-24T09:11:43.256|thread=27,Thread-1;|MELODY DEBUG: <PO>
looking up java:comp/env/jdbc/klaverjasDB resulted in: 15302137|#]
[#|2010-11-24T09:11:43.257|thread=27,Thread-1;|MELODY DEBUG:
datasources found in JNDI: [java:comp/env/jdbc/Games4AllDB, java:comp/
env/jdbc/klaverjasDB]|#]
[#|2010-11-24T09:11:43.258|thread=27,Thread-1;|MELODY DEBUG:
Datasource needs rewrap: java:comp/env/jdbc/Games4AllDB of class
com.sun.gjc.spi.jdbc40.DataSource40|#]
[#|2010-11-24T09:11:43.262|thread=27,Thread-1;|MELODY DEBUG: <PO> xx
original CM: 21858759 in dataSource 27218591, thread: Thread[http-
thread-pool-4848-(2),10,Grizzly]|#]
[#|2010-11-24T09:11:43.268|thread=27,Thread-1;|MELODY DEBUG: <PO> xx
wrapping CM: 26249026 in dataSource 27218591|#]
[#|2010-11-24T09:11:43.269|thread=27,Thread-1;|MELODY DEBUG:
Datasource rewrapped: java:comp/env/jdbc/Games4AllDB|#]
[#|2010-11-24T09:11:43.270|thread=27,Thread-1;|MELODY DEBUG:
Datasource needs rewrap: java:comp/env/jdbc/klaverjasDB of class
com.sun.gjc.spi.jdbc40.DataSource40|#]
[#|2010-11-24T09:11:43.271|thread=27,Thread-1;|MELODY DEBUG: <PO> xx
original CM: 27268460 in dataSource 15302137, thread: Thread[http-
thread-pool-4848-(2),10,Grizzly]|#]
[#|2010-11-24T09:11:43.271|thread=27,Thread-1;|MELODY DEBUG: <PO> xx
wrapping CM: 14589095 in dataSource 15302137|#]
[#|2010-11-24T09:11:43.272|thread=27,Thread-1;|MELODY DEBUG:
Datasource rewrapped: java:comp/env/jdbc/klaverjasDB|#]
[#|2010-11-24T09:11:43.273|thread=27,Thread-1;|MELODY DEBUG:
JavaMelody listener init done|#]
[#|2010-11-24T09:11:43.273|thread=27,Thread-1;|MELODY DEBUG:
JavaMelody listener init started|#]
[#|2010-11-24T09:11:43.280|thread=27,Thread-1;|MELODY DEBUG: <PO>
looking up java:comp/env/jdbc/Games4AllDB resulted in: 16696972|#]
[#|2010-11-24T09:11:43.287|thread=27,Thread-1;|MELODY DEBUG: <PO>
looking up java:comp/env/jdbc/klaverjasDB resulted in: 10303697|#]
[#|2010-11-24T09:11:43.288|thread=27,Thread-1;|MELODY DEBUG:
datasources found in JNDI: [java:comp/env/jdbc/Games4AllDB, java:comp/
env/jdbc/klaverjasDB]|#]
[#|2010-11-24T09:11:43.288|thread=27,Thread-1;|MELODY DEBUG:
Datasource needs rewrap: java:comp/env/jdbc/Games4AllDB of class
com.sun.gjc.spi.jdbc40.DataSource40|#]
[#|2010-11-24T09:11:43.289|thread=27,Thread-1;|MELODY DEBUG: <PO> xx
original CM: 33380357 in dataSource 16696972, thread: Thread[http-
thread-pool-4848-(2),10,Grizzly]|#]
[#|2010-11-24T09:11:43.290|thread=27,Thread-1;|MELODY DEBUG: <PO> xx
wrapping CM: 27127246 in dataSource 16696972|#]
[#|2010-11-24T09:11:43.290|thread=27,Thread-1;|MELODY DEBUG:
Datasource rewrapped: java:comp/env/jdbc/Games4AllDB|#]
[#|2010-11-24T09:11:43.291|thread=27,Thread-1;|MELODY DEBUG:
Datasource needs rewrap: java:comp/env/jdbc/klaverjasDB of class
com.sun.gjc.spi.jdbc40.DataSource40|#]
[#|2010-11-24T09:11:43.292|thread=27,Thread-1;|MELODY DEBUG: <PO> xx
original CM: 23559301 in dataSource 10303697, thread: Thread[http-
thread-pool-4848-(2),10,Grizzly]|#]
[#|2010-11-24T09:11:43.293|thread=27,Thread-1;|MELODY DEBUG: <PO> xx
wrapping CM: 18884733 in dataSource 10303697|#]
[#|2010-11-24T09:11:43.293|thread=27,Thread-1;|MELODY DEBUG:
Datasource rewrapped: java:comp/env/jdbc/klaverjasDB|#]
[#|2010-11-24T09:11:43.294|thread=27,Thread-1;|MELODY DEBUG:
JavaMelody listener init done|#]
[#|2010-11-24T09:14:55.364|thread=24,Thread-1;|MELODY DEBUG:
JavaMelody filter init started|#]
[#|2010-11-24T09:14:55.372|thread=24,Thread-1;|MELODY DEBUG: OS: Linux
unknown, i386/32|#]
[#|2010-11-24T09:14:55.373|thread=24,Thread-1;|MELODY DEBUG: Java:
Java(TM) SE Runtime Environment, 1.6.0_22-b04|#]
[#|2010-11-24T09:14:55.374|thread=24,Thread-1;|MELODY DEBUG: Server:
GlassFish Server Open Source Edition 3.0.1|#]
[#|2010-11-24T09:14:55.374|thread=24,Thread-1;|MELODY DEBUG: Webapp
context: /game-store-klaverjas|#]
[#|2010-11-24T09:14:55.375|thread=24,Thread-1;|MELODY DEBUG:
JavaMelody version: 1.23.0-SNAPSHOT|#]
[#|2010-11-24T09:14:55.375|thread=24,Thread-1;|MELODY DEBUG: Host:
plein.spe...@127.0.1.1|#]
[#|2010-11-24T09:14:55.376|thread=24,Thread-1;|MELODY DEBUG: parameter
defined: system-actions-enabled=true|#]
[#|2010-11-24T09:14:55.377|thread=24,Thread-1;|MELODY DEBUG: parameter
defined: datasources=java:comp/env/jdbc/Games4AllDB,java:comp/env/jdbc/
klaverjasDB|#]
[#|2010-11-24T09:14:55.382|thread=24,Thread-1;|MELODY DEBUG: log
listeners initialized|#]
[#|2010-11-24T09:14:55.393|thread=24,Thread-1;|MELODY DEBUG: <PO>
looking up java:comp/env/jdbc/Games4AllDB resulted in: 15376239|#]
[#|2010-11-24T09:14:55.399|thread=24,Thread-1;|MELODY DEBUG: <PO>
looking up java:comp/env/jdbc/klaverjasDB resulted in: 25770524|#]
[#|2010-11-24T09:14:55.399|thread=24,Thread-1;|MELODY DEBUG:
datasources found in JNDI: [java:comp/env/jdbc/Games4AllDB, java:comp/
env/jdbc/klaverjasDB]|#]
[#|2010-11-24T09:14:55.401|thread=24,Thread-1;|MELODY DEBUG:
Datasource needs rewrap: java:comp/env/jdbc/Games4AllDB of class
com.sun.gjc.spi.jdbc40.DataSource40|#]
[#|2010-11-24T09:14:55.402|thread=24,Thread-1;|MELODY DEBUG: <PO> xx
original CM: 4602469 in dataSource 15376239, thread: Thread[http-
thread-pool-8180-(1),10,Grizzly]|#]
[#|2010-11-24T09:14:55.402|thread=24,Thread-1;|MELODY DEBUG: <PO> xx
wrapping CM: 10737061 in dataSource 15376239|#]
[#|2010-11-24T09:14:55.403|thread=24,Thread-1;|MELODY DEBUG:
Datasource rewrapped: java:comp/env/jdbc/Games4AllDB|#]
[#|2010-11-24T09:14:55.404|thread=24,Thread-1;|MELODY DEBUG:
Datasource needs rewrap: java:comp/env/jdbc/klaverjasDB of class
com.sun.gjc.spi.jdbc40.DataSource40|#]
[#|2010-11-24T09:14:55.404|thread=24,Thread-1;|MELODY DEBUG: <PO> xx
original CM: 2059782 in dataSource 25770524, thread: Thread[http-
thread-pool-8180-(1),10,Grizzly]|#]
[#|2010-11-24T09:14:55.405|thread=24,Thread-1;|MELODY DEBUG: <PO> xx
wrapping CM: 24136960 in dataSource 25770524|#]
[#|2010-11-24T09:14:55.406|thread=24,Thread-1;|MELODY DEBUG:
Datasource rewrapped: java:comp/env/jdbc/klaverjasDB|#]
[#|2010-11-24T09:14:55.420|thread=24,Thread-1;|MELODY DEBUG: counters
initialized|#]
[#|2010-11-24T09:14:55.462|thread=24,Thread-1;|MELODY DEBUG: counters
data read from files in /tmp/javamelody/game-store-
klaverjas_plein.spelplein.eu|#]
[#|2010-11-24T09:14:55.504|thread=24,Thread-1;|MELODY DEBUG: collect
task scheduled every 60s|#]
[#|2010-11-24T09:14:56.092|thread=24,Thread-1;|MELODY DEBUG: first
collect of data done|#]
[#|2010-11-24T09:14:56.093|thread=24,Thread-1;|MELODY DEBUG:
JavaMelody filter init done|#]
[#|2010-11-24T09:14:56.143|thread=24,Thread-1;|Getting context in
thread http-thread-pool-8180-(1): Thread[http-thread-pool-8180-(1),
10,Grizzly]|#]
[#|2010-11-24T09:14:56.149|thread=24,Thread-1;|**** GAME: klaverjas|#]
[#|2010-11-24T09:14:56.150|thread=24,Thread-1;|CREATED CONTEXT:
klaverjas|#]
[#|2010-11-24T09:14:56.156|thread=24,Thread-1;|dataSource: 16461351
found in java:comp/env/jdbc/Games4AllDB, thread=Thread[http-thread-
pool-8180-(1),10,Grizzly]|#]
[#|2010-11-24T09:14:56.162|thread=24,Thread-1;|found connection
manager: 9638747 in 16461351|#]
[#|2010-11-24T09:14:56.405|thread=24,Thread-1;|dataSource: 8759735
found in java:comp/env/jdbc/klaverjasDB, thread=Thread[http-thread-
pool-8180-(1),10,Grizzly]|#]
[#|2010-11-24T09:14:56.405|thread=24,Thread-1;|found connection
manager: 21588786 in 8759735|#]


On Nov 23, 7:12 pm, Emeric Vernat <ever...@free.fr> wrote:
> In fact, com.sun.gjc.spi.jdbc40.ConnectionWrapper40 extends com.sun.gjc.spi.jdbc40.ConnectionHolder40.
> So which class you get probably depends on your glassfish configuration or on your application.
>
> And I have now included your change for JdbcWrapper.rewrapConnection in trunk of svn for the next release, thanks:http://code.google.com/p/javamelody/source/browse/trunk/javamelody-co...
>
> For the first issue, can you post your "net.bull.javamelody" logs?
>
> And if you know that, what jndi name do you use in your application to lookup the datasource? (that is what is x in "new InitialContext().lookup(x)"?)
> Do you have a resource-ref in your web.xml, like the following one?http://code.google.com/p/javamelody/source/browse/trunk/javamelody-co...

Emeric Vernat

unread,
Dec 5, 2010, 2:18:02 PM12/5/10
to javam...@googlegroups.com
Hi,

If "JavaMelody filter init started" shows up twice, it is perhaps because glassfish starts the filter and listener after reading META-INF/web-fragment.xml in the javamelody jar file and then starts again the filter and listener after reading them in your web.xml file.
It seems to me that glassfish 3.0.1 is different from tomcat on this point: tomcat 7.0.x does not start the filter twice if it is in web.xml and in web-fragment.xml.
So in glassfish 3, you should probably remove the filter and the listener from your web.xml and let the web-fragment.xml do its job (and so you need to put javamelody parameter in context.xml or in system properties).


Then if you have a new instance for each JNDI lookup, it is perhaps because it is like that in the specification of JavaEE 6 (and glassfish is the reference implementation of JavaEE 6). I think that it was not the default behavior in tomcat 6 and glassfish 2.
If we have some chance, there is in glassfish 3 configuration or in your datasource configuration some parameter to restore the old behavior of the JNDI lookups.
For example, there is such a parameter in tomcat 7.0.5 configuration:
https://issues.apache.org/bugzilla/show_bug.cgi?id=50159
and if there is no such parameter in glassfish, you could ask them an enhancement for such a backward compatibility parameter.

In any case, if the JavaEE 6 specification is the issue, then if you find the right parameter in glassfish or if you find a patch in javamelody to make it work, please say us.

bye, Emeric

Le 24/11/2010 09:51, Pieter a �crit :

Reply all
Reply to author
Forward
0 new messages