[lucene-solr] 01/17: added logging support

[is...@apache.org]

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

ishan pushed a commit to branch prs-perf-test
in repository https://gitbox.apache.org/repos/asf/lucene-solr.git

commit 807dc03078f9b39bb45445c62a5f85039c9fbda7
Author: noblepaul <no...@gmail.com>
AuthorDate: Fri Feb 5 20:30:11 2021 +1100

    added logging support
---
 .../cloud/api/collections/CreateCollectionCmd.java | 56 +++++++++----
 .../solr/handler/admin/ContainerPluginsApi.java    |  8 ++
 .../org/apache/solr/common/cloud/WaitTime.java     | 96 ++++++++++++++++++++++
 3 files changed, 143 insertions(+), 17 deletions(-)

diff --git a/solr/core/src/java/org/apache/solr/cloud/api/collections/CreateCollectionCmd.java b/solr/core/src/java/org/apache/solr/cloud/api/collections/CreateCollectionCmd.java
index a9299cc..0582429 100644
--- a/solr/core/src/java/org/apache/solr/cloud/api/collections/CreateCollectionCmd.java
+++ b/solr/core/src/java/org/apache/solr/cloud/api/collections/CreateCollectionCmd.java
@@ -53,6 +53,7 @@ import org.apache.solr.common.cloud.DocRouter;
 import org.apache.solr.common.cloud.ImplicitDocRouter;
 import org.apache.solr.common.cloud.Replica;
 import org.apache.solr.common.cloud.ReplicaPosition;
+import org.apache.solr.common.cloud.WaitTime;
 import org.apache.solr.common.cloud.ZkConfigManager;
 import org.apache.solr.common.cloud.ZkNodeProps;
 import org.apache.solr.common.cloud.ZkStateReader;
@@ -174,21 +175,29 @@ public class CreateCollectionCmd implements OverseerCollectionMessageHandler.Cmd
       ocmh.overseer.offerStateUpdate(Utils.toJSON(message));
 
       // wait for a while until we see the collection
-      TimeOut waitUntil = new TimeOut(30, TimeUnit.SECONDS, timeSource);
-      boolean created = false;
-      while (! waitUntil.hasTimedOut()) {
-        waitUntil.sleep(100);
-        created = ocmh.cloudManager.getClusterStateProvider().getClusterState().hasCollection(collectionName);
-        if (created) break;
-      }
-      if (!created) {
-        throw new SolrException(SolrException.ErrorCode.SERVER_ERROR, "Could not fully create collection: " + collectionName);
+      WaitTime.start("create-coll-node");
+      try {
+        boolean created;
+        TimeOut waitUntil = new TimeOut(30, TimeUnit.SECONDS, timeSource);
+        created = false;
+        while (!waitUntil.hasTimedOut()) {
+          waitUntil.sleep(100);
+          created = ocmh.cloudManager.getClusterStateProvider().getClusterState().hasCollection(collectionName);
+          if (created) break;
+        }
+
+        if (!created) {
+          throw new SolrException(SolrException.ErrorCode.SERVER_ERROR, "Could not fully create collection: " + collectionName);
+        }
+      } finally {
+        WaitTime.end();
       }
 
       // refresh cluster state
       clusterState = ocmh.cloudManager.getClusterStateProvider().getClusterState();
 
       List<ReplicaPosition> replicaPositions = null;
+      WaitTime.start("buildReplicaPositions");
       try {
         replicaPositions = buildReplicaPositions(ocmh.cloudManager, clusterState, clusterState.getCollection(collectionName), message, shardNames, sessionWrapper);
       } catch (Assign.AssignmentException e) {
@@ -196,6 +205,8 @@ public class CreateCollectionCmd implements OverseerCollectionMessageHandler.Cmd
         new DeleteCollectionCmd(ocmh).call(clusterState, deleteMessage, results);
         // unwrap the exception
         throw new SolrException(ErrorCode.BAD_REQUEST, e.getMessage(), e.getCause());
+      } finally {
+        WaitTime.end();
       }
 
       if (replicaPositions.isEmpty()) {
@@ -287,17 +298,28 @@ public class CreateCollectionCmd implements OverseerCollectionMessageHandler.Cmd
         }
       }
 
