@Transactional annotation lead to a huge memory allocation during creation String representation of Method uses for logging only [SPR-16492]

[spring-projects-issues]

Alexander Fedorov opened SPR-16492 and commented

Hello Team,
we have faced a very intensive CPU consuming. One of the reason is very high GC activity.
GC activity could be splitted into two points:

1. minor GC collections which should be done very quickly in parallel
2. major GC collections ( FullGC ) which should be a rare case and should not lead to a long delay from app ( because FullGC is stop the world in our case ).

Minor GC could be tuned with help of investigating of memory allocation events inside new TLAB.
Major GC could be tuned with help of investigating of memory allocation events outside TLAB.

We use JMC and JFR API for aggregating memory allocation events.
It looks like

1. Memory allocation events inside new TLAB
   !allocation_inside_TLAB.jpg|thumbnail!

2. Memory allocation events outside TLAB
   !allocation_outside_TLAB.jpg|thumbnail!

Where higlighted categories are:

spring.cache_interceptor  org.springframework.cache.interceptor
spring.TransactionInterceptor.invoke org.springframework.transaction.interceptor.TransactionInterceptor.invoke()

Hotspots looks like:

!allocation_inside_TLAB_hotspots2.jpg|thumbnail!

Reg. to transaction we have same bad code that designed for logging that will never used:

package org.springframework.transaction.interceptor;

/** 
 * @author Rod Johnson
 * @author Juergen Hoeller
 * @since 1.1
 * @see #setTransactionManager
 * @see #setTransactionAttributes
 * @see #setTransactionAttributeSource
 */
public abstract class TransactionAspectSupport implements BeanFactoryAware, InitializingBean {


	/**
	 * General delegate for around-advice-based subclasses, delegating to several other template
	 * methods on this class. Able to handle {@link CallbackPreferringPlatformTransactionManager}
	 * as well as regular {@link PlatformTransactionManager} implementations.
	 * @param method the Method being invoked
	 * @param targetClass the target class that we're invoking the method on
	 * @param invocation the callback to use for proceeding with the target invocation
	 * @return the return value of the method, if any
	 * @throws Throwable propagated from the target invocation
	 */
	protected Object invokeWithinTransaction(Method method, Class<?> targetClass, final InvocationCallback invocation)
			throws Throwable {

		// If the transaction attribute is null, the method is non-transactional.
		final TransactionAttribute txAttr = getTransactionAttributeSource().getTransactionAttribute(method, targetClass);
		final PlatformTransactionManager tm = determineTransactionManager(txAttr);
		final String joinpointIdentification = methodIdentification(method, targetClass);

		if (txAttr == null || !(tm instanceof CallbackPreferringPlatformTransactionManager)) {
			// Standard transaction demarcation with getTransaction and commit/rollback calls.
			TransactionInfo txInfo = createTransactionIfNecessary(tm, txAttr, joinpointIdentification);
			Object retVal = null;
			try {
				// This is an around advice: Invoke the next interceptor in the chain.
				// This will normally result in a target object being invoked.
				retVal = invocation.proceedWithInvocation();
			}
			catch (Throwable ex) {
				// target invocation exception
				completeTransactionAfterThrowing(txInfo, ex);
				throw ex;
			}
			finally {
				cleanupTransactionInfo(txInfo);
			}
			commitTransactionAfterReturning(txInfo);
			return retVal;
		}

		else {
			// It's a CallbackPreferringPlatformTransactionManager: pass a TransactionCallback in.
			try {
				Object result = ((CallbackPreferringPlatformTransactionManager) tm).execute(txAttr,
						new TransactionCallback<Object>() {
							@Override
							public Object doInTransaction(TransactionStatus status) {
								TransactionInfo txInfo = prepareTransactionInfo(tm, txAttr, joinpointIdentification, status);
								try {
									return invocation.proceedWithInvocation();
								}
								catch (Throwable ex) {
									if (txAttr.rollbackOn(ex)) {
										// A RuntimeException: will lead to a rollback.
										if (ex instanceof RuntimeException) {
											throw (RuntimeException) ex;
										}
										else {
											throw new ThrowableHolderException(ex);
										}
									}
									else {
										// A normal return value: will lead to a commit.
										return new ThrowableHolder(ex);
									}
								}
								finally {
									cleanupTransactionInfo(txInfo);
								}
							}
						});

				// Check result: It might indicate a Throwable to rethrow.
				if (result instanceof ThrowableHolder) {
					throw ((ThrowableHolder) result).getThrowable();
				}
				else {
					return result;
				}
			}
			catch (ThrowableHolderException ex) {
				throw ex.getCause();
			}
		}
	}


