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.version>5.3.14.Final</hibernate.version>
<hibernate-validator.version>6.0.18.Final</hibernate-validator.version>
<dependency>
<groupId>com.h2database</groupId>
<artifactId>h2</artifactId>
<version>1.4.199</version>
<scope>test</scope>
</dependency>
<dependency>
<groupId>mysql</groupId>
<artifactId>mysql-connector-java</artifactId>
<version>8.0.17</version>
<scope>test</scope>
</dependency>
<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>
<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="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"));
@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
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;
@Override
public String toString() {
return "User [id=" + id + ", created=" + created + ", name=" + name + "]";
}
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.
appender=com.p6spy.engine.spy.appender.StdoutLogger
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:
<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
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: