[sling-org-apache-sling-scripting-core] branch master updated: SLING-10584 log an info message if adding bindings takes more than 1 msec (#8)

[jo...@apache.org]

This is an automated email from the ASF dual-hosted git repository.

joerghoh pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/sling-org-apache-sling-scripting-core.git


The following commit(s) were added to refs/heads/master by this push:
     new fd44c75  SLING-10584 log an info message if adding bindings takes more than 1 msec (#8)
fd44c75 is described below

commit fd44c75af0083a78182bba53cb2b6d8a7d98a8dc
Author: Jörg Hoh <jo...@users.noreply.github.com>
AuthorDate: Wed Aug 4 10:18:25 2021 +0200

    SLING-10584 log an info message if adding bindings takes more than 1 msec (#8)
---
 .../sling/scripting/core/impl/DefaultSlingScript.java      | 12 ++++++++++++
 .../scripting/core/impl/bundled/ScriptContextProvider.java | 14 ++++++++++++++
 2 files changed, 26 insertions(+)

diff --git a/src/main/java/org/apache/sling/scripting/core/impl/DefaultSlingScript.java b/src/main/java/org/apache/sling/scripting/core/impl/DefaultSlingScript.java
index 519080d..f7cd274 100644
--- a/src/main/java/org/apache/sling/scripting/core/impl/DefaultSlingScript.java
+++ b/src/main/java/org/apache/sling/scripting/core/impl/DefaultSlingScript.java
@@ -89,6 +89,9 @@ class DefaultSlingScript implements SlingScript, Servlet, ServletConfig {
     /** The logger. */
     private static final Logger LOGGER = LoggerFactory.getLogger(DefaultSlingScript.class);
 
+    /** is defined on multiple files in this bundle*/
+    private static final long WARN_LIMIT_FOR_BVP_NANOS = (1000*1000); // 1 ms
+
     /** Thread local containing the resource resolver. */
     private static ThreadLocal<ResourceResolver> requestResourceResolver = new ThreadLocal<ResourceResolver>();
 
@@ -732,7 +735,16 @@ class DefaultSlingScript implements SlingScript, Servlet, ServletConfig {
 
             ProtectedBindings protectedBindings = new ProtectedBindings(bindings, protectedKeys);
             for (BindingsValuesProvider provider : bindingsValuesProviders) {
+                long start = System.nanoTime();
                 provider.addBindings(protectedBindings);
+                long stop = System.nanoTime();
+                LOGGER.trace("Invoking addBindings() of {} took {} nanoseconds",
+                        provider.getClass().getName(), stop-start);
+                if (stop-start > WARN_LIMIT_FOR_BVP_NANOS) {
+                    LOGGER.info("Adding the bindings of {} took {} microseconds which is above the harcoded limit of {} microseconds;"
+                            + " if this message appears often it indicates that this BindingsValuesProvider has an impact on general page rendering performance",
+                            new Object[]{provider.getClass().getName(), (stop-start)/1000, WARN_LIMIT_FOR_BVP_NANOS/1000});
+                }
             }
         }
 
diff --git a/src/main/java/org/apache/sling/scripting/core/impl/bundled/ScriptContextProvider.java b/src/main/java/org/apache/sling/scripting/core/impl/bundled/ScriptContextProvider.java
index c4612fd..4e8dd0d 100644
--- a/src/main/java/org/apache/sling/scripting/core/impl/bundled/ScriptContextProvider.java
+++ b/src/main/java/org/apache/sling/scripting/core/impl/bundled/ScriptContextProvider.java
@@ -62,6 +62,11 @@ import org.slf4j.LoggerFactory;
 )
 public class ScriptContextProvider implements BundleListener {
 
+    private static final Logger LOG = LoggerFactory.getLogger(ScriptContextProvider.class);
+
+    /** is defined on multiple files in this bundle*/
+    private static final long WARN_LIMIT_FOR_BVP_NANOS = (1000*1000); // 1 ms
+
     private static final Set<String> PROTECTED_BINDINGS = Collections.unmodifiableSet(new HashSet<>(Arrays.asList(
             SlingBindings.REQUEST,
             SlingBindings.RESPONSE,
@@ -117,7 +122,16 @@ public class ScriptContextProvider implements BundleListener {
         ProtectedBindings protectedBindings = new ProtectedBindings(bindings, PROTECTED_BINDINGS);
         for (BindingsValuesProvider bindingsValuesProvider : bvpTracker.getBindingsValuesProviders(scriptEngine.getFactory(),
                 BindingsValuesProvider.DEFAULT_CONTEXT)) {
+            long start = System.nanoTime();
             bindingsValuesProvider.addBindings(protectedBindings);
+            long stop = System.nanoTime();
+            LOG.trace("Invoking addBindings() of {} took {} nanoseconds",
+                    bindingsValuesProvider.getClass().getName(), stop-start);
+            if ((stop-start) > WARN_LIMIT_FOR_BVP_NANOS) {
+                LOG.info("Adding the bindings of {} took {} microseconds which is above the hardcoded limit of {} microseconds;"
+                        + " if this message appears often it indicates that this BindingsValuesProvider has an impact on general page rendering performance",
+                        new Object[]{bindingsValuesProvider.getClass().getName(), (stop-start)/1000, WARN_LIMIT_FOR_BVP_NANOS/1000});
+            }
         }
         ScriptContext scriptContext = new BundledScriptContext();
         Map<String, LazyBindings.Supplier> slingBindingsSuppliers = new HashMap<>();