Skip to content

Commit 6d60d45

Browse files
gavinkinggavinking
committed
more rationalization of TRACE-level logging
introduce SequenceGeneratorLogger + TableGeneratorLogger
1 parent a0017b3 commit 6d60d45

22 files changed

+258
-248
lines changed

‎hibernate-core/src/main/java/org/hibernate/action/internal/UnresolvedEntityInsertActions.java‎

Lines changed: 2 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,6 @@
77
import java.io.IOException;
88
import java.io.ObjectInputStream;
99
import java.io.ObjectOutputStream;
10-
import java.lang.invoke.MethodHandles;
1110
import java.util.IdentityHashMap;
1211
import java.util.Map;
1312
import java.util.Set;
@@ -21,10 +20,10 @@
2120
import org.hibernate.engine.spi.SharedSessionContractImplementor;
2221
import org.hibernate.engine.spi.Status;
2322
import org.hibernate.event.spi.EventSource;
23+
import org.hibernate.internal.CoreLogging;
2424
import org.hibernate.internal.CoreMessageLogger;
2525
import org.hibernate.internal.util.collections.IdentitySet;
2626

27-
import org.jboss.logging.Logger;
2827

2928
import static java.util.Collections.emptySet;
3029
import static org.hibernate.pretty.MessageHelper.infoString;
@@ -43,11 +42,7 @@
4342
* @author Gail Badner
4443
*/
4544
public class UnresolvedEntityInsertActions {
46-
private static final CoreMessageLogger LOG = Logger.getMessageLogger(
47-
MethodHandles.lookup(),
48-
CoreMessageLogger.class,
49-
UnresolvedEntityInsertActions.class.getName()
50-
);
45+
private static final CoreMessageLogger LOG = CoreLogging.messageLogger( UnresolvedEntityInsertActions.class );
5146

5247
private static final int INIT_SIZE = 5;
5348

‎hibernate-core/src/main/java/org/hibernate/boot/model/convert/internal/AttributeConverterManager.java‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -49,7 +49,7 @@ public RegisteredConversion findRegisteredConversion(Class<?> domainType) {
4949

5050
public void addConverter(ConverterDescriptor<?,?> descriptor) {
5151
if ( log.isTraceEnabled() ) {
52-
log.tracef( "Starting AttributeConverterManager#addConverter : `%s`",
52+
log.tracef( "Registering AttributeConverter '%s'",
5353
descriptor.getAttributeConverterClass().getName() );
5454
}
5555

@@ -59,7 +59,7 @@ public void addConverter(ConverterDescriptor<?,?> descriptor) {
5959
if ( registeredConversion != null ) {
6060
// we can skip registering the converter, the RegisteredConversion will always take precedence
6161
if ( log.isDebugEnabled() ) {
62-
log.debugf( "Skipping registration of discovered AttributeConverter `%s` for auto-apply",
62+
log.debugf( "Skipping registration of discovered AttributeConverter '%s' for auto-apply",
6363
descriptor.getAttributeConverterClass().getName() );
6464
}
6565
return;
@@ -114,7 +114,7 @@ public void addRegistration(RegisteredConversion conversion, BootstrapContext co
114114
if ( attributeConverterDescriptorsByClass != null ) {
115115
final var removed = attributeConverterDescriptorsByClass.remove( conversion.getConverterType() );
116116
if ( removed != null && log.isDebugEnabled() ) {
117-
log.debugf( "Removed potentially auto-applicable converter `%s` due to @ConverterRegistration",
117+
log.debugf( "Removed potentially auto-applicable converter '%s' due to @ConverterRegistration",
118118
removed.getAttributeConverterClass().getName() );
119119
}
120120
}

‎hibernate-core/src/main/java/org/hibernate/engine/jdbc/JdbcLogging.java‎

Lines changed: 22 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -21,6 +21,7 @@
2121
import java.lang.invoke.MethodHandles;
2222

2323
import static org.jboss.logging.Logger.Level.DEBUG;
24+
import static org.jboss.logging.Logger.Level.INFO;
2425
import static org.jboss.logging.Logger.Level.TRACE;
2526
import static org.jboss.logging.Logger.Level.WARN;
2627

@@ -139,7 +140,27 @@ public interface JdbcLogging extends BasicLogger {
139140
id = 100018)
140141
void logDriverInfo(String name, String version, int major, int minor, int jdbcMajor, int jdbcMinor);
141142

143+
@LogMessage(level = TRACE)
144+
@Message(value = "Unable to reset connection back to auto-commit", id = 100019)
145+
void unableToResetAutoCommit();
146+
147+
@LogMessage(level = INFO)
148+
@Message(value = "Unable to release isolated connection", id = 100020)
149+
void unableToReleaseIsolatedConnection(@Cause Throwable ignored);
150+
151+
@LogMessage(level = INFO)
152+
@Message(value = "Unable to roll back isolated connection on exception ", id = 100021)
153+
void unableToRollBackIsolatedConnection(@Cause Exception ignored);
154+
142155
@LogMessage(level = WARN)
143-
@Message(value = "Called joinTransaction() on a non-JTA EntityManager (ignoring)", id = 100020)
156+
@Message(value = "Called joinTransaction() on a non-JTA EntityManager (ignoring)", id = 100025)
144157
void callingJoinTransactionOnNonJtaEntityManager();
158+
159+
@LogMessage(level = TRACE)
160+
@Message(value = "Current timestamp retrieved from database: %s (nanos=%s, time=%s)", id = 100031)
161+
void currentTimestampRetrievedFromDatabase(Object timestamp, int nanos, long time);
162+
163+
@LogMessage(level = TRACE)
164+
@Message(value = "Sequence value retrieved from database: %s", id = 100032)
165+
void sequenceValueRetrievedFromDatabase(Number sequenceValue);
145166
}

‎hibernate-core/src/main/java/org/hibernate/engine/spi/CollectionEntry.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -261,7 +261,7 @@ public void afterAction(PersistentCollection<?> collection) {
261261
* Reset the stored snapshot for both the persistent collection and this collection entry.
262262
* Used during the merge of detached collections.
263263
*
264-
* @param collection the persistentcollection to be updated
264+
* @param collection the persistent collection to be updated
265265
* @param storedSnapshot the new stored snapshot
266266
*/
267267
public void resetStoredSnapshot(PersistentCollection<?> collection, Serializable storedSnapshot) {

‎hibernate-core/src/main/java/org/hibernate/generator/internal/CurrentTimestampGeneration.java‎

Lines changed: 10 additions & 45 deletions
Original file line numberDiff line numberDiff line change
@@ -216,24 +216,23 @@ static CurrentTimestampGeneratorDelegate getGeneratorDelegate(
216216
context.getDatabase().getDialect(),
217217
basicValue.getMetadata()
218218
);
219-
final Clock baseClock = context.getServiceRegistry()
220-
.requireService( ConfigurationService.class )
221-
.getSetting( CLOCK_SETTING_NAME, value -> (Clock) value );
219+
final Clock baseClock =
220+
context.getServiceRegistry().requireService( ConfigurationService.class )
221+
.getSetting( CLOCK_SETTING_NAME, value -> (Clock) value );
222222
final Key key = new Key( propertyType, baseClock, size.getPrecision() == null ? 0 : size.getPrecision() );
223223
final CurrentTimestampGeneratorDelegate delegate = GENERATOR_DELEGATES.get( key );
224224
if ( delegate != null ) {
225225
return delegate;
226226
}
227-
final BiFunction<@Nullable Clock, Integer, CurrentTimestampGeneratorDelegate> producer = GENERATOR_PRODUCERS.get( key.clazz );
227+
final var producer = GENERATOR_PRODUCERS.get( key.clazz );
228228
if ( producer == null ) {
229229
return null;
230230
}
231-
final CurrentTimestampGeneratorDelegate generatorDelegate = producer.apply( key.clock, key.precision );
232-
final CurrentTimestampGeneratorDelegate old = GENERATOR_DELEGATES.putIfAbsent(
233-
key,
234-
generatorDelegate
235-
);
236-
return old != null ? old : generatorDelegate;
231+
else {
232+
final var generatorDelegate = producer.apply( key.clock, key.precision );
233+
final var old = GENERATOR_DELEGATES.putIfAbsent( key, generatorDelegate );
234+
return old != null ? old : generatorDelegate;
235+
}
237236
case DB:
238237
return null;
239238
default:
@@ -280,40 +279,6 @@ interface CurrentTimestampGeneratorDelegate {
280279
Object generate();
281280
}
282281

283-
private static class Key {
284-
private final Class<?> clazz;
285-
private final @Nullable Clock clock;
286-
private final int precision;
287-
288-
public Key(Class<?> clazz, @Nullable Clock clock, int precision) {
289-
this.clazz = clazz;
290-
this.clock = clock;
291-
this.precision = precision;
292-
}
293-
294-
@Override
295-
public boolean equals(Object o) {
296-
if ( this == o ) {
297-
return true;
298-
}
299-
if ( o == null || getClass() != o.getClass() ) {
300-
return false;
301-
}
302-
303-
Key key = (Key) o;
304-
305-
if ( precision != key.precision ) {
306-
return false;
307-
}
308-
return clock == key.clock && clazz.equals( key.clazz );
309-
}
310-
311-
@Override
312-
public int hashCode() {
313-
int result = clazz.hashCode();
314-
result = 31 * result + ( clock == null ? 0 : clock.hashCode() );
315-
result = 31 * result + precision;
316-
return result;
317-
}
282+
private record Key(Class<?> clazz, @Nullable Clock clock, int precision) {
318283
}
319284
}

‎hibernate-core/src/main/java/org/hibernate/generator/internal/SourceGeneration.java‎

Lines changed: 4 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -15,12 +15,9 @@
1515
import org.hibernate.generator.EventTypeSets;
1616
import org.hibernate.generator.GeneratorCreationContext;
1717
import org.hibernate.generator.BeforeExecutionGenerator;
18-
import org.hibernate.internal.CoreMessageLogger;
1918
import org.hibernate.type.descriptor.java.JavaType;
2019

21-
import org.jboss.logging.Logger;
2220

23-
import java.lang.invoke.MethodHandles;
2421
import java.lang.reflect.Member;
2522
import java.sql.CallableStatement;
2623
import java.sql.PreparedStatement;
@@ -30,6 +27,7 @@
3027
import java.util.EnumSet;
3128

3229
import static java.sql.Types.TIMESTAMP;
30+
import static org.hibernate.engine.jdbc.JdbcLogging.JDBC_MESSAGE_LOGGER;
3331
import static org.hibernate.generator.EventTypeSets.INSERT_AND_UPDATE;
3432

3533
/**
@@ -52,12 +50,6 @@
5250
@Internal
5351
public class SourceGeneration implements BeforeExecutionGenerator {
5452

55-
private static final CoreMessageLogger log = Logger.getMessageLogger(
56-
MethodHandles.lookup(),
57-
CoreMessageLogger.class,
58-
SourceGeneration.class.getName()
59-
);
60-
6153
private final JavaType<?> propertyType;
6254
private final CurrentTimestampGeneration.CurrentTimestampGeneratorDelegate valueGenerator;
6355

@@ -97,7 +89,9 @@ private Timestamp getCurrentTimestamp(SharedSessionContractImplementor session)
9789
final Timestamp ts = callable
9890
? extractCalledResult( statement, coordinator, timestampSelectString )
9991
: extractResult( statement, coordinator, timestampSelectString );
100-
logResult( ts );
92+
if ( JDBC_MESSAGE_LOGGER.isTraceEnabled() ) {
93+
JDBC_MESSAGE_LOGGER.currentTimestampRetrievedFromDatabase( ts, ts.getNanos(), ts.getTime() );
94+
}
10195
return ts;
10296
}
10397
catch (SQLException e) {
@@ -130,14 +124,4 @@ private static Timestamp extractCalledResult(PreparedStatement statement, JdbcCo
130124
return callable.getTimestamp( 1 );
131125
}
132126

133-
private static void logResult(Timestamp ts) {
134-
if ( log.isTraceEnabled() ) {
135-
log.tracev(
136-
"Current timestamp retrieved from db : {0} (nanos={1}, time={2})",
137-
ts,
138-
ts.getNanos(),
139-
ts.getTime()
140-
);
141-
}
142-
}
143127
}

‎hibernate-core/src/main/java/org/hibernate/id/enhanced/HiLoOptimizer.java‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -75,7 +75,8 @@ public HiLoOptimizer(Class<?> returnClass, int incrementSize) {
7575
throw new HibernateException( "increment size cannot be less than 1" );
7676
}
7777
if ( log.isTraceEnabled() ) {
78-
log.tracev( "Creating hilo optimizer with [incrementSize={0}; returnClass={1}]", incrementSize, returnClass.getName() );
78+
log.tracev( "Creating hilo optimizer with [incrementSize={0}; returnClass={1}]",
79+
incrementSize, returnClass.getName() );
7980
}
8081
}
8182

‎hibernate-core/src/main/java/org/hibernate/id/enhanced/LegacyHiLoAlgorithmOptimizer.java‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -47,7 +47,8 @@ public LegacyHiLoAlgorithmOptimizer(Class<?> returnClass, int incrementSize) {
4747
throw new HibernateException( "increment size cannot be less than 1" );
4848
}
4949
if ( log.isTraceEnabled() ) {
50-
log.tracev( "Creating hilo optimizer (legacy) with [incrementSize={0}; returnClass={1}]", incrementSize, returnClass.getName() );
50+
log.tracev( "Creating hilo optimizer (legacy) with [incrementSize={0}; returnClass={1}]",
51+
incrementSize, returnClass.getName() );
5152
}
5253
initialMaxLo = incrementSize;
5354
}

‎hibernate-core/src/main/java/org/hibernate/id/enhanced/PooledOptimizer.java‎

Lines changed: 2 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -57,11 +57,8 @@ public PooledOptimizer(Class<?> returnClass, int incrementSize) {
5757
throw new HibernateException( "increment size cannot be less than 1" );
5858
}
5959
if ( log.isTraceEnabled() ) {
60-
log.tracev(
61-
"Creating pooled optimizer with [incrementSize={0}; returnClass={1}]",
62-
incrementSize,
63-
returnClass.getName()
64-
);
60+
log.tracev( "Creating pooled optimizer with [incrementSize={0}; returnClass={1}]",
61+
incrementSize, returnClass.getName() );
6562
}
6663
}
6764

‎hibernate-core/src/main/java/org/hibernate/id/enhanced/SequenceGeneratorLogger.java‎

Lines changed: 64 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,64 @@
1+
/*
2+
* SPDX-License-Identifier: Apache-2.0
3+
* Copyright Red Hat Inc. and Hibernate Authors
4+
*/
5+
package org.hibernate.id.enhanced;
6+
7+
import org.hibernate.Internal;
8+
import org.hibernate.internal.log.SubSystemLogging;
9+
import org.jboss.logging.BasicLogger;
10+
import org.jboss.logging.Logger;
11+
import org.jboss.logging.annotations.LogMessage;
12+
import org.jboss.logging.annotations.Message;
13+
import org.jboss.logging.annotations.MessageLogger;
14+
import org.jboss.logging.annotations.ValidIdRange;
15+
16+
import java.lang.invoke.MethodHandles;
17+
18+
import static org.jboss.logging.Logger.Level.INFO;
19+
import static org.jboss.logging.Logger.Level.WARN;
20+
21+
/**
22+
* Logging related to {@link TableGenerator} operations
23+
*
24+
* @author Gavin King
25+
*/
26+
@SubSystemLogging(
27+
name = SequenceGeneratorLogger.NAME,
28+
description = "Logging related to sequence-based identifier generation"
29+
)
30+
@MessageLogger(projectCode = "HHH")
31+
@ValidIdRange(min = 90201, max = 90300)
32+
@Internal
33+
public interface SequenceGeneratorLogger extends BasicLogger {
34+
String NAME = SubSystemLogging.BASE + ".id.table";
35+
36+
Logger SEQUENCE_GENERATOR_LOGGER = Logger.getLogger(NAME);
37+
SequenceGeneratorLogger SEQUENCE_GENERATOR_MESSAGE_LOGGER = Logger.getMessageLogger(
38+
MethodHandles.lookup(),
39+
SequenceGeneratorLogger.class,
40+
NAME
41+
);
42+
43+
@LogMessage(level = INFO)
44+
@Message(value = "Forcing table use for sequence-style generator due to pooled optimizer selection where db does not support pooled sequences",
45+
id = 90201)
46+
void forcingTableUse();
47+
48+
@LogMessage(level = WARN)
49+
@Message(value = "The increment size of the sequence '%s' is set to [%d] in the entity mapping while the associated database sequence increment size is [%d]"
50+
+ " - the database sequence increment size will take precedence to avoid identifier allocation conflicts.",
51+
id = 90202)
52+
void sequenceIncrementSizeMismatch(String sequenceName, int incrementSize, int databaseIncrementSize);
53+
54+
@LogMessage(level = WARN)
55+
@Message(value = "Sequence-style generator configuration specified explicit optimizer [%s], but [%s=%s]; using optimizer [%s] increment default of [%s]",
56+
id = 90203)
57+
void honoringOptimizerSetting(
58+
String none,
59+
String incrementParam,
60+
int incrementSize,
61+
String positiveOrNegative,
62+
int defaultIncrementSize);
63+
64+
}

0 commit comments

Comments
 (0)