You can configure Hibernate to log SQL query via
<property name="hibernate.show_sql" value="false" />
But that is not the best solution, because Hibernate:
- Logs to Standard Output.
- Does not log SQL Parameters (since Hibernate uses PreparedStatement, and the values are not available when created the PreparedStatement)
- Does not out-of-the box logs the Execution TIme.
A better solution is to use P6Spy.
First we gona use P6Spy in automatic Integration Test and in-memory database H2 Cheet Sheat. So first add Maven test dependency.
<!-- Hibernate 5 and EAP 7.3 Version -->
<hibernate.version>5.3.14.Final</hibernate.version>
<hibernate-validator.version>6.0.18.Final</hibernate-validator.version>
<!-- H2 in-memory database -->
<dependency>
<groupId>com.h2database</groupId>
<artifactId>h2</artifactId>
<version>1.4.199</version>
<scope>test</scope>
</dependency>
<!-- MySQL 8 Community Edition, CE -->
<dependency>
<groupId>mysql</groupId>
<artifactId>mysql-connector-java</artifactId>
<version>8.0.17</version>
<scope>test</scope>
</dependency>
<!-- Hibernate 5 -->
<dependency>
<groupId>org.hibernate</groupId>
<artifactId>hibernate-core</artifactId>
<version>${hibernate.version}</version>
<scope>test</scope>
</dependency>
<dependency>
<groupId>org.hibernate</groupId>
<artifactId>hibernate-envers</artifactId>
<version>${hibernate.version}</version>
<scope>test</scope>
</dependency>
<dependency>
<groupId>org.hibernate.validator</groupId>
<artifactId>hibernate-validator</artifactId>
<version>${hibernate-validator.version}</version>
<scope>test</scope>
</dependency>
<dependency>
<groupId>org.glassfish</groupId>
<artifactId>jakarta.el</artifactId>
<version>3.0.2</version>
<scope>test</scope>
</dependency>
<!-- P6Spy -->
<dependency>
<groupId>p6spy</groupId>
<artifactId>p6spy</artifactId>
<version>3.9.1</version>
<scope>test</scope>
</dependency>
And now modify our src/test/resources/META-INF/persistence.xml. Note the updated hibernate.connection.driver_class and hibernate.connection.url.
<?xml version="1.0" encoding="UTF-8"?>
<persistence xmlns="http://xmlns.jcp.org/xml/ns/persistence"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://xmlns.jcp.org/xml/ns/persistence http://xmlns.jcp.org/xml/ns/persistence/persistence_2_2.xsd"
version="2.2">
<persistence-unit name="IT" transaction-type="RESOURCE_LOCAL">
<class>se.magnuskkarlsson.example.javaee8_p6spy.entity.User</class>
<properties>
<property name="hibernate.dialect" value="org.hibernate.dialect.H2Dialect" />
<!-- <property name="hibernate.connection.driver_class" value="org.h2.Driver" /> -->
<!-- <property name="hibernate.connection.url" value="jdbc:h2:mem:" /> -->
<property name="hibernate.connection.driver_class" value="com.p6spy.engine.spy.P6SpyDriver" />
<property name="hibernate.connection.url" value="jdbc:p6spy:h2:mem:" />
<property name="hibernate.hbm2ddl.auto" value="create-drop" />
<property name="hibernate.show_sql" value="false" />
<property name="hibernate.format_sql" value="false" />
<property name="hibernate.generate_statistics" value="false" />
<property name="hibernate.cache.infinispan.statistics" value="false" />
</properties>
</persistence-unit>
</persistence>
And in our IT class everything is the same. For rendering test data I use Generating Test Data - JavaFaker.
package se.magnuskkarlsson.example.javaee8_p6spy.control;
import java.util.Locale;
import javax.persistence.EntityManager;
import javax.persistence.Persistence;
import org.junit.After;
import org.junit.AfterClass;
import org.junit.Before;
import org.junit.BeforeClass;
import org.junit.Test;
import com.github.javafaker.Faker;
import se.magnuskkarlsson.example.javaee8_p6spy.entity.User;
public class UserIT {
private static EntityManager em;
private final Faker faker = new Faker(new Locale("sv-SE")); // default Locale("en", "")
@BeforeClass
public static void oneTimeSetUp() throws Exception {
em = Persistence.createEntityManagerFactory("IT").createEntityManager();
}
@Before
public void setUp() throws Exception {
em.getTransaction().begin();
}
@After
public void tearDown() {
em.getTransaction().commit();
}
@AfterClass
public static void oneTimeTearDown() throws Exception {
}
// ----------------------- Test Methods -----------------------
@Test
public void create() throws Exception {
User user = new User();
user.setName(faker.name().fullName());
em.persist(user);
System.out.println("Persisted " + user.getId());
}
}
And my @Entity class.
package se.magnuskkarlsson.example.javaee8_p6spy.entity;
import java.util.Date;
import javax.persistence.Column;
import javax.persistence.Entity;
import javax.persistence.GeneratedValue;
import javax.persistence.GenerationType;
import javax.persistence.Id;
import javax.persistence.Temporal;
import javax.persistence.TemporalType;
import javax.validation.constraints.NotBlank;
import javax.validation.constraints.Size;
@Entity
public class User {
@Id
@GeneratedValue(strategy = GenerationType.IDENTITY)
private Long id;
@Temporal(TemporalType.TIMESTAMP)
@Column
private Date created = new Date();
@NotBlank
@Size(min = 2, max = 255)
@Column(length = 255)
private String name;
// ----------------------- Logic Methods -----------------------
// ----------------------- Helper Methods -----------------------
@Override
public String toString() {
return "User [id=" + id + ", created=" + created + ", name=" + name + "]";
}
// ----------------------- Get and Set Methods -----------------------
public Long getId() {
return id;
}
public void setId(Long id) {
this.id = id;
}
public Date getCreated() {
return created;
}
public void setCreated(Date created) {
this.created = created;
}
public String getName() {
return name;
}
public void setName(String name) {
this.name = name;
}
}
And finally we need a P6Spy configuration file src/test/resources/spy.properties, which we copy from https://p6spy.readthedocs.io/en/latest/configandusage.html.
Then we need to uncomment one line to set logging to console appender=com.p6spy.engine.spy.appender.StdoutLogger.
#################################################################
# P6Spy Options File #
# See documentation for detailed instructions #
# http://p6spy.github.io/p6spy/2.0/configandusage.html #
#################################################################
#################################################################
# MODULES #
# #
# Module list adapts the modular functionality of P6Spy. #
# Only modules listed are active. #
# (default is com.p6spy.engine.logging.P6LogFactory and #
# com.p6spy.engine.spy.P6SpyFactory) #
# Please note that the core module (P6SpyFactory) can't be #
# deactivated. #
# Unlike the other properties, activation of the changes on #
# this one requires reload. #
#################################################################
#modulelist=com.p6spy.engine.spy.P6SpyFactory,com.p6spy.engine.logging.P6LogFactory,com.p6spy.engine.outage.P6OutageFactory
################################################################
# CORE (P6SPY) PROPERTIES #
################################################################
# A comma separated list of JDBC drivers to load and register.
# (default is empty)
#
# Note: This is normally only needed when using P6Spy in an
# application server environment with a JNDI data source or when
# using a JDBC driver that does not implement the JDBC 4.0 API
# (specifically automatic registration).
#driverlist=
# for flushing per statement
# (default is false)
#autoflush=false
# sets the date format using Java's SimpleDateFormat routine.
# In case property is not set, milliseconds since 1.1.1970 (unix time) is used (default is empty)
#dateformat=
# prints a stack trace for every statement logged
#stacktrace=false
# if stacktrace=true, specifies the stack trace to print
#stacktraceclass=
# determines if property file should be reloaded
# Please note: reload means forgetting all the previously set
# settings (even those set during runtime - via JMX)
# and starting with the clean table
# (default is false)
#reloadproperties=false
# determines how often should be reloaded in seconds
# (default is 60)
#reloadpropertiesinterval=60
# specifies the appender to use for logging
# Please note: reload means forgetting all the previously set
# settings (even those set during runtime - via JMX)
# and starting with the clean table
# (only the properties read from the configuration file)
# (default is com.p6spy.engine.spy.appender.FileLogger)
#appender=com.p6spy.engine.spy.appender.Slf4JLogger
appender=com.p6spy.engine.spy.appender.StdoutLogger
#appender=com.p6spy.engine.spy.appender.FileLogger
# name of logfile to use, note Windows users should make sure to use forward slashes in their pathname (e:/test/spy.log)
# (used for com.p6spy.engine.spy.appender.FileLogger only)
# (default is spy.log)
#logfile=spy.log
# append to the p6spy log file. if this is set to false the
# log file is truncated every time. (file logger only)
# (default is true)
#append=true
# class to use for formatting log messages (default is: com.p6spy.engine.spy.appender.SingleLineFormat)
#logMessageFormat=com.p6spy.engine.spy.appender.SingleLineFormat
# Custom log message format used ONLY IF logMessageFormat is set to com.p6spy.engine.spy.appender.CustomLineFormat
# default is %(currentTime)|%(executionTime)|%(category)|connection%(connectionId)|%(sqlSingleLine)
# Available placeholders are:
# %(connectionId) the id of the connection
# %(currentTime) the current time expressing in milliseconds
# %(executionTime) the time in milliseconds that the operation took to complete
# %(category) the category of the operation
# %(effectiveSql) the SQL statement as submitted to the driver
# %(effectiveSqlSingleLine) the SQL statement as submitted to the driver, with all new lines removed
# %(sql) the SQL statement with all bind variables replaced with actual values
# %(sqlSingleLine) the SQL statement with all bind variables replaced with actual values, with all new lines removed
#customLogMessageFormat=%(currentTime)|%(executionTime)|%(category)|connection%(connectionId)|%(sqlSingleLine)
# format that is used for logging of the java.util.Date implementations (has to be compatible with java.text.SimpleDateFormat)
# (default is yyyy-MM-dd'T'HH:mm:ss.SSSZ)
#databaseDialectDateFormat=yyyy-MM-dd'T'HH:mm:ss.SSSZ
# format that is used for logging of the java.sql.Timestamp implementations (has to be compatible with java.text.SimpleDateFormat)
# (default is yyyy-MM-dd'T'HH:mm:ss.SSSZ)
#databaseDialectTimestampFormat=yyyy-MM-dd'T'HH:mm:ss.SSSZ
# format that is used for logging booleans, possible values: boolean, numeric
# (default is boolean)
#databaseDialectBooleanFormat=boolean
# Specifies the format for logging binary data. Not applicable if excludebinary is true.
# (default is com.p6spy.engine.logging.format.HexEncodedBinaryFormat)
#databaseDialectBinaryFormat=com.p6spy.engine.logging.format.PostgreSQLBinaryFormat
#databaseDialectBinaryFormat=com.p6spy.engine.logging.format.MySQLBinaryFormat
#databaseDialectBinaryFormat=com.p6spy.engine.logging.format.HexEncodedBinaryFormat
# whether to expose options via JMX or not
# (default is true)
#jmx=true
# if exposing options via jmx (see option: jmx), what should be the prefix used?
# jmx naming pattern constructed is: com.p6spy(.<jmxPrefix>)?:name=<optionsClassName>
# please note, if there is already such a name in use it would be unregistered first (the last registered wins)
# (default is none)
#jmxPrefix=
# if set to true, the execution time will be measured in nanoseconds as opposed to milliseconds
# (default is false)
#useNanoTime=false
#################################################################
# DataSource replacement #
# #
# Replace the real DataSource class in your application server #
# configuration with the name com.p6spy.engine.spy.P6DataSource #
# (that provides also connection pooling and xa support). #
# then add the JNDI name and class name of the real #
# DataSource here #
# #
# Values set in this item cannot be reloaded using the #
# reloadproperties variable. Once it is loaded, it remains #
# in memory until the application is restarted. #
# #
#################################################################
#realdatasource=/RealMySqlDS
#realdatasourceclass=com.mysql.jdbc.jdbc2.optional.MysqlDataSource
#################################################################
# DataSource properties #
# #
# If you are using the DataSource support to intercept calls #
# to a DataSource that requires properties for proper setup, #
# define those properties here. Use name value pairs, separate #
# the name and value with a semicolon, and separate the #
# pairs with commas. #
# #
# The example shown here is for mysql #
# #
#################################################################
#realdatasourceproperties=port;3306,serverName;myhost,databaseName;jbossdb,foo;bar
#################################################################
# JNDI DataSource lookup #
# #
# If you are using the DataSource support outside of an app #
# server, you will probably need to define the JNDI Context #
# environment. #
# #
# If the P6Spy code will be executing inside an app server then #
# do not use these properties, and the DataSource lookup will #
# use the naming context defined by the app server. #
# #
# The two standard elements of the naming environment are #
# jndicontextfactory and jndicontextproviderurl. If you need #
# additional elements, use the jndicontextcustom property. #
# You can define multiple properties in jndicontextcustom, #
# in name value pairs. Separate the name and value with a #
# semicolon, and separate the pairs with commas. #
# #
# The example shown here is for a standalone program running on #
# a machine that is also running JBoss, so the JNDI context #
# is configured for JBoss (3.0.4). #
# #
# (by default all these are empty) #
#################################################################
#jndicontextfactory=org.jnp.interfaces.NamingContextFactory
#jndicontextproviderurl=localhost:1099
#jndicontextcustom=java.naming.factory.url.pkgs;org.jboss.naming:org.jnp.interfaces
#jndicontextfactory=com.ibm.websphere.naming.WsnInitialContextFactory
#jndicontextproviderurl=iiop://localhost:900
################################################################
# P6 LOGGING SPECIFIC PROPERTIES #
################################################################
# filter what is logged
# please note this is a precondition for usage of: include/exclude/sqlexpression
# (default is false)
#filter=false
# comma separated list of strings to include
# please note that special characters escaping (used in java) has to be done for the provided regular expression
# (default is empty)
#include=
# comma separated list of strings to exclude
# (default is empty)
#exclude=
# sql expression to evaluate if using regex
# please note that special characters escaping (used in java) has to be done for the provided regular expression
# (default is empty)
#sqlexpression=
#list of categories to exclude: error, info, batch, debug, statement,
#commit, rollback, result and resultset are valid values
# (default is info,debug,result,resultset,batch)
#excludecategories=info,debug,result,resultset,batch
#whether the binary values (passed to DB or retrieved ones) should be logged with placeholder: [binary] or not.
# (default is false)
#excludebinary=false
# Execution threshold applies to the standard logging of P6Spy.
# While the standard logging logs out every statement
# regardless of its execution time, this feature puts a time
# condition on that logging. Only statements that have taken
# longer than the time specified (in milliseconds) will be
# logged. This way it is possible to see only statements that
# have exceeded some high water mark.
# This time is reloadable.
#
# executionThreshold=integer time (milliseconds)
# (default is 0)
#executionThreshold=
################################################################
# P6 OUTAGE SPECIFIC PROPERTIES #
################################################################
# Outage Detection
#
# This feature detects long-running statements that may be indicative of
# a database outage problem. If this feature is turned on, it will log any
# statement that surpasses the configurable time boundary during its execution.
# When this feature is enabled, no other statements are logged except the long
# running statements. The interval property is the boundary time set in seconds.
# For example, if this is set to 2, then any statement requiring at least 2
# seconds will be logged. Note that the same statement will continue to be logged
# for as long as it executes. So if the interval is set to 2, and the query takes
# 11 seconds, it will be logged 5 times (at the 2, 4, 6, 8, 10 second intervals).
#
# outagedetection=true|false
# outagedetectioninterval=integer time (seconds)
#
# (default is false)
#outagedetection=false
# (default is 60)
#outagedetectioninterval=30
Now lets run the integration test and we can now see P6Spy logging on one line SQL query, and parameter values. But we also see execution time, which is the second field.
1605965528692|0|commit|connection 0|url jdbc:p6spy:h2:mem:||
1605965528694|0|statement|connection 0|url jdbc:p6spy:h2:mem:|drop table User if exists|drop table User if exists
...
1605965528697|0|commit|connection 0|url jdbc:p6spy:h2:mem:||
1605965528705|7|statement|connection 0|url jdbc:p6spy:h2:mem:|create table User (id bigint generated by default as identity, created timestamp, name varchar(255), primary key (id))|create table User (id bigint generated by default as identity, created timestamp, name varchar(255), primary key (id))
...
1605965529531|1|statement|connection 0|url jdbc:p6spy:h2:mem:|insert into User (id, created, name) values (null, ?, ?)|insert into User (id, created, name) values (null, '2020-11-21T14:32:09.480+0100', 'Karin Nilsson')
...
1605965529540|0|commit|connection 0|url jdbc:p6spy:h2:mem:||
Now lets build a simple JAX-RS app and use P6Spy and MySQL Community Edition in JBoss EAP 7.3. How To Install MySQL Community Edition (CE) 8.0 on Fedora 32/31/30/29
After installing MySQL 8 CE we need to configure MySQL DataSource in EAP 7. First create folder and file jboss-eap-7.3.0/modules/com/mysql/main/module.xml. Then copy MySQL CE 8 JDBC Driver from above Maven dependency mysql:mysql-connector-java:8.0.17 to this folder. [1]
<?xml version="1.0" ?>
<module xmlns="urn:jboss:module:1.1" name="com.mysql">
<resources>
<resource-root path="mysql-connector-java-8.0.17.jar" />
</resources>
<dependencies>
<module name="javax.api" />
<module name="javax.transaction.api" />
</dependencies>
</module>
Then we also is going to need to add P6Spy as a EAP/Wildfly module. Create folder and file jboss-eap-7.3.0/modules/com/p6spy/main/module.xml and copy P6Spy from above maven dependency p6spy:p6spy:3.9.1. Note that we also add EAP module org.slf4j and com.mysql, since in production we do not want to log to standard out, but use a logging framework. We are going to use standard jboss logging, but we need the SLF4J logging API bridge.
<?xml version="1.0" ?>
<module xmlns="urn:jboss:module:1.1" name="com.p6spy">
<resources>
<resource-root path="p6spy-3.9.1.jar" />
</resources>
<dependencies>
<module name="javax.api" />
<module name="javax.transaction.api" />
<module name="org.slf4j"/>
<module name="com.mysql"/>
</dependencies>
</module>
Then we going to run EAP in standalone mode, so lets edit standalone.xml. Note that we need to add MySQL and P6Spy driver and in datasoruce connection-url and driver.
<subsystem xmlns="urn:jboss:domain:datasources:5.0">
<datasources>
...
<datasource jndi-name="java:jboss/datasources/MySQLDS" pool-name="MySQLDS" enabled="true" use-java-context="true" statistics-enabled="${wildfly.datasources.statistics-enabled:${wildfly.statistics-enabled:false}}">
<connection-url>jdbc:p6spy:mysql://localhost:3306/p6spy?serverTimezone=UTC</connection-url>
<driver>p6spy</driver>
<security>
<user-name>root</user-name>
<password>root</password>
</security>
<validation>
<valid-connection-checker class-name="org.jboss.jca.adapters.jdbc.extensions.mysql.MySQLValidConnectionChecker"/>
<validate-on-match>true</validate-on-match>
<background-validation>false</background-validation>
<exception-sorter class-name="org.jboss.jca.adapters.jdbc.extensions.mysql.MySQLExceptionSorter"/>
</validation>
</datasource>
<drivers>
...
<driver name="mysql" module="com.mysql">
<driver-class>com.mysql.cj.jdbc.Driver</driver-class>
<xa-datasource-class>com.mysql.cj.jdbc.MysqlXADataSource</xa-datasource-class>
</driver>
<driver name="p6spy" module="com.p6spy">
<driver-class>com.p6spy.engine.spy.P6SpyDriver</driver-class>
</driver>
</drivers>
</datasources>
</subsystem>
The final thing to do is to copy jboss-eap-7.3.0/bin/spy.properties. And change
appender=com.p6spy.engine.spy.appender.Slf4JLogger
#appender=com.p6spy.engine.spy.appender.StdoutLogger
#appender=com.p6spy.engine.spy.appender.FileLogger
Now when we run this and invoke our simple JAX-RS service from curl.
$ curl -v -X POST -H "Content-Type: application/json" -H "Accept: application/json" --data '{"name":"MY_NAME"}' http://localhost:8080/javaee8-p6spy/api/users
We see in server.log
2020-11-19 02:45:06,446 INFO [p6spy] (ServerService Thread Pool -- 82) 1605750306446|0|statement|connection 0|url jdbc:p6spy:mysql://localhost:3306/p6spy?serverTimezone=UTC|SELECT 1|SELECT 1
...
2020-11-19 02:45:06,497 INFO [p6spy] (ServerService Thread Pool -- 82) 1605750306497|0|statement|connection 0|url jdbc:p6spy:mysql://localhost:3306/p6spy?serverTimezone=UTC|SELECT 1|SELECT 1
...
2020-11-19 02:45:06,867 INFO [se.magnuskkarlsson.example.javaee8_p6spy.boundary.UserResource] (default task-1) Creating User [id=null, created=Thu Nov 19 02:45:06 CET 2020, name=MY_NAME] ...
2020-11-19 02:45:06,870 INFO [p6spy] (default task-1) 1605750306870|0|statement|connection 0|url jdbc:p6spy:mysql://localhost:3306/p6spy?serverTimezone=UTC|SELECT 1|SELECT 1
2020-11-19 02:45:06,873 INFO [p6spy] (default task-1) 1605750306873|0|statement|connection 0|url jdbc:p6spy:mysql://localhost:3306/p6spy?serverTimezone=UTC|insert into User (created, name) values (?, ?)|insert into User (created, name) values ('2020-11-19T02:45:06.816+0100', 'MY_NAME')
2020-11-19 02:45:06,874 INFO [se.magnuskkarlsson.example.javaee8_p6spy.boundary.UserResource] (default task-1) Created User [id=5, created=Thu Nov 19 02:45:06 CET 2020, name=MY_NAME].
2020-11-19 02:45:06,895 INFO [p6spy] (default task-1) 1605750306895|9|commit|connection 0|url jdbc:p6spy:mysql://localhost:3306/p6spy?serverTimezone=UTC||
...
Reference:
No comments:
Post a Comment