search

sylvainlaurent / JDBC-Performance-Logger

A JDBC driver wrapper and GUI to analyze statement performance
Apache License 2.0
84 stars 26 forks source link

Switch output of catched SQL to stdout on server side #55

Closed gjaekel closed 7 years ago

gjaekel commented 7 years ago

Dear Sylvain, I would like to disable the ouput of catched SQL to stdout on server side. Because I want to have the agent installed, but "quiet" in a production environment and just to connect to it via the remote GUI as needed. How to a achieve this? with greetings Guido

sylvainlaurent commented 7 years ago

The driver uses java.util.Logger, so you can configure it according to https://docs.oracle.com/javase/7/docs/api/java/util/logging/LogManager.html For instance in the tests I bridge it to SLF4J (using jul-to-slf4j lib + configuration in logging.properties) which is itself bridged to log4j (using slf4j-log4j12 lib) which is configured in the log4j.xml file.

see https://github.com/sylvainlaurent/JDBC-Performance-Logger/tree/master/jdbc-perf-logger-driver/src/test/resources .

If you just want to make it quiet, you don't have to bridge java.util.logging, you can directly configure it in a logging.properties file.

gjaekel commented 7 years ago

Dear Sylvain, thank for fast reply!

But that's seems not to be a smart way for me. Because I even take efforts to set up an per-application logging (and I can't even understand that this isn't the default on Wildfly). Therefore the logging use the application logging configuration (the SQL is logged in the applications logfile) and therefore I would have configure it for every (comming and going) application.

(In addition, I don't want to suppress the initial agents driver interception messages - but these appear in the Wildfly's console log and will not be affected.)

Nevertheless i'll now play with your suggestion and give feedback. Because there may be other things on stdout I have to filter out the used Logger(s), right?

But in fact my idea is let your package have a swich to suppress the local SQL logging and this may be passed as a system property. I'm a system engineer but no developer, but I'll also will try to find the associated lines in the code.

gjaekel commented 7 years ago

Aaaargh! I'm VERY sorry, but the output I observed isn't produced by the JDBC-Performance-Logger at all! It was (globaly) caused by Hibernate; by setting the System-Property hibernate.show_sql= true, as I just double-verified.

As a result, now I don't notice any local "SQL-related" output anymore. I just get the initial "Transforming class for interception" and related on the Wildfly's log channels, which is already perfect.

Next, I'll try to apply it to our Tomcat installations ...

BTW: The updated timestamp delta calculation with respect to the selected line is a very smart feature I never seen before.

sylvainlaurent commented 7 years ago

I'm glad you found the problem and that you find the tool useful. Regards Sylvain

gjaekel commented 7 years ago

Dear Sylvain,

Here my feedback: Today I found time to evaluate it on our Tomcats. All jdbc datasources for all application are managed by the Tomcat JDBC Pool, no application directly uses the drivers directly. The drivers are accessible for Tomcat along with the pool driver through it's lib directory.

If I apply the JDBC-Performance-Logger as an agent, it also have to add the SQL drivers to the JVMs plain classpath. Or the datasource initialisation inside a container will fail with 'interface foo not visible' for the driver class, e.g.:

