feat: add performance debug logging (wip)
diff --git a/src/main/java/org/apache/sling/models/impl/ModelAdapterFactory.java b/src/main/java/org/apache/sling/models/impl/ModelAdapterFactory.java
index 1ecd7f7..c0a7b9d 100644
--- a/src/main/java/org/apache/sling/models/impl/ModelAdapterFactory.java
+++ b/src/main/java/org/apache/sling/models/impl/ModelAdapterFactory.java
@@ -203,6 +203,7 @@
}
private static final Logger log = LoggerFactory.getLogger(ModelAdapterFactory.class);
+ private static final Logger perfLog = LoggerFactory.getLogger(ModelAdapterFactory.class.getName() + "-perf");
private final ConcurrentMap<String, RankedServices<Injector>> injectors = new ConcurrentHashMap<>();
private final RankedServices<Injector> sortedInjectors = new RankedServices<>();
@@ -249,7 +250,7 @@
@Override
@SuppressWarnings("null")
public <AdapterType> AdapterType getAdapter(Object adaptable, Class<AdapterType> type) {
- Result<AdapterType> result = internalCreateModel(adaptable, type);
+ Result<AdapterType> result = internalCreateModelMeasured(adaptable, type);
if (!result.wasSuccessful()) {
if (result == Result.POST_CONSTRUCT_PREVENTED_MODEL_CONSTRUCTION) {
log.debug("Could not adapt to model as PostConstruct method returned false"); // do no construct runtime exception in this case
@@ -265,7 +266,7 @@
@Override
public @NotNull <ModelType> ModelType createModel(@NotNull Object adaptable, @NotNull Class<ModelType> type) throws MissingElementsException,
InvalidAdaptableException, ValidationException, InvalidModelException {
- Result<ModelType> result = internalCreateModel(adaptable, type);
+ Result<ModelType> result = internalCreateModelMeasured(adaptable, type);
if (!result.wasSuccessful()) {
throw result.getThrowable();
}
@@ -348,6 +349,31 @@
return adaptableCache;
}
+
+ private <ModelType> Result<ModelType> internalCreateModelMeasured(@NotNull Object adaptable, @NotNull Class<ModelType> type) {
+ Result<ModelType> result;
+ if (perfLog.isDebugEnabled()) {
+ long startTime = perfLog.isDebugEnabled() ? System.nanoTime() : -1;
+ ThreadInvocationCounter threadInvocationCounter = invocationCountThreadLocal.get();
+ threadInvocationCounter.resetStats();
+
+ result = internalCreateModel(adaptable, type);
+
+ double duration = ((double) System.nanoTime() - startTime) / 1000000.0;
+
+ perfLog.debug("createdModel({},{}) took {}ms, instantiations {}, max recursion {}",
+ adaptable.getClass().getName(),
+ type.getName(),
+ duration,
+ threadInvocationCounter.getOverallCount(),
+ threadInvocationCounter.getMaxRecursion());
+ } else {
+ result = internalCreateModel(adaptable, type);
+ }
+
+ return result;
+ }
+
@SuppressWarnings("unchecked")
<ModelType> Result<ModelType> internalCreateModel(final Object adaptable, final Class<ModelType> requestedType) {
Result<ModelType> result;
@@ -1304,7 +1330,7 @@
if (clazz == null) {
throw new ModelClassException("Could find model registered for resource type: " + resource.getResourceType());
}
- return handleBoundModelResult(internalCreateModel(resource, clazz));
+ return handleBoundModelResult(internalCreateModelMeasured(resource, clazz));
}
@Override
@@ -1313,7 +1339,7 @@
if (clazz == null) {
throw new ModelClassException("Could find model registered for request path: " + request.getServletPath());
}
- return handleBoundModelResult(internalCreateModel(request, clazz));
+ return handleBoundModelResult(internalCreateModelMeasured(request, clazz));
}
private Object handleBoundModelResult(Result<?> result) {
@@ -1344,7 +1370,7 @@
if (clazz == null) {
throw new ModelClassException("Could find model registered for resource type: " + resource.getResourceType());
}
- Result<?> result = internalCreateModel(resource, clazz);
+ Result<?> result = internalCreateModelMeasured(resource, clazz);
return handleAndExportResult(result, name, targetClass, options);
}
@@ -1355,7 +1381,7 @@
if (clazz == null) {
throw new ModelClassException("Could find model registered for request path: " + request.getServletPath());
}
- Result<?> result = internalCreateModel(request, clazz);
+ Result<?> result = internalCreateModelMeasured(request, clazz);
return handleAndExportResult(result, name, targetClass, options);
}
diff --git a/src/main/java/org/apache/sling/models/impl/ThreadInvocationCounter.java b/src/main/java/org/apache/sling/models/impl/ThreadInvocationCounter.java
index b386aa5..e1c454e 100644
--- a/src/main/java/org/apache/sling/models/impl/ThreadInvocationCounter.java
+++ b/src/main/java/org/apache/sling/models/impl/ThreadInvocationCounter.java
@@ -21,6 +21,8 @@
class ThreadInvocationCounter {
private int count;
+ private int max;
+ private int overallCount;
final int maxRecursionDepth;
@@ -28,12 +30,29 @@
this.maxRecursionDepth = maxRecursionDepth;
}
+ public void resetStats() {
+ max = 0;
+ overallCount = 0;
+ }
+
+ public int getMaxRecursion() {
+ return max;
+ }
+
+ public int getOverallCount() {
+ return overallCount;
+ }
+
public boolean isMaximumReached() {
return count >= maxRecursionDepth;
}
public void increase() {
this.count++;
+ this.overallCount++;
+ if (count > max) {
+ max = count;
+ }
}
public void decrease() {
