HHH-17073 Add PrePartialAutoFlush listeners

This commit is contained in:
Andrea Boriero 2024-02-28 16:43:32 +01:00 committed by Andrea Boriero
parent fe77bcfee9
commit e4e26ee989
10 changed files with 264 additions and 4 deletions

View File

@ -53,6 +53,9 @@ public interface SessionEventListener extends Serializable {
default void flushStart() {} default void flushStart() {}
default void flushEnd(int numberOfEntities, int numberOfCollections) {} default void flushEnd(int numberOfEntities, int numberOfCollections) {}
default void prePartialFlushStart(){}
default void prePartialFlushEnd(){}
default void partialFlushStart() {} default void partialFlushStart() {}
default void partialFlushEnd(int numberOfEntities, int numberOfCollections) {} default void partialFlushEnd(int numberOfEntities, int numberOfCollections) {}

View File

@ -229,6 +229,28 @@ public class SessionEventListenerManagerImpl implements SessionEventListenerMana
} }
} }
@Override
public void prePartialFlushStart() {
if ( listeners == null ) {
return;
}
for ( SessionEventListener listener : listeners ) {
listener.prePartialFlushStart();
}
}
@Override
public void prePartialFlushEnd() {
if ( listeners == null ) {
return;
}
for ( SessionEventListener listener : listeners ) {
listener.prePartialFlushEnd();
}
}
@Override @Override
public void partialFlushStart() { public void partialFlushStart() {
if ( listeners == null ) { if ( listeners == null ) {

View File

@ -63,6 +63,9 @@ public class StatisticalLoggingSessionEventListener extends BaseSessionEventList
private long partialFlushCollectionCount; private long partialFlushCollectionCount;
private long partialFlushTime; private long partialFlushTime;
private int prePartialFlushCount;
private long prePartialFlushTime;
// JDBC Connection acquisition ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // JDBC Connection acquisition ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
@ -237,6 +240,22 @@ public class StatisticalLoggingSessionEventListener extends BaseSessionEventList
// Partial-flushing ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ // Partial-flushing ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
private long partialFlushStart = -1; private long partialFlushStart = -1;
private long prePartialFlushStart = -1;
@Override
public void prePartialFlushStart() {
assert prePartialFlushStart < 0 : "Nested calls to prePartialFlushStart";
prePartialFlushStart = System.nanoTime();
}
@Override
public void prePartialFlushEnd() {
assert prePartialFlushStart > 0 : "Unexpected call to partialFlushEnd; expecting partialFlushStart";
prePartialFlushCount++;
prePartialFlushTime += ( System.nanoTime() - partialFlushStart );
prePartialFlushStart = -1;
}
@Override @Override
public void partialFlushStart() { public void partialFlushStart() {
@ -269,6 +288,7 @@ public class StatisticalLoggingSessionEventListener extends BaseSessionEventList
" %s nanoseconds spent performing %s L2C hits;\n" + " %s nanoseconds spent performing %s L2C hits;\n" +
" %s nanoseconds spent performing %s L2C misses;\n" + " %s nanoseconds spent performing %s L2C misses;\n" +
" %s nanoseconds spent executing %s flushes (flushing a total of %s entities and %s collections);\n" + " %s nanoseconds spent executing %s flushes (flushing a total of %s entities and %s collections);\n" +
" %s nanoseconds spent executing %s pre-partial-flushes;\n" +
" %s nanoseconds spent executing %s partial-flushes (flushing a total of %s entities and %s collections)\n" + " %s nanoseconds spent executing %s partial-flushes (flushing a total of %s entities and %s collections)\n" +
"}", "}",
jdbcConnectionAcquisitionTime, jdbcConnectionAcquisitionTime,
@ -291,6 +311,8 @@ public class StatisticalLoggingSessionEventListener extends BaseSessionEventList
flushCount, flushCount,
flushEntityCount, flushEntityCount,
flushCollectionCount, flushCollectionCount,
prePartialFlushTime,
prePartialFlushCount,
partialFlushTime, partialFlushTime,
partialFlushCount, partialFlushCount,
partialFlushEntityCount, partialFlushEntityCount,

View File

@ -93,9 +93,19 @@ public class DefaultAutoFlushEventListener extends AbstractFlushingEventListener
} }
@Override @Override
public void onAutoPreFlush(EventSource source) { public void onAutoPreFlush(EventSource source) throws HibernateException {
if ( flushMightBeNeeded( source ) ) { final SessionEventListenerManager eventListenerManager = source.getEventListenerManager();
preFlush( source, source.getPersistenceContextInternal() ); eventListenerManager.prePartialFlushStart();
final EventManager eventManager = source.getEventManager();
HibernateMonitoringEvent hibernateMonitoringEvent = eventManager.beginPrePartialFlush();
try {
if ( flushMightBeNeeded( source ) ) {
preFlush( source, source.getPersistenceContextInternal() );
}
}
finally {
eventManager.completePrePartialFlush( hibernateMonitoringEvent, source );
eventListenerManager.prePartialFlushEnd();
} }
} }

View File

@ -224,4 +224,16 @@ public final class EmptyEventManager implements EventManager {
int[] dirtyProperties) { int[] dirtyProperties) {
} }
@Override
public HibernateMonitoringEvent beginPrePartialFlush() {
return null;
}
@Override
public void completePrePartialFlush(
HibernateMonitoringEvent prePartialFlush,
SharedSessionContractImplementor session) {
}
} }

View File

@ -22,6 +22,6 @@ public interface AutoFlushEventListener {
*/ */
void onAutoFlush(AutoFlushEvent event) throws HibernateException; void onAutoFlush(AutoFlushEvent event) throws HibernateException;
default void onAutoPreFlush(EventSource source) { default void onAutoPreFlush(EventSource source) throws HibernateException {
} }
} }

