From 26495fb6005ab2a6e3dbfd04d4eacd69ab8b6050 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Christian=20B=C3=BCrgi?= Date: Fri, 23 Aug 2024 23:14:28 +0200 Subject: [PATCH] HHH-18513 fix wrong prePartialFlush calculation in Session Metrics log --- ...tatisticalLoggingSessionEventListener.java | 4 +- ...sticalLoggingSessionEventListenerTest.java | 217 ++++++++++++++++++ 2 files changed, 219 insertions(+), 2 deletions(-) create mode 100644 hibernate-core/src/test/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListenerTest.java diff --git a/hibernate-core/src/main/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListener.java b/hibernate-core/src/main/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListener.java index 6b56f0fa11..433ec03aed 100644 --- a/hibernate-core/src/main/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListener.java +++ b/hibernate-core/src/main/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListener.java @@ -248,10 +248,10 @@ public class StatisticalLoggingSessionEventListener extends BaseSessionEventList @Override public void prePartialFlushEnd() { - assert prePartialFlushStart > 0 : "Unexpected call to partialFlushEnd; expecting partialFlushStart"; + assert prePartialFlushStart > 0 : "Unexpected call to prePartialFlushEnd; expecting prePartialFlushStart"; prePartialFlushCount++; - prePartialFlushTime += ( System.nanoTime() - partialFlushStart ); + prePartialFlushTime += ( System.nanoTime() - prePartialFlushStart ); prePartialFlushStart = -1; } diff --git a/hibernate-core/src/test/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListenerTest.java b/hibernate-core/src/test/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListenerTest.java new file mode 100644 index 0000000000..c87ec5b837 --- /dev/null +++ b/hibernate-core/src/test/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListenerTest.java @@ -0,0 +1,217 @@ +/* + * 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.engine.internal; + +import java.util.List; +import java.util.regex.Matcher; +import java.util.regex.Pattern; +import java.util.stream.Collectors; +import java.util.stream.Stream; + +import org.hibernate.cfg.AvailableSettings; +import org.hibernate.internal.CoreMessageLogger; + +import org.hibernate.testing.logger.LoggerInspectionRule; +import org.hibernate.testing.logger.Triggerable; +import org.hibernate.testing.orm.domain.gambit.BasicEntity; +import org.hibernate.testing.orm.junit.DomainModel; +import org.hibernate.testing.orm.junit.Jira; +import org.hibernate.testing.orm.junit.ServiceRegistry; +import org.hibernate.testing.orm.junit.SessionFactory; +import org.hibernate.testing.orm.junit.SessionFactoryScope; +import org.hibernate.testing.orm.junit.Setting; +import org.junit.Rule; +import org.junit.jupiter.api.Test; + +import org.jboss.logging.Logger; + +import static org.assertj.core.api.Assertions.assertThat; +import static org.junit.jupiter.api.Assertions.assertTrue; + +/** + * @author Christian Bürgi + */ +@DomainModel(annotatedClasses = { + BasicEntity.class +}) +@SessionFactory(generateStatistics = true) +@ServiceRegistry(settings = { + @Setting(name = AvailableSettings.STATEMENT_BATCH_SIZE, value = "10"), + @Setting(name = AvailableSettings.ORDER_INSERTS, value = "true"), + @Setting(name = AvailableSettings.USE_QUERY_CACHE, value = "true"), + @Setting(name = AvailableSettings.USE_SECOND_LEVEL_CACHE, value = "true") +}) +@Jira("https://hibernate.atlassian.net/browse/HHH-18513") +public class StatisticalLoggingSessionEventListenerTest { + + @Rule + public LoggerInspectionRule logInspection = new LoggerInspectionRule( + Logger.getMessageLogger( + CoreMessageLogger.class, + StatisticalLoggingSessionEventListener.class.getName() + ) ); + + @Test + void testSessionMetricsLog(SessionFactoryScope scope) { + Triggerable triggerable = logInspection.watchForLogMessages( "Session Metrics {" ); + long startTime = System.nanoTime(); + + scope.inTransaction( session -> { + session.persist( new BasicEntity( 1, "fooData" ) ); + session.persist( new BasicEntity( 2, "fooData2" ) ); + session.flush(); + session.clear(); + for ( int i = 0; i < 2; i++ ) { + assertThat( session.createQuery( "select data from BasicEntity e where e.id=1", String.class ) + .setCacheable( true ) + .getSingleResult() ).isEqualTo( "fooData" ); + } + } ); + long sessionNanoDuration = System.nanoTime() - startTime; + + List messages = triggerable.triggerMessages(); + assertThat( messages ).hasSize( 1 ); + String sessionMetricsLog = messages.get( 0 ); + + // acquiring JDBC connections + SessionMetric acquiringJdbcConnectionsMetric = extractMetric( + sessionMetricsLog, + "([0-9]+) nanoseconds spent acquiring ([0-9]+) JDBC connections" + ); + assertThat( acquiringJdbcConnectionsMetric.getDuration() ).isGreaterThan( 0L ) + .isLessThan( sessionNanoDuration ); + + // releasing JDBC connections + SessionMetric releasingJdbcConnectionsMetric = extractMetric( + sessionMetricsLog, + "([0-9]+) nanoseconds spent releasing ([0-9]+) JDBC connections" + ); + assertThat( releasingJdbcConnectionsMetric.getDuration() ).isGreaterThan( 0L ) + .isLessThan( sessionNanoDuration ); + + // preparing JDBC statements + SessionMetric preparingJdbcStatmentsMetric = extractMetric( + sessionMetricsLog, + "([0-9]+) nanoseconds spent preparing ([0-9]+) JDBC statements" + ); + assertThat( preparingJdbcStatmentsMetric.getDuration() ).isGreaterThan( 0L ) + .isLessThan( sessionNanoDuration ); + + // executing JDBC statements + SessionMetric executingJdbcStatmentsMetric = extractMetric( + sessionMetricsLog, + "([0-9]+) nanoseconds spent executing ([0-9]+) JDBC statements" + ); + assertThat( executingJdbcStatmentsMetric.getDuration() ).isGreaterThan( 0L ) + .isLessThan( sessionNanoDuration ); + + // executing JDBC batches + SessionMetric executingJdbcBatchesMetric = extractMetric( + sessionMetricsLog, + "([0-9]+) nanoseconds spent executing ([0-9]+) JDBC batches" + ); + assertThat( executingJdbcBatchesMetric.getDuration() ).isGreaterThan( 0L ) + .isLessThan( sessionNanoDuration ); + + // performing L2C puts + SessionMetric performingL2CPutsMetric = extractMetric( + sessionMetricsLog, + "([0-9]+) nanoseconds spent performing ([0-9]+) L2C puts" + ); + assertThat( performingL2CPutsMetric.getDuration() ).isGreaterThan( 0L ) + .isLessThan( sessionNanoDuration ); + + // performing L2C hits + SessionMetric performingL2CHitsMetric = extractMetric( + sessionMetricsLog, + "([0-9]+) nanoseconds spent performing ([0-9]+) L2C hits" + ); + assertThat( performingL2CHitsMetric.getDuration() ).isGreaterThan( 0L ) + .isLessThan( sessionNanoDuration ); + + // performing L2C misses + SessionMetric performingL2CMissesMetric = extractMetric( + sessionMetricsLog, + "([0-9]+) nanoseconds spent performing ([0-9]+) L2C misses" + ); + assertThat( performingL2CMissesMetric.getDuration() ).isGreaterThan( 0L ) + .isLessThan( sessionNanoDuration ); + + // executing flushes + SessionMetric executingFlushesMetric = extractMetric( + sessionMetricsLog, + "([0-9]+) nanoseconds spent executing ([0-9]+) flushes" + ); + assertThat( executingFlushesMetric.getDuration() ).isGreaterThan( 0L ) + .isLessThan( sessionNanoDuration ); + + // executing pre-partial-flushes + SessionMetric executingPrePartialFlushesMetric = extractMetric( + sessionMetricsLog, + "([0-9]+) nanoseconds spent executing ([0-9]+) pre-partial-flushes" + ); + assertThat( executingPrePartialFlushesMetric.getDuration() ).isGreaterThan( 0L ) + .isLessThan( sessionNanoDuration ); + + // executing partial-flushes + SessionMetric executingPartialFlushesMetric = extractMetric( + sessionMetricsLog, + "([0-9]+) nanoseconds spent executing ([0-9]+) partial-flushes" + ); + assertThat( executingPartialFlushesMetric.getDuration() ).isGreaterThan( 0L ) + .isLessThan( sessionNanoDuration ); + + // Number of metrics + List metricList = List.of( + acquiringJdbcConnectionsMetric, + releasingJdbcConnectionsMetric, + preparingJdbcStatmentsMetric, + executingJdbcStatmentsMetric, + executingJdbcBatchesMetric, + performingL2CPutsMetric, + performingL2CHitsMetric, + performingL2CMissesMetric, + executingFlushesMetric, + executingPrePartialFlushesMetric, + executingPartialFlushesMetric + ); + int numberOfMetrics = metricList.size(); + // Number of lines + assertThat( sessionMetricsLog.lines().count() ) + .as( "The StatisticalLoggingSessionEventListener should write a line per metric (" + + numberOfMetrics + " lines) plus a header and a footer (2 lines)" ) + .isEqualTo( numberOfMetrics + 2 ); + // Total time + long sumDuration = metricList.stream().map( SessionMetric::getDuration ).mapToLong( Long::longValue ).sum(); + assertThat( sumDuration ).isLessThanOrEqualTo( sessionNanoDuration ); + } + + private SessionMetric extractMetric(String logMessage, String regex) { + Pattern pattern = Pattern.compile( regex ); + Matcher matcher = pattern.matcher( logMessage ); + assertTrue( matcher.find() ); + return new SessionMetric( Long.parseLong( matcher.group( 1 ) ), Integer.parseInt( matcher.group( 2 ) ) ); + } + + private static class SessionMetric { + private final long duration; + private final int count; + + public SessionMetric(long duration, int count) { + this.duration = duration; + this.count = count; + } + + public long getDuration() { + return duration; + } + + public int getCount() { + return count; + } + } +}