-      if(!isLegacyCloud) {
-        // wait for all replica entries to be created
-        Map<String, Replica> replicas = ocmh.waitToSeeReplicasInState(collectionName, coresToCreate.keySet());
-        for (Map.Entry<String, ShardRequest> e : coresToCreate.entrySet()) {
-          ShardRequest sreq = e.getValue();
-          sreq.params.set(CoreAdminParams.CORE_NODE_NAME, replicas.get(e.getKey()).getName());
-          shardHandler.submit(sreq, sreq.shards[0], sreq.params);
+      WaitTime.start("submitting-to-shardhandler");
+      try {
+        if(!isLegacyCloud) {
+          // wait for all replica entries to be created
+          Map<String, Replica> replicas = ocmh.waitToSeeReplicasInState(collectionName, coresToCreate.keySet());
+          for (Map.Entry<String, ShardRequest> e : coresToCreate.entrySet()) {
+            ShardRequest sreq = e.getValue();
+            sreq.params.set(CoreAdminParams.CORE_NODE_NAME, replicas.get(e.getKey()).getName());
+            shardHandler.submit(sreq, sreq.shards[0], sreq.params);
+          }
         }
+      } finally {
+        WaitTime.end();
       }
 
-      shardRequestTracker.processResponses(results, shardHandler, false, null, Collections.emptySet());
+
+      WaitTime.start("shardRequestTracker.processResponses");
+      try {
+        shardRequestTracker.processResponses(results, shardHandler, false, null, Collections.emptySet());
+      } finally {
+        WaitTime.end();
+      }
       @SuppressWarnings({"rawtypes"})
       boolean failure = results.get("failure") != null && ((SimpleOrderedMap)results.get("failure")).size() > 0;
       if (failure) {
diff --git a/solr/core/src/java/org/apache/solr/handler/admin/ContainerPluginsApi.java b/solr/core/src/java/org/apache/solr/handler/admin/ContainerPluginsApi.java
index 2c971c0..2ee4a38 100644
--- a/solr/core/src/java/org/apache/solr/handler/admin/ContainerPluginsApi.java
+++ b/solr/core/src/java/org/apache/solr/handler/admin/ContainerPluginsApi.java
@@ -35,6 +35,7 @@ import org.apache.solr.api.PayloadObj;
 import org.apache.solr.client.solrj.SolrRequest.METHOD;
 import org.apache.solr.client.solrj.request.beans.PluginMeta;
 import org.apache.solr.common.cloud.SolrZkClient;
+import org.apache.solr.common.cloud.WaitTime;
 import org.apache.solr.common.cloud.ZkStateReader;
 import org.apache.solr.common.util.Utils;
 import org.apache.solr.core.CoreContainer;
@@ -70,6 +71,13 @@ public class ContainerPluginsApi {
     public void list(SolrQueryRequest req, SolrQueryResponse rsp) throws IOException {
       rsp.add(PLUGIN, plugins(zkClientSupplier));
     }
+
+    @EndPoint(method = METHOD.GET,
+        path = "/node/wait-times",
+        permission = PermissionNameProvider.Name.COLL_READ_PERM)
+    public void waitTimes(SolrQueryRequest req, SolrQueryResponse rsp) {
+      rsp.add("wait-times" , WaitTime.getCounts());
+    }
   }
 
   @EndPoint(method = METHOD.POST,
diff --git a/solr/solrj/src/java/org/apache/solr/common/cloud/WaitTime.java b/solr/solrj/src/java/org/apache/solr/common/cloud/WaitTime.java
new file mode 100644
index 0000000..75d0b8d
--- /dev/null
+++ b/solr/solrj/src/java/org/apache/solr/common/cloud/WaitTime.java
@@ -0,0 +1,96 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements.  See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You 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 org.apache.solr.common.cloud;
+
+import java.io.IOException;
+import java.util.Map;
+import java.util.Stack;
+import java.util.concurrent.ConcurrentHashMap;
+import java.util.concurrent.atomic.AtomicInteger;
+import java.util.concurrent.atomic.AtomicLong;
+
+import org.apache.solr.common.MapWriter;
+import org.apache.solr.common.annotation.JsonProperty;
+import org.apache.solr.common.util.ReflectMapWriter;
+
+public class WaitTime {
+  static Map<String, Count> counts = new ConcurrentHashMap<>();
+  private final String name;
+  private long start;
+
+  WaitTime(String name) {
+    this.name = name;
+    start = System.currentTimeMillis();
+
+  }
+
+  static final ThreadLocal<Stack<WaitTime>> current = ThreadLocal.withInitial(Stack::new);
+
+  public static void start(String name) {
+    WaitTime value = new WaitTime(name);
+    current.get().push(value);
+
+  }
+
+  public static void end() {
+    WaitTime val = null;
+    try {
+      val = current.get().pop();
+      if (val == null) return;
+    } catch (Exception e) {
+      e.printStackTrace();
+      return;
+    }
+
+    Count c = counts.get(val.name);
+    if (c == null) counts.put(val.name, c = new Count());
+    c.count.incrementAndGet();
+    long delta = System.currentTimeMillis() - val.start;
+    c.cumulativeTime.addAndGet(delta);
+    if (delta > c.max.get()) c.max.set(delta);
+    if (delta < c.min.get()) c.min.set(delta);
+  }
+
+
+  public static MapWriter getCounts() {
+    return ew -> counts.forEach(ew.getBiConsumer());
+  }
+
+  public static class Count implements ReflectMapWriter {
+    @JsonProperty
+    public final AtomicInteger count = new AtomicInteger();
+
+    @JsonProperty
+    public final AtomicLong cumulativeTime = new AtomicLong();
+
+    @JsonProperty
+    public AtomicLong max = new AtomicLong(0);
+
+    @JsonProperty
+    public AtomicLong min = new AtomicLong(Long.MAX_VALUE);
+
+    @Override
+    public void writeMap(EntryWriter ew) throws IOException {
+      ReflectMapWriter.super.writeMap(ew);
+      int count = this.count.get();
+      if (count > 0) ew.put("avg", cumulativeTime.get() / count);
+
+    }
+  }
+
+}