Add properties stats with durations to nodes and query stats

Change-Id: I269864b429c3ba0a73afc52b72b496ced9d6caab
diff --git a/src/main/java/com/googlesource/gerrit/plugins/task/StopWatch.java b/src/main/java/com/googlesource/gerrit/plugins/task/StopWatch.java
new file mode 100644
index 0000000..f7d36e7
--- /dev/null
+++ b/src/main/java/com/googlesource/gerrit/plugins/task/StopWatch.java
@@ -0,0 +1,82 @@
+// Copyright (C) 2022 The Android Open Source Project
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package com.googlesource.gerrit.plugins.task;
+
+import com.google.common.base.Stopwatch;
+import java.util.concurrent.TimeUnit;
+import java.util.function.LongConsumer;
+
+public class StopWatch {
+  protected Stopwatch stopwatch;
+  protected LongConsumer consumer;
+  protected long nanoseconds;
+
+  public StopWatch enableIfNonNull(Object statistics) {
+    if (statistics != null) {
+      enable();
+    }
+    return this;
+  }
+
+  public StopWatch enable() {
+    stopwatch = Stopwatch.createUnstarted();
+    return this;
+  }
+
+  public StopWatch run(Runnable runnable) {
+    start();
+    runnable.run();
+    stop();
+    return this;
+  }
+
+  public StopWatch start() {
+    if (stopwatch != null && !stopwatch.isRunning()) {
+      stopwatch.start();
+    }
+    return this;
+  }
+
+  public StopWatch stop() {
+    if (stopwatch != null && stopwatch.isRunning()) {
+      stopwatch.stop();
+      if (consumer != null) {
+        consume(consumer);
+      }
+    }
+    return this;
+  }
+
+  public StopWatch setConsumer(LongConsumer consumer) {
+    if (consumer != null) {
+      stopwatch = Stopwatch.createUnstarted();
+    }
+    this.consumer = consumer;
+    return this;
+  }
+
+  public StopWatch consume(LongConsumer consumer) {
+    if (stopwatch != null) {
+      consumer.accept(get());
+    }
+    return this;
+  }
+
+  public long get() {
+    nanoseconds += stopwatch.elapsed(TimeUnit.NANOSECONDS);
+    stopwatch.reset();
+    return nanoseconds;
+  }
+}
diff --git a/src/main/java/com/googlesource/gerrit/plugins/task/TaskAttributeFactory.java b/src/main/java/com/googlesource/gerrit/plugins/task/TaskAttributeFactory.java
index 65b53cb..414ca25 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/task/TaskAttributeFactory.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/task/TaskAttributeFactory.java
@@ -69,6 +69,7 @@
       public boolean isTaskRefreshNeeded;
       public Boolean hasUnfilterableSubNodes;
       public Object nodesByBranchCache;
+      public Object properties;
     }
 
     public Boolean applicable;
@@ -163,6 +164,7 @@
           statistics.numberOfDuplicates++;
         }
         attribute.statistics = new TaskAttribute.Statistics();
+        attribute.statistics.properties = node.propertiesStatistics;
       }
     }
 
diff --git a/src/main/java/com/googlesource/gerrit/plugins/task/TaskTree.java b/src/main/java/com/googlesource/gerrit/plugins/task/TaskTree.java
index 2f543bb..17b1a1b 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/task/TaskTree.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/task/TaskTree.java
@@ -72,6 +72,7 @@
     public Object definitionsPerSubSectionCache;
     public Object definitionsByBranchBySubSectionCache;
     public Object changesByNamesFactoryQueryCache;
+    public Properties.Statistics properties;
   }
 
   protected static final String TASK_DIR = "task";
@@ -232,6 +233,7 @@
     public Task task;
     public boolean isDuplicate;
 
+    protected Properties.Statistics propertiesStatistics;
     protected final Properties properties;
     protected final TaskKey taskKey;
     protected StatisticsMap<BranchNameKey, List<Node>> nodesByBranch;
@@ -277,10 +279,7 @@
 
     public List<Node> getApplicableSubNodes()
         throws ConfigInvalidException, IOException, StorageException {
-      if (hasUnfilterableSubNodes) {
-        return getSubNodes();
-      }
-      return new ApplicableNodeFilter().getSubNodes();
+      return hasUnfilterableSubNodes ? getSubNodes() : new ApplicableNodeFilter().getSubNodes();
     }
 
     @Override
@@ -304,6 +303,10 @@
       isDuplicate = path.contains(key);
       path.add(key);
 
+      if (statistics != null) {
+        properties.setStatisticsConsumer(
+            s -> statistics.properties = (propertiesStatistics = s).sum(statistics.properties));
+      }
       this.task = properties.getTask(getChangeData());
 
       this.duplicateKeys = new LinkedList<>(parent.duplicateKeys);