View File

@ -155,6 +155,12 @@ public interface EventManager {
EntityEntry entry, EntityEntry entry,
int[] dirtyProperties); int[] dirtyProperties);
HibernateMonitoringEvent beginPrePartialFlush();
void completePrePartialFlush(
HibernateMonitoringEvent prePartialFlush,
SharedSessionContractImplementor session
);
enum CacheActionDescription { enum CacheActionDescription {
ENTITY_INSERT( "Entity Insert" ), ENTITY_INSERT( "Entity Insert" ),

View File

@ -43,6 +43,7 @@ public class JfrEventManager implements EventManager {
private static final EventType flushEventType = EventType.getEventType( FlushEvent.class ); private static final EventType flushEventType = EventType.getEventType( FlushEvent.class );
private static final EventType partialFlushEventType = EventType.getEventType( PartialFlushEvent.class ); private static final EventType partialFlushEventType = EventType.getEventType( PartialFlushEvent.class );
private static final EventType dirtyCalculationEventType = EventType.getEventType( DirtyCalculationEvent.class ); private static final EventType dirtyCalculationEventType = EventType.getEventType( DirtyCalculationEvent.class );
private static final EventType prePartialFlushEventType = EventType.getEventType( PrePartialFlushEvent.class );
@Override @Override
public SessionOpenEvent beginSessionOpenEvent() { public SessionOpenEvent beginSessionOpenEvent() {
@ -528,6 +529,34 @@ public class JfrEventManager implements EventManager {
} }
} }
@Override
public PrePartialFlushEvent beginPrePartialFlush() {
if ( prePartialFlushEventType.isEnabled() ) {
final PrePartialFlushEvent partialFlushEvent = new PrePartialFlushEvent();
partialFlushEvent.startedAt = System.nanoTime();
partialFlushEvent.begin();
return partialFlushEvent;
}
else {
return null;
}
}
@Override
public void completePrePartialFlush(
HibernateMonitoringEvent event,
SharedSessionContractImplementor session) {
if ( event != null ) {
final PrePartialFlushEvent prePartialFlushEvent = (PrePartialFlushEvent) event;
prePartialFlushEvent.end();
if ( prePartialFlushEvent.shouldCommit() ) {
prePartialFlushEvent.executionTime = getExecutionTime( prePartialFlushEvent.startedAt );
prePartialFlushEvent.sessionIdentifier = getSessionIdentifier( session );
prePartialFlushEvent.commit();
}
}
}
private long getExecutionTime(Long startTime) { private long getExecutionTime(Long startTime) {
return NANOSECONDS.convert( System.nanoTime() - startTime, NANOSECONDS ); return NANOSECONDS.convert( System.nanoTime() - startTime, NANOSECONDS );
} }

View File

@ -0,0 +1,40 @@
/*
* Hibernate, Relational Persistence for Idiomatic Java
*
* License: GNU Lesser General Public License (LGPL), version 2.1 or later.
* See the lgpl.txt file in the root directory or <http://www.gnu.org/licenses/lgpl-2.1.html>.
*/
package org.hibernate.event.jfr.internal;
import org.hibernate.event.spi.HibernateMonitoringEvent;
import org.hibernate.internal.build.AllowNonPortable;
import jdk.jfr.Category;
import jdk.jfr.Description;
import jdk.jfr.Event;
import jdk.jfr.Label;
import jdk.jfr.Name;
import jdk.jfr.StackTrace;
@Name( PrePartialFlushEvent.NAME )
@Label( "PrePartialFlushEvent Execution" )
@Category( "Hibernate ORM" )
@Description( "PrePartialFlushEvent Execution" )
@StackTrace(false)
@AllowNonPortable
public class PrePartialFlushEvent extends Event implements HibernateMonitoringEvent {
public static final String NAME = "org.hibernate.orm.PrePartialFlushEvent";
@Label("Session Identifier")
public String sessionIdentifier;
@Label("PrePartialFlushEvent time")
public long executionTime;
@Override
public String toString() {
return NAME;
}
public transient long startedAt;
}

View File

@ -0,0 +1,116 @@
package org.hibernate.event.jfr.flush;
import java.util.List;
import org.hibernate.event.jfr.internal.FlushEvent;
import org.hibernate.event.jfr.internal.PrePartialFlushEvent;
import org.hibernate.testing.orm.junit.DomainModel;
import org.hibernate.testing.orm.junit.SessionFactory;
import org.hibernate.testing.orm.junit.SessionFactoryScope;
import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.Test;
import jakarta.persistence.Entity;
import jakarta.persistence.Id;
import jdk.jfr.consumer.RecordedEvent;
import org.moditect.jfrunit.EnableEvent;
import org.moditect.jfrunit.JfrEventTest;
import org.moditect.jfrunit.JfrEvents;
import static org.assertj.core.api.Assertions.assertThat;
@JfrEventTest
@DomainModel(annotatedClasses = {
PrePartialFlushTest.TestEntity.class,
})
@SessionFactory
public class PrePartialFlushTest {
public JfrEvents jfrEvents = new JfrEvents();
@AfterEach
public void tearDown(SessionFactoryScope scope){
scope.inTransaction(
session -> {
session.createMutationQuery( "delete from TestEntity " ).executeUpdate();
}
);
}
@Test
@EnableEvent(PrePartialFlushEvent.NAME)
public void testPrePartialFlushEvent(SessionFactoryScope scope) {
jfrEvents.reset();
String sessionId = scope.fromTransaction(
session -> {
TestEntity entity = new TestEntity( 1, "name_1" );
session.persist( entity );
session.createQuery( "select t from TestEntity t" ).list();
return session.getSessionIdentifier().toString();
}
);
List<RecordedEvent> events = jfrEvents.events()
.filter(
recordedEvent ->
{
String eventName = recordedEvent.getEventType().getName();
return eventName.equals( PrePartialFlushEvent.NAME );
}
).toList();
assertThat( events ).hasSize( 1 );
RecordedEvent event = events.get( 0 );
assertThat( event.getEventType().getName() )
.isEqualTo( PrePartialFlushEvent.NAME );
assertThat( event.getLong( "executionTime" ) ).isGreaterThan( 0 );
assertThat( event.getString( "sessionIdentifier" ) )
.isEqualTo( sessionId );
}
@Test
@EnableEvent(PrePartialFlushEvent.NAME)
public void testPrePartialFlushEventNotTriggered(SessionFactoryScope scope) {
jfrEvents.reset();
String sessionId = scope.fromTransaction(
session -> {
TestEntity entity = new TestEntity( 1, "name_1" );
session.persist( entity );
return session.getSessionIdentifier().toString();
}
);
List<RecordedEvent> events = jfrEvents.events()
.filter(
recordedEvent ->
{
String eventName = recordedEvent.getEventType().getName();
return eventName.equals( PrePartialFlushEvent.NAME );
}
).toList();
assertThat( events ).hasSize( 0 );
}
@Entity(name = "TestEntity")
public static class TestEntity {
@Id
private Integer id;
private String name;
public TestEntity() {
}
public TestEntity(Integer id, String name) {
this.id = id;
this.name = name;
}
public void setName(String name) {
this.name = name;
}
}
}