20161122-103635.584 javax.persistence.PersistenceException: org.hibernate.exception.GenericJDBCException: Could not open connection
20161122-103635.584     at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763)
20161122-103635.585     at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677)
20161122-103635.585     at org.hibernate.jpa.internal.QueryImpl.getSingleResult(QueryImpl.java:524)
20161122-103635.585     at org.hibernate.jpa.criteria.compile.CriteriaQueryTypeQueryAdapter.getSingleResult(CriteriaQueryTypeQueryAdapter.java:71)
20161122-103635.585     at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
20161122-103635.585     at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
20161122-103635.586     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
20161122-103635.586     at java.lang.reflect.Method.invoke(Method.java:498)
20161122-103635.586     at org.springframework.orm.jpa.SharedEntityManagerCreator$DeferredQueryInvocationHandler.invoke(SharedEntityManagerCreator.java:360)
20161122-103635.586     at com.sun.proxy.$Proxy390.getSingleResult(Unknown Source)
20161122-103635.586     at org.springframework.data.jpa.repository.query.JpaQueryExecution$SingleEntityExecution.doExecute(JpaQueryExecution.java:197)
20161122-103635.587     at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:74)
20161122-103635.587     at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:98)
20161122-103635.587     at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:89)
20161122-103635.587     at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:421)
20161122-103635.587     at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:381)
20161122-103635.588     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
20161122-103635.587     at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:421)
20161122-103635.587     at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:381)
20161122-103635.588     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
20161122-103635.588     at org.springframework.data.repository.core.support.RepositoryFactorySupport$DefaultMethodInvokingMethodInterceptor.invoke(RepositoryFactorySupport.java:512)
20161122-103635.588     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
20161122-103635.588     at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:98)
20161122-103635.589     at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:262)
20161122-103635.589     at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:95)
20161122-103635.589     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
20161122-103635.589     at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:136)
20161122-103635.590     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
20161122-103635.590     at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodIntercceptor.invoke(CrudMethodMetadataPostPr
20161122-103635.590     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
20161122-103635.590     at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
20161122-103635.591     at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
20161122-103635.591     at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
20161122-103635.591     at com.sun.proxy.$Proxy370.countByIsSuperTrue(Unknown Source)
20161122-103635.591     at de.dnb.urhwahrng.applicationservice.datamanagement.AdminRepository.existSuperAdmin(AdminRepository.java:91)
20161122-103635.591     at de.dnb.urhwahrng.applicationservice.datamanagement.AdminRepository$$FastClassBySpringCGLIB$$616c9488.invoke(<generated>)
20161122-103635.592     at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
20161122-103635.592     at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:649)
20161122-103635.592     at de.dnb.urhwahrng.applicationservice.datamanagement.AdminRepository$$EnhancerBySpringCGLIB$$ee9e468f.existSuperAdmin(<generated>)
20161122-103635.592     at de.dnb.urhwahrng.applicationservice.business.usecases.admin.CreateDefaultSuperAdminUseCase.createDefaultSuperAdmin(CreateDefaultSuperAdminUseCase.java:31)
20161122-103635.593     at de.dnb.urhwahrng.applicationservice.business.service.init.ServiceInitializer.onApplicationEvent(ServiceInitializer.java:29)
20161122-103635.593     at de.dnb.urhwahrng.applicationservice.business.service.init.ServiceInitializer.onApplicationEvent(ServiceInitializer.java:17)
20161122-103635.593     at org.springframework.context.event.SimpleApplicationEventMulticaster.invokeListener(SimpleApplicationEventMulticaster.java:151)
20161122-103635.593     at org.springframework.context.event.SimpleApplicationEventMulticaster.multicastEvent(SimpleApplicationEventMulticaster.java:128)
20161122-103635.594     at org.springframework.context.support.AbstractApplicationContext.publishEvent(AbstractApplicationContext.java:331)
20161122-103635.594     at org.springframework.context.support.AbstractApplicationContext.finishRefresh(AbstractApplicationContext.java:773)
20161122-103635.594     at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:483)
20161122-103635.594     at org.springframework.web.context.ContextLoader.configureAndRefreshWebApplicationContext(ContextLoader.java:403)
20161122-103635.594     at org.springframework.web.context.ContextLoader.initWebApplicationContext(ContextLoader.java:306)
20161122-103635.595     at org.springframework.web.context.ContextLoaderListener.contextInitialized(ContextLoaderListener.java:106)
20161122-103635.595     at org.apache.catalina.core.StandardContext.listenerStart(Unknown Source)
20161122-103635.595     at org.apache.catalina.core.StandardContext.startInternal(Unknown Source)
20161122-103635.595     at org.apache.catalina.util.LifecycleBase.start(Unknown Source)
20161122-103635.595     at org.apache.catalina.core.ContainerBase.addChildInternal(Unknown Source)
20161122-103635.596     at org.apache.catalina.core.ContainerBase.addChild(Unknown Source)
20161122-103635.596     at org.apache.catalina.core.StandardHost.addChild(Unknown Source)
20161122-103635.596     at org.apache.catalina.startup.HostConfig.deployWAR(Unknown Source)
20161122-103635.596     at org.apache.catalina.startup.HostConfig$DeployWar.run(Unknown Source)
20161122-103635.596     at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
20161122-103635.597     at java.util.concurrent.FutureTask.run(FutureTask.java:266)
20161122-103635.597     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
20161122-103635.597     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
20161122-103635.597     at java.lang.Thread.run(Thread.java:745)
20161122-103635.597 Caused by: org.hibernate.exception.GenericJDBCException: Could not open connection
20161122-103635.598     at org.hibernate.exception.internal.StandardSQLExceptionConverter.convert(StandardSQLExceptionConverter.java:54)
20161122-103635.598     at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:126)
20161122-103635.598     at org.hibernate.engine.jdbc.spi.SqlExceptionHelper.convert(SqlExceptionHelper.java:112)
20161122-103635.598     at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:235)
20161122-103635.598     at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.getConnection(LogicalConnectionImpl.java:171)
20161122-103635.599     at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.connection(StatementPreparerImpl.java:63)
20161122-103635.599     at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$5.doPrepare(StatementPreparerImpl.java:162)
20161122-103635.599     at org.hibernate.engine.jdbc.internal.StatementPreparerImpl$StatementPreparationTemplate.prepareStatement(StatementPreparerImpl.java:186)
20161122-103635.599     at org.hibernate.engine.jdbc.internal.StatementPreparerImpl.prepareQueryStatement(StatementPreparerImpl.java:160)
20161122-103635.599     at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1885)
20161122-103635.600     at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1862)
20161122-103635.600     at org.hibernate.loader.Loader.executeQueryStatement(Loader.java:1839)
20161122-103635.600     at org.hibernate.loader.Loader.doQuery(Loader.java:910)
20161122-103635.600     at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:355)
20161122-103635.600     at org.hibernate.loader.Loader.doList(Loader.java:2554)
20161122-103635.601     at org.hibernate.loader.Loader.doList(Loader.java:2540)
20161122-103635.601     at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2370)
20161122-103635.601     at org.hibernate.loader.Loader.list(Loader.java:2365)
20161122-103635.601     at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:497)
20161122-103635.601     at org.hibernate.hql.internal.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:387)
20161122-103635.602     at org.hibernate.engine.query.spi.HQLQueryPlan.performList(HQLQueryPlan.java:236)
20161122-103635.602     at org.hibernate.internal.SessionImpl.list(SessionImpl.java:1264)
20161122-103635.602     at org.hibernate.internal.QueryImpl.list(QueryImpl.java:103)
20161122-103635.602     at org.hibernate.jpa.internal.QueryImpl.list(QueryImpl.java:573)
20161122-103635.602     at org.hibernate.jpa.internal.QueryImpl.getSingleResult(QueryImpl.java:495)
20161122-103635.603     ... 57 more
20161122-103635.603 Caused by: java.sql.SQLException: java.lang.IllegalArgumentException: interface com.mysql.jdbc.MySQLConnection is not visible from class loader
20161122-103635.603     at ch.sla.jdbcperflogger.driver.WrappingDriver.wrapConnection(WrappingDriver.java:142)
20161122-103635.603     at ch.sla.jdbcperflogger.agent.DriverInterceptor.connect(DriverInterceptor.java:13)
20161122-103635.603     at com.mysql.jdbc.Driver.connect(Driver.java)
20161122-103635.604     at org.apache.tomcat.jdbc.pool.PooledConnection.connectUsingDriver(PooledConnection.java:307)
20161122-103635.604     at org.apache.tomcat.jdbc.pool.PooledConnection.connect(PooledConnection.java:200)
20161122-103635.604     at org.apache.tomcat.jdbc.pool.ConnectionPool.createConnection(ConnectionPool.java:710)
20161122-103635.604     at org.apache.tomcat.jdbc.pool.ConnectionPool.borrowConnection(ConnectionPool.java:644)
20161122-103635.604     at org.apache.tomcat.jdbc.pool.ConnectionPool.getConnection(ConnectionPool.java:187)
20161122-103635.605     at org.apache.tomcat.jdbc.pool.DataSourceProxy.getConnection(DataSourceProxy.java:127)
20161122-103635.605     at org.hibernate.engine.jdbc.connections.internal.DatasourceConnectionProviderImpl.getConnection(DatasourceConnectionProviderImpl.java:139)
20161122-103635.605     at org.hibernate.internal.AbstractSessionImpl$NonContextualJdbcConnectionAccess.obtainConnection(AbstractSessionImpl.java:380)
20161122-103635.606     at org.hibernate.engine.jdbc.internal.LogicalConnectionImpl.obtainConnection(LogicalConnectionImpl.java:228)
20161122-103635.606     ... 78 more
20161122-103635.606 Caused by: java.lang.IllegalArgumentException: interface com.mysql.jdbc.MySQLConnection is not visible from class loader
20161122-103635.606     at java.lang.reflect.Proxy$ProxyClassFactory.apply(Proxy.java:581)
20161122-103635.606     at java.lang.reflect.Proxy$ProxyClassFactory.apply(Proxy.java:557)
20161122-103635.607     at java.lang.reflect.WeakCache$Factory.get(WeakCache.java:230)
20161122-103635.607     at java.lang.reflect.WeakCache.get(WeakCache.java:127)
20161122-103635.607     at java.lang.reflect.Proxy.getProxyClass0(Proxy.java:419)
20161122-103635.607     at java.lang.reflect.Proxy.newProxyInstance(Proxy.java:719)
20161122-103635.607     at ch.sla.jdbcperflogger.driver.WrappingDriver.wrapConnection(WrappingDriver.java:169)
20161122-103635.608     at ch.sla.jdbcperflogger.agent.DriverInterceptor.connect(DriverInterceptor.java:13)
20161122-103635.608     at com.mysql.jdbc.NonRegisteringDriver.connect(NonRegisteringDriver.java)
20161122-103635.608     at com.mysql.jdbc.Driver.connect$accessor$VYtw5NUl(Driver.java)
20161122-103635.608     at com.mysql.jdbc.Driver$auxiliary$TNwlmAJg.call(Unknown Source)
20161122-103635.608     at ch.sla.jdbcperflogger.driver.WrappingDriver.wrapConnection(WrappingDriver.java:137)
20161122-103635.609     ... 89 more