Measure the execution time of your CronJobs

In SAP Commerce, it’s easy to see when a particular cron job was executed, what the status of the execution result is, and when the job finished. It’s also not that hard to determine the execution time of the job. To do that, you need to calculate this time yourself (extract the endTime from the startTime) and voila, you have your execution time. But wait, what if I want to know which jobs take too long to execute and which jobs run very fast? What is the trend of the execution time of a particular cron job? That’s what I’ll try to answer in this blog.

In the world of programming, of course, there are always several ways to solve problems. For this problem, we could have written some queries to get this information, but since our customer uses Datadog to monitor and analyse application performance, the first thing that came to mind was to send this information (execution time of the most important cron jobs) to Datadog and use the power of this tool to record information and create monitoring.

Use Aspect Oriented Programming (AOP)

Aspect-oriented programming (AOP) is a powerful paradigm that complements the traditional object-oriented (OO) approach to software design. It provides an elegant solution to cross cutting concerns, which isn’t the case with OO. It allows us to apply new behavior to classes in a flexible, declarative manner without touching the class itself.

With (AOP) integration in Spring, we can easily add aspects to Spring beans. In our case, we’ll add logging behaviour to some of our cron job classes.

AOP concepts and terminology

Before we get into the implementation details of our solution, let us first explain the basics of AOP and briefly review the concepts and terminology specific to AOP.

Aspect
This is a module that has a number of APIs providing cross-cutting requirements.

Advise
This is the actual action that is performed either before or after the method is executed. This is an actual piece of code that is called by the Spring AOP framework during program execution.

Join point
This is a point in your application where you can insert the AOP aspect. You can also say that this is the point in the application where an action is performed using the Spring AOP framework.

Pointcut
A pointcut is a specific connection point where an advice is applied. Example: All methods starting with get in classes belonging to package x.y.z.

Registering and using AOP Aspect

In the following few steps, I’ll show you how we can log the execution time of any method by using AOP.

Step 1: Create a custom annotation

First, create a marker annotation @Timeable. This annotation will be used later to hook around any method annotated with it.

[java]
package myextension.aop;

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Retention(RetentionPolicy.RUNTIME)
@Target(ElementType.METHOD)
public @interface Timeable {
String value();
}
[/java]

For each method annotated with @Timeable, the execution time is measured and logged. The value will be used in the log to expose the name of our cron job.

Step 2: Register the AOP Advice

In your extension-spring.xml add the following bean and AOP declarations.

[xml]
<alias name="defaultTimeableAdvise" alias="timeableAdvise" />
<bean id="defaultTimeableAdvise" class="myextension.aop.TimeableAdvise"/>

<aop:config proxy-target-class="true">
<aop:pointcut id="timeablePointCut" expression="@annotation(myextension.aop.Timeable)" />
<aop:aspect ref="defaultTimeableAdvise">
<aop:around pointcut-ref="timeablePointCut" method="logExecutionTime" />
</aop:aspect>
</aop:config>
[/xml]

We defined our AOP Advice and Around with a custom annotation (mycompany.aop.Timeable).

We could have also used an expression to call all cron jobs that extends a specific interface or base class. But in our case, we wanted to be flexible and let the developer decide for which methods he wants to measure the execution time by simply annotating a method with annotation @Timeable.

Here are some examples of common pointcut expressions that can be used.

Step 3: Make the execution of our Advice configurable

In your local.properties, add the following two properties:

[java]
measure.execution.time.enabled=true
measure.execution.time.threshold=30
[/java]

To be more flexible, we added two properties that can be configured and changed at runtime:
measure.execution.time.enabled: enables or disables measuring and logging of the execution time of a cron job.
measure.execution.time.threshold: a threshold in seconds. Execution times below this threshold will not be logged.

Step 4: create the Advice

Create TimeableAdvice and Around where we can hook on methods annotated with @Timeable.

TimeableAdvice is an Around Advice that contains the logic for measuring the execution time taken by the method.

[java]
package myextension.aop;

import com.google.common.base.Stopwatch;
import de.hybris.platform.util.Config;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.reflect.MethodSignature;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class TimeableAdvise {
private static final Logger log = LoggerFactory.getLogger(TimeableAdvise.class);

private static final String MEASURE_EXECUTION_TIME_ENABLED = "measure.execution.time.enabled";
private static final String MEASURE_EXECUTION_TIME_THRESHOLD = "measure.execution.time.threshold";

public Object logExecutionTime(ProceedingJoinPoint joinPoint) {
var signature = (MethodSignature) joinPoint.getSignature();
var method = signature.getMethod();
var annotation = method.getAnnotation(Timeable.class);

var stopwatch = Stopwatch.createStarted();

Object result = null;
try {
result = joinPoint.proceed();
if (isMeasurementEnabled(stopwatch)) {
log.info("Execution of [{}] took {}.", annotation.value(), stopwatch.stop());
}
} catch (Throwable e) {
log.error(e.getMessage(), e);
}

return result;
}

private boolean isMeasurementEnabled(Stopwatch stopwatch) {
return Config.getBoolean(MEASURE_EXECUTION_TIME_ENABLED, false)
&& stopwatch.elapsed().toSeconds() > Config.getLong(MEASURE_EXECUTION_TIME_THRESHOLD, 100);
}
}

[/java]

Step 5: use the Advice

To measure the execution time of a cron job, add the @Timeable annotation to the perform() method and voila. The Advice we’ve created in step 4 wil take care of measuring and logging the duration of our MyJobPerformable cron job.

[java]
public class MyJobPerformable extends AbstractJobPerformable<CronJobModel> {

@Override
@Timeable("My heavy Job")
public PerformResult perform(final CronJobModel cronJob) {
// your business logic here
return new PerformResult(CronJobResult.SUCCESS, CronJobStatus.FINISHED);
}
}
[/java]

See the execution time in Datadog

After the application has been running for a while, the logs are displayed in Datadog for all jobs annotated with @Timeable. From here we can quickly spot the jobs that take a lot of time if we want to. In Datadog we can also configure alerts when certain jobs take more than the expected time to run.

Conclusion

We have seen how easy it is to create an Advise and measure the execution time of a particular method by just adding one annotation or without touching the methods we want the execution time to be measured. You can visit this page for more information about using AOP in SAP Commerce and this page for an extended documentation about Aspect Oriented Programming with Spring.