diff --git a/src/main/java/com/googlesource/gerrit/plugins/task/properties/AbstractExpander.java b/src/main/java/com/googlesource/gerrit/plugins/task/properties/AbstractExpander.java
index 3813319..c970cec 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/task/properties/AbstractExpander.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/task/properties/AbstractExpander.java
@@ -19,6 +19,7 @@
 import java.util.Collections;
 import java.util.List;
 import java.util.Set;
+import java.util.function.Consumer;
 import java.util.function.Function;
 
 /**
@@ -39,6 +40,12 @@
  * the name/value associations via the getValueForName() method.
  */
 public abstract class AbstractExpander {
+  protected Consumer<Matcher.Statistics> statisticsConsumer;
+
+  public void setStatisticsConsumer(Consumer<Matcher.Statistics> statisticsConsumer) {
+    this.statisticsConsumer = statisticsConsumer;
+  }
+
   /**
    * Returns expanded object if property found in the Strings in the object's Fields (except the
    * excluded ones). Returns same object if no expansions occurred.
@@ -134,6 +141,7 @@
       return null;
     }
     Matcher m = new Matcher(text);
+    m.setStatisticsConsumer(statisticsConsumer);
     if (!m.find()) {
       return text;
     }
diff --git a/src/main/java/com/googlesource/gerrit/plugins/task/properties/CopyOnWrite.java b/src/main/java/com/googlesource/gerrit/plugins/task/properties/CopyOnWrite.java
index 3e55158..7d94438 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/task/properties/CopyOnWrite.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/task/properties/CopyOnWrite.java
@@ -14,11 +14,13 @@
 
 package com.googlesource.gerrit.plugins.task.properties;
 
+import com.googlesource.gerrit.plugins.task.StopWatch;
 import java.lang.reflect.InvocationTargetException;
 import java.lang.reflect.Method;
 import java.util.Arrays;
 import java.util.Optional;
 import java.util.function.Function;
+import java.util.function.LongConsumer;
 
 public class CopyOnWrite<T> {
   public static class CloneOnWrite<C extends Cloneable> extends CopyOnWrite<C> {
@@ -67,6 +69,7 @@
   }
 
   protected Function<T, T> copier;
+  protected StopWatch stopWatch = new StopWatch();
   protected T original;
   protected T copy;
 
@@ -75,6 +78,10 @@
     this.copier = copier;
   }
 
+  protected void setNanosecondsConsumer(LongConsumer nanosConsumer) {
+    stopWatch.setConsumer(nanosConsumer);
+  }
+
   public T getOriginal() {
     return original;
   }
@@ -84,7 +91,10 @@
   }
 
   public T getForWrite() {
-    return copy = isCopy() ? copy : copier.apply(original);
+    if (!isCopy()) {
+      stopWatch.run(() -> copy = copier.apply(original));
+    }
+    return copy;
   }
 
   public boolean isCopy() {
diff --git a/src/main/java/com/googlesource/gerrit/plugins/task/properties/Matcher.java b/src/main/java/com/googlesource/gerrit/plugins/task/properties/Matcher.java
index abe203d..dc7bc18 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/task/properties/Matcher.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/task/properties/Matcher.java
@@ -14,26 +14,61 @@
 
 package com.googlesource.gerrit.plugins.task.properties;
 
+import com.googlesource.gerrit.plugins.task.StopWatch;
+import java.util.function.Consumer;
+
 /** A handcrafted properties Matcher which has an API similar to an RE Matcher, but is faster. */
 public class Matcher {
-  String text;
-  int start;
-  int nameStart;
-  int end;
-  int cursor;
+  public static class Statistics {
+    public long appendNanoseconds;
+    public long findNanoseconds;
+
+    public Statistics sum(Statistics other) {
+      if (other == null) {
+        return this;
+      }
+      Statistics statistics = new Statistics();
+      statistics.appendNanoseconds = appendNanoseconds + other.appendNanoseconds;
+      statistics.findNanoseconds = findNanoseconds + other.findNanoseconds;
+      return statistics;
+    }
+  }
+
+  protected String text;
+  protected int start;
+  protected int nameStart;
+  protected int end;
+  protected int cursor;
+
+  protected Statistics statistics;
+  protected StopWatch appendNanoseconds = new StopWatch();
+  protected StopWatch findNanoseconds = new StopWatch();
 
   public Matcher(String text) {
     this.text = text;
   }
 
+  protected void setStatisticsConsumer(Consumer<Statistics> statisticsConsumer) {
+    if (statisticsConsumer != null) {
+      statistics = new Statistics();
+      statisticsConsumer.accept(statistics);
+      appendNanoseconds.setConsumer(ns -> statistics.appendNanoseconds = ns);
+      findNanoseconds.setConsumer(ns -> statistics.findNanoseconds = ns);
+    }
+  }
+
   public boolean find() {
+    findNanoseconds.start();
     start = text.indexOf("${", cursor);
     nameStart = start + 2;
     if (start < 0 || text.length() < nameStart + 1) {
+      findNanoseconds.stop();
       return false;
     }
     end = text.indexOf('}', nameStart);
-    return end >= 0;
+    boolean found = end >= 0;
+    findNanoseconds.stop();
+    return found;
   }
 
   public String getName() {
@@ -41,17 +76,21 @@
   }
 
   public void appendValue(StringBuffer buffer, String value) {
+    appendNanoseconds.start();
     if (start > cursor) {
       buffer.append(text.substring(cursor, start));
     }
     buffer.append(value);
     cursor = end + 1;
+    appendNanoseconds.stop();
   }
 
   public void appendTail(StringBuffer buffer) {
+    appendNanoseconds.start();
     if (cursor < text.length()) {
       buffer.append(text.substring(cursor));
       cursor = text.length();
     }
+    appendNanoseconds.stop();
   }
 }
diff --git a/src/main/java/com/googlesource/gerrit/plugins/task/properties/Properties.java b/src/main/java/com/googlesource/gerrit/plugins/task/properties/Properties.java
index e13594a..5fc6c12 100644
--- a/src/main/java/com/googlesource/gerrit/plugins/task/properties/Properties.java
+++ b/src/main/java/com/googlesource/gerrit/plugins/task/properties/Properties.java
@@ -17,15 +17,36 @@
 import com.google.common.collect.ImmutableSet;
 import com.google.gerrit.exceptions.StorageException;
 import com.google.gerrit.server.query.change.ChangeData;
+import com.googlesource.gerrit.plugins.task.StopWatch;
 import com.googlesource.gerrit.plugins.task.TaskConfig;
 import com.googlesource.gerrit.plugins.task.TaskConfig.NamesFactory;
 import com.googlesource.gerrit.plugins.task.TaskConfig.Task;
 import com.googlesource.gerrit.plugins.task.TaskTree;
 import java.util.Map;
+import java.util.function.Consumer;
 import java.util.function.Function;
 
 /** Use to expand properties like ${_name} in the text of various definitions. */
 public class Properties {
+  public static class Statistics {
+    public long getTaskNanoseconds;
+    public long copierNanoseconds;
+    public Matcher.Statistics matcher;
+
+    public Statistics sum(Statistics other) {
+      if (other == null) {
+        return this;
+      }
+      Statistics statistics = new Statistics();
+      statistics.getTaskNanoseconds = getTaskNanoseconds + other.getTaskNanoseconds;
+      statistics.copierNanoseconds = copierNanoseconds + other.copierNanoseconds;
+      statistics.matcher = matcher == null ? other.matcher : matcher.sum(other.matcher);
+      return statistics;
+    }
+
+    protected StopWatch getTask;
+  }
+
   public static final Properties EMPTY =
       new Properties() {
         @Override
@@ -37,6 +58,9 @@
   public final Task origTask;
   protected final TaskTree.Node node;
   protected final CopyOnWrite<Task> task;
+  protected Statistics statistics;
+  protected Consumer<Statistics> statisticsConsumer;
+  protected Consumer<Matcher.Statistics> matcherStatisticsConsumer;
   protected Expander expander;
   protected Loader loader;
   protected boolean init = true;
@@ -57,8 +81,12 @@
 
   /** Use to expand properties specifically for Tasks. */
   public Task getTask(ChangeData changeData) throws StorageException {
+    if (statistics != null) {
+      statistics.getTask = new StopWatch().enable().start();
+    }
     loader = new Loader(origTask, changeData, getParentMapper());
     expander = new Expander(n -> loader.load(n));
+    expander.setStatisticsConsumer(matcherStatisticsConsumer);
     if (isTaskRefreshRequired || init) {
       expander.expand(task, TaskConfig.KEY_APPLICABLE);
       isApplicableRefreshRequired = loader.isNonTaskDefinedPropertyLoaded();
@@ -75,9 +103,23 @@
         isTaskRefreshRequired = loader.isNonTaskDefinedPropertyLoaded();
       }
     }
+    if (statisticsConsumer != null) {
+      statistics.getTaskNanoseconds = statistics.getTask.stop().get();
+      statistics.getTask = null;
+      statisticsConsumer.accept(statistics);
+    }
     return task.getForRead();
   }
 
+  public void setStatisticsConsumer(Consumer<Statistics> statisticsConsumer) {
+    if (statisticsConsumer != null) {
+      this.statisticsConsumer = statisticsConsumer;
+      statistics = new Statistics();
+      matcherStatisticsConsumer = s -> statistics.matcher = s;
+      task.setNanosecondsConsumer(ns -> statistics.copierNanoseconds = ns);
+    }
+  }
+
   // To detect NamesFactories dependent on non task defined properties, the checking must be
   // done after subnodes are fully loaded, which unfortunately happens after getTask() is
   // called, therefore this must be called after all subnodes have been loaded.