Skip to content

Commit 4119e44

Browse files
boskoopdreab8
boskoop
authored and
dreab8
committed
HHH-18513 fix wrong prePartialFlush calculation in Session Metrics log
1 parent 8870ab8 commit 4119e44

File tree

2 files changed

+219
-2
lines changed

2 files changed

+219
-2
lines changed

‎hibernate-core/src/main/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListener.java‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -250,10 +250,10 @@ public void prePartialFlushStart() {
250250

251251
@Override
252252
public void prePartialFlushEnd() {
253-
assert prePartialFlushStart > 0 : "Unexpected call to partialFlushEnd; expecting partialFlushStart";
253+
assert prePartialFlushStart > 0 : "Unexpected call to prePartialFlushEnd; expecting prePartialFlushStart";
254254

255255
prePartialFlushCount++;
256-
prePartialFlushTime += ( System.nanoTime() - partialFlushStart );
256+
prePartialFlushTime += ( System.nanoTime() - prePartialFlushStart );
257257
prePartialFlushStart = -1;
258258
}
259259

‎hibernate-core/src/test/java/org/hibernate/engine/internal/StatisticalLoggingSessionEventListenerTest.java‎

Lines changed: 217 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,217 @@
1+
/*
2+
* Hibernate, Relational Persistence for Idiomatic Java
3+
*
4+
* License: GNU Lesser General Public License (LGPL), version 2.1 or later
5+
* See the lgpl.txt file in the root directory or http://www.gnu.org/licenses/lgpl-2.1.html
6+
*/
7+
package org.hibernate.engine.internal;
8+
9+
import java.util.List;
10+
import java.util.regex.Matcher;
11+
import java.util.regex.Pattern;
12+
import java.util.stream.Collectors;
13+
import java.util.stream.Stream;
14+
15+
import org.hibernate.cfg.AvailableSettings;
16+
import org.hibernate.internal.CoreMessageLogger;
17+
18+
import org.hibernate.testing.logger.LoggerInspectionRule;
19+
import org.hibernate.testing.logger.Triggerable;
20+
import org.hibernate.testing.orm.domain.gambit.BasicEntity;
21+
import org.hibernate.testing.orm.junit.DomainModel;
22+
import org.hibernate.testing.orm.junit.Jira;
23+
import org.hibernate.testing.orm.junit.ServiceRegistry;
24+
import org.hibernate.testing.orm.junit.SessionFactory;
25+
import org.hibernate.testing.orm.junit.SessionFactoryScope;
26+
import org.hibernate.testing.orm.junit.Setting;
27+
import org.junit.Rule;
28+
import org.junit.jupiter.api.Test;
29+
30+
import org.jboss.logging.Logger;
31+
32+
import static org.assertj.core.api.Assertions.assertThat;
33+
import static org.junit.jupiter.api.Assertions.assertTrue;
34+
35+
/**
36+
* @author Christian Bürgi
37+
*/
38+
@DomainModel(annotatedClasses = {
39+
BasicEntity.class
40+
})
41+
@SessionFactory(generateStatistics = true)
42+
@ServiceRegistry(settings = {
43+
@Setting(name = AvailableSettings.STATEMENT_BATCH_SIZE, value = "10"),
44+
@Setting(name = AvailableSettings.ORDER_INSERTS, value = "true"),
45+
@Setting(name = AvailableSettings.USE_QUERY_CACHE, value = "true"),
46+
@Setting(name = AvailableSettings.USE_SECOND_LEVEL_CACHE, value = "true")
47+
})
48+
@Jira("https://hibernate.atlassian.net/browse/HHH-18513")
49+
public class StatisticalLoggingSessionEventListenerTest {
50+
51+
@Rule
52+
public LoggerInspectionRule logInspection = new LoggerInspectionRule(
53+
Logger.getMessageLogger(
54+
CoreMessageLogger.class,
55+
StatisticalLoggingSessionEventListener.class.getName()
56+
) );
57+
58+
@Test
59+
void testSessionMetricsLog(SessionFactoryScope scope) {
60+
Triggerable triggerable = logInspection.watchForLogMessages( "Session Metrics {" );
61+
long startTime = System.nanoTime();
62+
63+
scope.inTransaction( session -> {
64+
session.persist( new BasicEntity( 1, "fooData" ) );
65+
session.persist( new BasicEntity( 2, "fooData2" ) );
66+
session.flush();
67+
session.clear();
68+
for ( int i = 0; i < 2; i++ ) {
69+
assertThat( session.createQuery( "select data from BasicEntity e where e.id=1", String.class )
70+
.setCacheable( true )
71+
.getSingleResult() ).isEqualTo( "fooData" );
72+
}
73+
} );
74+
long sessionNanoDuration = System.nanoTime() - startTime;
75+
76+
List<String> messages = triggerable.triggerMessages();
77+
assertThat( messages ).hasSize( 1 );
78+
String sessionMetricsLog = messages.get( 0 );
79+
80+
// acquiring JDBC connections
81+
SessionMetric acquiringJdbcConnectionsMetric = extractMetric(
82+
sessionMetricsLog,
83+
"([0-9]+) nanoseconds spent acquiring ([0-9]+) JDBC connections"
84+
);
85+
assertThat( acquiringJdbcConnectionsMetric.getDuration() ).isGreaterThan( 0L )
86+
.isLessThan( sessionNanoDuration );
87+
88+
// releasing JDBC connections
89+
SessionMetric releasingJdbcConnectionsMetric = extractMetric(
90+
sessionMetricsLog,
91+
"([0-9]+) nanoseconds spent releasing ([0-9]+) JDBC connections"
92+
);
93+
assertThat( releasingJdbcConnectionsMetric.getDuration() ).isGreaterThan( 0L )
94+
.isLessThan( sessionNanoDuration );
95+
96+
// preparing JDBC statements
97+
SessionMetric preparingJdbcStatmentsMetric = extractMetric(
98+
sessionMetricsLog,
99+
"([0-9]+) nanoseconds spent preparing ([0-9]+) JDBC statements"
100+
);
101+
assertThat( preparingJdbcStatmentsMetric.getDuration() ).isGreaterThan( 0L )
102+
.isLessThan( sessionNanoDuration );
103+
104+
// executing JDBC statements
105+
SessionMetric executingJdbcStatmentsMetric = extractMetric(
106+
sessionMetricsLog,
107+
"([0-9]+) nanoseconds spent executing ([0-9]+) JDBC statements"
108+
);
109+
assertThat( executingJdbcStatmentsMetric.getDuration() ).isGreaterThan( 0L )
110+
.isLessThan( sessionNanoDuration );
111+
112+
// executing JDBC batches
113+
SessionMetric executingJdbcBatchesMetric = extractMetric(
114+
sessionMetricsLog,
115+
"([0-9]+) nanoseconds spent executing ([0-9]+) JDBC batches"
116+
);
117+
assertThat( executingJdbcBatchesMetric.getDuration() ).isGreaterThan( 0L )
118+
.isLessThan( sessionNanoDuration );
119+
120+
// performing L2C puts
121+
SessionMetric performingL2CPutsMetric = extractMetric(
122+
sessionMetricsLog,
123+
"([0-9]+) nanoseconds spent performing ([0-9]+) L2C puts"
124+
);
125+
assertThat( performingL2CPutsMetric.getDuration() ).isGreaterThan( 0L )
126+
.isLessThan( sessionNanoDuration );
127+
128+
// performing L2C hits
129+
SessionMetric performingL2CHitsMetric = extractMetric(
130+
sessionMetricsLog,
131+
"([0-9]+) nanoseconds spent performing ([0-9]+) L2C hits"
132+
);
133+
assertThat( performingL2CHitsMetric.getDuration() ).isGreaterThan( 0L )
134+
.isLessThan( sessionNanoDuration );
135+
136+
// performing L2C misses
137+
SessionMetric performingL2CMissesMetric = extractMetric(
138+
sessionMetricsLog,
139+
"([0-9]+) nanoseconds spent performing ([0-9]+) L2C misses"
140+
);
141+
assertThat( performingL2CMissesMetric.getDuration() ).isGreaterThan( 0L )
142+
.isLessThan( sessionNanoDuration );
143+
144+
// executing flushes
145+
SessionMetric executingFlushesMetric = extractMetric(
146+
sessionMetricsLog,
147+
"([0-9]+) nanoseconds spent executing ([0-9]+) flushes"
148+
);
149+
assertThat( executingFlushesMetric.getDuration() ).isGreaterThan( 0L )
150+
.isLessThan( sessionNanoDuration );
151+
152+
// executing pre-partial-flushes
153+
SessionMetric executingPrePartialFlushesMetric = extractMetric(
154+
sessionMetricsLog,
155+
"([0-9]+) nanoseconds spent executing ([0-9]+) pre-partial-flushes"
156+
);
157+
assertThat( executingPrePartialFlushesMetric.getDuration() ).isGreaterThan( 0L )
158+
.isLessThan( sessionNanoDuration );
159+
160+
// executing partial-flushes
161+
SessionMetric executingPartialFlushesMetric = extractMetric(
162+
sessionMetricsLog,
163+
"([0-9]+) nanoseconds spent executing ([0-9]+) partial-flushes"
164+
);
165+
assertThat( executingPartialFlushesMetric.getDuration() ).isGreaterThan( 0L )
166+
.isLessThan( sessionNanoDuration );
167+
168+
// Number of metrics
169+
List<SessionMetric> metricList = List.of(
170+
acquiringJdbcConnectionsMetric,
171+
releasingJdbcConnectionsMetric,
172+
preparingJdbcStatmentsMetric,
173+
executingJdbcStatmentsMetric,
174+
executingJdbcBatchesMetric,
175+
performingL2CPutsMetric,
176+
performingL2CHitsMetric,
177+
performingL2CMissesMetric,
178+
executingFlushesMetric,
179+
executingPrePartialFlushesMetric,
180+
executingPartialFlushesMetric
181+
);
182+
int numberOfMetrics = metricList.size();
183+
// Number of lines
184+
assertThat( sessionMetricsLog.lines().count() )
185+
.as( "The StatisticalLoggingSessionEventListener should write a line per metric ("
186+
+ numberOfMetrics + " lines) plus a header and a footer (2 lines)" )
187+
.isEqualTo( numberOfMetrics + 2 );
188+
// Total time
189+
long sumDuration = metricList.stream().map( SessionMetric::getDuration ).mapToLong( Long::longValue ).sum();
190+
assertThat( sumDuration ).isLessThanOrEqualTo( sessionNanoDuration );
191+
}
192+
193+
private SessionMetric extractMetric(String logMessage, String regex) {
194+
Pattern pattern = Pattern.compile( regex );
195+
Matcher matcher = pattern.matcher( logMessage );
196+
assertTrue( matcher.find() );
197+
return new SessionMetric( Long.parseLong( matcher.group( 1 ) ), Integer.parseInt( matcher.group( 2 ) ) );
198+
}
199+
200+
private static class SessionMetric {
201+
private final long duration;
202+
private final int count;
203+
204+
public SessionMetric(long duration, int count) {
205+
this.duration = duration;
206+
this.count = count;
207+
}
208+
209+
public long getDuration() {
210+
return duration;
211+
}
212+
213+
public int getCount() {
214+
return count;
215+
}
216+
}
217+
}

0 commit comments

Comments
 (0)