You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@sling.apache.org by di...@apache.org on 2022/12/14 08:55:43 UTC
[sling-org-apache-sling-models-impl] branch perf-logging created (now 9e7abde)
This is an automated email from the ASF dual-hosted git repository.
diru pushed a change to branch perf-logging
in repository https://gitbox.apache.org/repos/asf/sling-org-apache-sling-models-impl.git
at 9e7abde feat: add performance debug logging (wip)
This branch includes the following new commits:
new 9e7abde feat: add performance debug logging (wip)
The 1 revisions listed above as "new" are entirely new to this
repository and will be described in separate emails. The revisions
listed as "add" were already present in the repository and have only
been added to this reference.
[sling-org-apache-sling-models-impl] 01/01: feat: add performance debug logging (wip)
Posted by di...@apache.org.
This is an automated email from the ASF dual-hosted git repository.
diru pushed a commit to branch perf-logging
in repository https://gitbox.apache.org/repos/asf/sling-org-apache-sling-models-impl.git
commit 9e7abdeb784e3d3818ccbc09d58be52ad3332b30
Author: Dirk Rudolph <dr...@adobe.com>
AuthorDate: Wed Dec 14 09:55:32 2022 +0100
feat: add performance debug logging (wip)
---
.../sling/models/impl/ModelAdapterFactory.java | 38 ++++++++++++++++++----
.../sling/models/impl/ThreadInvocationCounter.java | 19 +++++++++++
2 files changed, 51 insertions(+), 6 deletions(-)
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 @@ public class ModelAdapterFactory implements AdapterFactory, Runnable, ModelFacto
}
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 @@ public class ModelAdapterFactory implements AdapterFactory, Runnable, ModelFacto
@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 @@ public class ModelAdapterFactory implements AdapterFactory, Runnable, ModelFacto
@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 @@ public class ModelAdapterFactory implements AdapterFactory, Runnable, ModelFacto
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 @@ public class ModelAdapterFactory implements AdapterFactory, Runnable, ModelFacto
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 @@ public class ModelAdapterFactory implements AdapterFactory, Runnable, ModelFacto
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 @@ public class ModelAdapterFactory implements AdapterFactory, Runnable, ModelFacto
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 @@ public class ModelAdapterFactory implements AdapterFactory, Runnable, ModelFacto
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 @@ package org.apache.sling.models.impl;
class ThreadInvocationCounter {
private int count;
+ private int max;
+ private int overallCount;
final int maxRecursionDepth;
@@ -28,12 +30,29 @@ class ThreadInvocationCounter {
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() {