Extended logging of JPA L2 cache usage with thread info. (#1065)
This commit contains extension to the EclipseLink logging to print information about persistence cache operations and usage.
It prints info when entity is stored, refreshed, removed, invalidated in the cache and info about cache hits/miss.
This feature is controlled by new "eclipselink.cache.extended.logging property" and generates messages at the FINEST log level.
It prints additional message if one thread stored item into cache and different picking item.
Signed-off-by: Radek Felcman <radek.felcman@oracle.com>
diff --git a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/config/PersistenceUnitProperties.java b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/config/PersistenceUnitProperties.java
index 191543b..310cb5c 100644
--- a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/config/PersistenceUnitProperties.java
+++ b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/config/PersistenceUnitProperties.java
@@ -1,6 +1,6 @@
/*
* Copyright (c) 1998, 2021 Oracle and/or its affiliates. All rights reserved.
- * Copyright (c) 1998, 2019 IBM Corporation. All rights reserved.
+ * Copyright (c) 1998, 2021 IBM Corporation. All rights reserved.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0 which is available at
@@ -1289,6 +1289,22 @@
*/
public static final String CACHE_TYPE_DEFAULT = CACHE_TYPE_ + DEFAULT;
+ /**
+ * The "<code>eclipselink.cache.extended.logging</code>" property control (enable/disable)
+ * usage logging of JPA L2 cache. In case of "<code>true</code>" EclipseLink generates messages into log output
+ * about cache hit/miss new object population and object removal or invalidation.
+ * This kind of messages will by displayed only if logging level (property "<code>eclipselink.logging.level</code>")
+ * is "<code>FINEST</code>"
+ * It displays Entity class, ID and thread info (ID, Name).
+ * <p>
+ * <b>Allowed Values:</b>
+ * <ul>
+ * <li>"<code>false</code>" (DEFAULT)
+ * <li>"<code>true</code>"
+ * </ul>
+ */
+ public static final String CACHE_EXTENDED_LOGGING = "eclipselink.cache.extended.logging";
+
/*
* NOTE: The Canonical Model properties should be kept in sync with those
* in org.eclipse.persistence.internal.jpa.modelgen.CanonicalModelProperties.
diff --git a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/descriptors/ObjectBuilder.java b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/descriptors/ObjectBuilder.java
index 6b7c38a..7f61824 100644
--- a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/descriptors/ObjectBuilder.java
+++ b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/descriptors/ObjectBuilder.java
@@ -1,6 +1,6 @@
/*
- * Copyright (c) 1998, 2019 Oracle and/or its affiliates. All rights reserved.
- * Copyright (c) 1998, 2018 IBM Corporation. All rights reserved.
+ * Copyright (c) 1998, 2021 Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 1998, 2021 IBM Corporation. All rights reserved.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0 which is available at
@@ -1185,7 +1185,9 @@
session.load(domainObject, group, query.getDescriptor(), false);
}
}
-
+ if (session.getProject().allowExtendedCacheLogging() && cacheKey != null && cacheKey.getObject() != null) {
+ session.log(SessionLog.FINEST, SessionLog.CACHE, "cache_item_creation", new Object[] {domainObject.getClass(), primaryKey, Thread.currentThread().getId(), Thread.currentThread().getName()});
+ }
if (returnCacheKey) {
return cacheKey;
} else {
@@ -1347,7 +1349,9 @@
if (!cacheHit) {
concreteDescriptor.getObjectBuilder().instantiateEagerMappings(protectedObject, session);
}
-
+ if (session.getProject().allowExtendedCacheLogging() && cacheKey != null && cacheKey.getObject() != null) {
+ session.log(SessionLog.FINEST, SessionLog.CACHE, "cache_item_creation", new Object[] {protectedObject.getClass(), primaryKey, Thread.currentThread().getId(), Thread.currentThread().getName()});
+ }
if (returnCacheKey) {
return cacheKey;
} else {
@@ -4430,6 +4434,9 @@
concreteDescriptor.getObjectBuilder().buildAttributesIntoObject(domainObject, cacheKey, databaseRow, query, joinManager, fetchGroup, true, session);
}
}
+ if (session.getProject().allowExtendedCacheLogging() && cacheKey != null && cacheKey.getObject() != null) {
+ session.log(SessionLog.FINEST, SessionLog.CACHE, "cache_item_refresh", new Object[] {domainObject.getClass(), cacheKey.getKey(), Thread.currentThread().getId(), Thread.currentThread().getName()});
+ }
return cacheHit;
}
diff --git a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/identitymaps/CacheKey.java b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/identitymaps/CacheKey.java
index 4c76af9..3001c04 100644
--- a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/identitymaps/CacheKey.java
+++ b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/identitymaps/CacheKey.java
@@ -1,5 +1,5 @@
/*
- * Copyright (c) 1998, 2020 Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 1998, 2021 Oracle and/or its affiliates. All rights reserved.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0 which is available at
@@ -31,6 +31,11 @@
*/
public class CacheKey extends ConcurrencyManager implements Cloneable {
+ //These constants are used in extended cache logging to compare cache item creation thread and thread which picking item from the cache
+ public final long CREATION_THREAD_ID = Thread.currentThread().getId();
+ public final String CREATION_THREAD_NAME = String.copyValueOf(Thread.currentThread().getName().toCharArray());
+ public final long CREATION_THREAD_HASHCODE = Thread.currentThread().hashCode();
+
/** The key holds the vector of primary key values for the object. */
protected Object key;
diff --git a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/identitymaps/IdentityMapManager.java b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/identitymaps/IdentityMapManager.java
index 08f9e5a..5f47d3d 100644
--- a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/identitymaps/IdentityMapManager.java
+++ b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/identitymaps/IdentityMapManager.java
@@ -1,6 +1,6 @@
/*
- * Copyright (c) 1998, 2019 Oracle and/or its affiliates. All rights reserved.
- * Copyright (c) 1998, 2018 IBM Corporation. All rights reserved.
+ * Copyright (c) 1998, 2021 Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 1998, 2021 IBM Corporation. All rights reserved.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0 which is available at
@@ -1508,6 +1508,9 @@
} else {
value = map.remove(key, objectToRemove);
}
+ if (session.getProject().allowExtendedCacheLogging()) {
+ session.log(SessionLog.FINEST, SessionLog.CACHE, "cache_item_removal", new Object[] {domainClass, key, Thread.currentThread().getId(), Thread.currentThread().getName()});
+ }
return value;
}
diff --git a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/localization/i18n/TraceLocalizationResource.java b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/localization/i18n/TraceLocalizationResource.java
index 1376c02..338001e 100644
--- a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/localization/i18n/TraceLocalizationResource.java
+++ b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/localization/i18n/TraceLocalizationResource.java
@@ -1,6 +1,6 @@
/*
* Copyright (c) 1998, 2021 Oracle and/or its affiliates. All rights reserved.
- * Copyright (c) 2017, 2020 IBM Corporation. All rights reserved.
+ * Copyright (c) 2017, 2021 IBM Corporation. All rights reserved.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0 which is available at
@@ -42,6 +42,14 @@
{ "initialize_identitymaps", "initialize identitymaps" },
{ "external_transaction_has_rolled_back_internally", "external transaction has rolled back internally" },
{ "validate_cache", "validate cache." },
+ { "cache_item_creation", "Entity ({0}) with Id ({1}) was stored in the cache by thread (Id: {2} Name: {3})" },
+ { "cache_item_refresh", "Entity ({0}) with Id ({1}) was refreshed in the cache by thread (Id: {2} Name: {3})" },
+ { "cache_item_removal", "Entity ({0}) with Id ({1}) was removed from the cache by thread (Id: {2} Name: {3})" },
+ { "cache_item_invalidation", "Entity ({0}) with Id ({1}) was invalidated from the cache by thread (Id: {2} Name: {3})" },
+ { "cache_class_invalidation", "Entities based on class ({0}) was invalidated from the cache by thread (Id: {1} Name: {2})" },
+ { "cache_hit", "Cache hit for entity ({0}) with Id ({1})" },
+ { "cache_miss", "Cache miss for entity ({0}) with Id ({1})" },
+ { "cache_thread_info", "Cached entity ({0}) with Id ({1}) was stored into cache by another thread (id: {2} name: {3}), than current thread (id: {4} name: {5})" },
{ "stack_of_visited_objects_that_refer_to_the_corrupt_object", "stack of visited objects that refer to the corrupt object: {0}" },
{ "corrupt_object_referenced_through_mapping", "corrupt object referenced through mapping: {0}" },
{ "corrupt_object", "corrupt object: {0}" },
diff --git a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/sessions/IdentityMapAccessor.java b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/sessions/IdentityMapAccessor.java
index a5eea4c..dd01e56 100644
--- a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/sessions/IdentityMapAccessor.java
+++ b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/sessions/IdentityMapAccessor.java
@@ -1,5 +1,5 @@
/*
- * Copyright (c) 1998, 2019 Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 1998, 2021 Oracle and/or its affiliates. All rights reserved.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0 which is available at
@@ -757,6 +757,9 @@
rcm.propagateCommand(command);
}
}
+ if (session.getProject().allowExtendedCacheLogging()) {
+ session.log(SessionLog.FINEST, SessionLog.CACHE, "cache_item_invalidation", new Object[] {theClass, primaryKey, Thread.currentThread().getId(), Thread.currentThread().getName()});
+ }
}
/**
@@ -864,6 +867,9 @@
}
}
invalidateQueryCache(myClass);
+ if (session.getProject().allowExtendedCacheLogging()) {
+ session.log(SessionLog.FINEST, SessionLog.CACHE, "cache_class_invalidation", new Object[] {myClass, Thread.currentThread().getId(), Thread.currentThread().getName()});
+ }
}
/**
diff --git a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/sessions/UnitOfWorkImpl.java b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/sessions/UnitOfWorkImpl.java
index 77bf6f8..7ad4536 100644
--- a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/sessions/UnitOfWorkImpl.java
+++ b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/internal/sessions/UnitOfWorkImpl.java
@@ -1,5 +1,5 @@
/*
- * Copyright (c) 1998, 2020 Oracle and/or its affiliates. All rights reserved.
+ * Copyright (c) 1998, 2021 Oracle and/or its affiliates. All rights reserved.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0 which is available at
@@ -4022,6 +4022,22 @@
if (descriptor.isDescriptorTypeAggregate()) {
throw ValidationException.cannotRegisterAggregateObjectInUnitOfWork(objectToRegister.getClass());
}
+ if (project.allowExtendedCacheLogging()) {
+ //Not null if objectToRegister exist in cache
+ CacheKey cacheKey = ((org.eclipse.persistence.internal.sessions.IdentityMapAccessor)this.getRootSession(null).getParent().getIdentityMapAccessor()).getCacheKeyForObject(objectToRegister);
+ Object objectToRegisterId = this.getId(objectToRegister);
+ if (cacheKey != null) {
+ log(SessionLog.FINEST, SessionLog.CACHE, "cache_hit", new Object[] {objectToRegister.getClass(), objectToRegisterId});
+ Thread currentThread = Thread.currentThread();
+ if (currentThread.hashCode() != cacheKey.CREATION_THREAD_HASHCODE) {
+ log(SessionLog.FINEST, SessionLog.CACHE, "cache_thread_info", new Object[]{objectToRegister.getClass(), objectToRegisterId,
+ cacheKey.CREATION_THREAD_ID, cacheKey.CREATION_THREAD_NAME,
+ currentThread.getId(), currentThread.getName()});
+ }
+ } else {
+ log(SessionLog.FINEST, SessionLog.CACHE, "cache_miss", new Object[] {objectToRegister.getClass(), objectToRegisterId});
+ }
+ }
//CR#2272
logDebugMessage(objectToRegister, "register_existing");
Object registeredObject;
diff --git a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/sessions/Project.java b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/sessions/Project.java
index 88ff19d..7af3db7 100644
--- a/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/sessions/Project.java
+++ b/foundation/org.eclipse.persistence.core/src/main/java/org/eclipse/persistence/sessions/Project.java
@@ -158,6 +158,9 @@
/** Flag that allows transform named stored procedure parameters into positional/index based */
protected boolean namingIntoIndexed = false;
+ /** Flag that allows extended logging of JPA L2 cache or not. */
+ protected boolean allowExtendedCacheLogging = false;
+
/**
* Mapped Superclasses (JPA 2) collection of parent non-relational descriptors keyed on MetadataClass
* without creating a compile time dependency on JPA.
@@ -1319,6 +1322,14 @@
}
/**
+ * INTERNAL:
+ * Return true if extended logging of JPA L2 cache usage is allowed on this project.
+ */
+ public boolean allowExtendedCacheLogging() {
+ return this.allowExtendedCacheLogging;
+ }
+
+ /**
* PUBLIC:
* Return the descriptor for the alias
*/
@@ -1375,6 +1386,14 @@
/**
* INTERNAL:
+ * Set whether extended logging of JPA L2 cache usage is allowed on this project.
+ */
+ public void setAllowExtendedCacheLogging(boolean allowExtendedCacheLogging) {
+ this.allowExtendedCacheLogging = allowExtendedCacheLogging;
+ }
+
+ /**
+ * INTERNAL:
* Indicates whether there is at least one descriptor that has at least on mapping that
* require a call on deleted objects to update change sets.
*/
diff --git a/jpa/org.eclipse.persistence.jpa/src/main/java/org/eclipse/persistence/internal/jpa/EntityManagerSetupImpl.java b/jpa/org.eclipse.persistence.jpa/src/main/java/org/eclipse/persistence/internal/jpa/EntityManagerSetupImpl.java
index bcc9500..e62cfa5 100644
--- a/jpa/org.eclipse.persistence.jpa/src/main/java/org/eclipse/persistence/internal/jpa/EntityManagerSetupImpl.java
+++ b/jpa/org.eclipse.persistence.jpa/src/main/java/org/eclipse/persistence/internal/jpa/EntityManagerSetupImpl.java
@@ -1,6 +1,6 @@
/*
* Copyright (c) 1998, 2021 Oracle and/or its affiliates. All rights reserved.
- * Copyright (c) 1998, 2019 IBM Corporation. All rights reserved.
+ * Copyright (c) 1998, 2021 IBM Corporation. All rights reserved.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License v. 2.0 which is available at
@@ -2892,6 +2892,7 @@
updateSQLCastSetting(m);
updateUppercaseSetting(m);
updateCacheStatementSettings(m);
+ updateAllowExtendedCacheLogging(m);
updateTemporalMutableSetting(m);
updateTableCreationSettings(m);
updateIndexForeignKeys(m);
@@ -3917,6 +3918,26 @@
}
/**
+ * Enable or disable extended logging of JPA L2 cache usage.
+ * The method needs to be called in deploy stage.
+ */
+ protected void updateAllowExtendedCacheLogging(Map m){
+ // Set allow native SQL queries flag if it was specified.
+ String allowExtendedCacheLogging = EntityManagerFactoryProvider.getConfigPropertyAsStringLogDebug(PersistenceUnitProperties.CACHE_EXTENDED_LOGGING, m, session);
+
+ if (allowExtendedCacheLogging != null) {
+ if (allowExtendedCacheLogging.equalsIgnoreCase("true")) {
+ session.getProject().setAllowExtendedCacheLogging(true);
+ } else if (allowExtendedCacheLogging.equalsIgnoreCase("false")) {
+ session.getProject().setAllowExtendedCacheLogging(false);
+ } else {
+ session.handleException(ValidationException.invalidBooleanValueForSettingAllowNativeSQLQueries(allowExtendedCacheLogging));
+ }
+ }
+ }
+
+
+ /**
* If Bean Validation is enabled, bootstraps Bean Validation on descriptors.
* @param puProperties merged properties for this persistence unit
*/