	/**
	 * Convenience method to return a String representation of this Method
	 * for use in logging. Can be overridden in subclasses to provide a
	 * different identifier for the given method.
	 * @param method the method we're interested in
	 * @param targetClass the class that the method is being invoked on
	 * @return a String representation identifying this method
	 * @see org.springframework.util.ClassUtils#getQualifiedMethodName
	 */
	protected String methodIdentification(Method method, Class<?> targetClass) {
		String simpleMethodId = methodIdentification(method);
		if (simpleMethodId != null) {
			return simpleMethodId;
		}
		return (targetClass != null ? targetClass : method.getDeclaringClass()).getName() + "." + method.getName();
	}

	/**
	 * Convenience method to return a String representation of this Method
	 * for use in logging. Can be overridden in subclasses to provide a
	 * different identifier for the given method.
	 * @param method the method we're interested in
	 * @return a String representation identifying this method
	 * @deprecated in favor of {@link #methodIdentification(Method, Class)}
	 */
	@Deprecated
	protected String methodIdentification(Method method) {
		return null;
	}

	/**
	 * Create a transaction if necessary, based on the given method and class.
	 * <p>Performs a default TransactionAttribute lookup for the given method.
	 * @param method the method about to execute
	 * @param targetClass the class that the method is being invoked on
	 * @return a TransactionInfo object, whether or not a transaction was created.
	 * The {@code hasTransaction()} method on TransactionInfo can be used to
	 * tell if there was a transaction created.
	 * @see #getTransactionAttributeSource()
	 * @deprecated in favor of
	 * {@link #createTransactionIfNecessary(PlatformTransactionManager, TransactionAttribute, String)}
	 */
	@Deprecated
	protected TransactionInfo createTransactionIfNecessary(Method method, Class<?> targetClass) {
		// If the transaction attribute is null, the method is non-transactional.
		TransactionAttribute txAttr = getTransactionAttributeSource().getTransactionAttribute(method, targetClass);
		PlatformTransactionManager tm = determineTransactionManager(txAttr);
		return createTransactionIfNecessary(tm, txAttr, methodIdentification(method, targetClass));
	}

/**
	 * Create a transaction if necessary based on the given TransactionAttribute.
	 * <p>Allows callers to perform custom TransactionAttribute lookups through
	 * the TransactionAttributeSource.
	 * @param txAttr the TransactionAttribute (may be {@code null})
	 * @param joinpointIdentification the fully qualified method name
	 * (used for monitoring and logging purposes)
	 * @return a TransactionInfo object, whether or not a transaction was created.
	 * The {@code hasTransaction()} method on TransactionInfo can be used to
	 * tell if there was a transaction created.
	 * @see #getTransactionAttributeSource()
	 */
	@SuppressWarnings("serial")
	protected TransactionInfo createTransactionIfNecessary(
			PlatformTransactionManager tm, TransactionAttribute txAttr, final String joinpointIdentification) {

		// If no name specified, apply method identification as transaction name.
		if (txAttr != null && txAttr.getName() == null) {
			txAttr = new DelegatingTransactionAttribute(txAttr) {
				@Override
				public String getName() {
					return joinpointIdentification;
				}
			};
		}

		TransactionStatus status = null;
		if (txAttr != null) {
			if (tm != null) {
				status = tm.getTransaction(txAttr);
			}
			else {
				if (logger.isDebugEnabled()) {
					logger.debug("Skipping transactional joinpoint [" + joinpointIdentification +
							"] because no transaction manager has been configured");
				}
			}
		}
		return prepareTransactionInfo(tm, txAttr, joinpointIdentification, status);
	}

Simplest way is reimplement with wrapping into if (logger.isDebugEnabled()) { all code lines that related to created java objects ( including string ) for logging.

Attached my version of [^TransactionAspectSupport.java]

Main changes are:

protected String methodIdentification(Method method, Class<?> targetClass) {
     if (logger.isDebugEnabled()) {
          String simpleMethodId = methodIdentification(method);
          if (simpleMethodId != null) {
               return simpleMethodId;
          }
          return (targetClass != null ? targetClass : method.getDeclaringClass()).getName() + "." + method.getName();
     }
     return null;
}

I will pull request little bit later.
in progress..

---

Affects: 4.3.14

Attachments:

• allocation_inside_TLAB_hotspots2.jpg (77.72 kB)
• allocation_inside_TLAB.jpg (20.01 kB)
• allocation_outside_TLAB.jpg (20.90 kB)
• TransactionAspectSupport.java (25.79 kB)

Issue Links:

• #19326 Reduce String allocations in TransactionAspectSupport.methodIdentification() ("duplicates")
• #21033 @Cacheable annotation lead to a huge memory allocation from the side of OperationCache equals/hashCode

[spring-projects-issues]

Juergen Hoeller commented

Once again, this has been addressed in the 4.3.x line already: see #19326, available as of 4.3.4. We compute the method identifications upfront and store them in the cached transaction attribute objects.

[spring-projects-issues]

Alexander Fedorov commented

Hi Juergen Hoeller,

we ok with fix.

Thank you!